Android Vitals - How adb measures App Startup 🔎
Tags: android, performance, startup, adb
Published: 2020-12-01 17:05:55

Last week, Chet Haase published a great blog post: [Testing App Startup Performance](https://medium.com/androiddevelopers/testing-app-startup-performance-36169c27ee55). It leverages the output of `ActivityTaskManager` to obtain the app startup duration.

> Whenever an activity starts, you’ll see something like this in the logcat output:

```
ActivityTaskManager: Displayed
com.android.samples.mytest/.MainActivity: +1s380ms
```

> This duration (1,380ms in this example) represents the time that it took from launching the app to the time when the system consider it “launched,” which includes drawing the first frame (hence “Displayed”).

This article is a deep dive to explore the question:

### What does `ActivityTaskManager` measure exactly?

I know you're impatient, let's jump to the conclusion: `ActivityTaskManager` measures the time ([uptime](https://dev.to/pyricau/android-vitals-what-time-is-it-2oih) on API < 30, realtime on API 30+) from when `system_process` receives an Intent to start an activity to when the window of that activity is done drawing.

Key takeways:

* This measure includes a **few hundred milliseconds prior to app code and resources loading**, i.e. time that an app developer cannot affect.
* You can measure this without the extra time from within the app, I'll share how at the end.

And now, let's dive into AOSP code!

# `ActivityTaskManager` log

```
ActivityTaskManager: Displayed
com.android.samples.mytest/.MainActivity: +1s380ms
```

We know what the log looks like so we can search for it on [cs.android.com](https://cs.android.com/):

![search](https://dev-to-uploads.s3.amazonaws.com/i/8vcew9k8n0x0r3tg3arb.png)
 
This leads us to [ActivityTaskManager.logAppDisplayed()](https://cs.android.com/android/platform/superproject/+/master:frameworks/base/services/core/java/com/android/server/wm/ActivityMetricsLogger.java;l=883-899;drc=35a009097530cce79b87cab469af8e62aba18e43):

```java
private void logAppDisplayed(TransitionInfoSnapshot info) {
  StringBuilder sb = mStringBuilder;
  sb.setLength(0);
  sb.append("Displayed ");
  sb.append(info.launchedActivityShortComponentName);
  sb.append(": ");
  TimeUtils.formatDuration(info.windowsDrawnDelayMs, sb);
  Log.i(TAG, sb.toString());
}
```

The startup duration is `TransitionInfoSnapshot.windowsDrawnDelayMs`. It's calculated in [TransitionInfoSnapshot.notifyWindowsDrawn()](https://cs.android.com/android/platform/superproject/+/master:frameworks/base/services/core/java/com/android/server/wm/ActivityMetricsLogger.java;l=590-606;drc=35a009097530cce79b87cab469af8e62aba18e43):

```java
TransitionInfoSnapshot notifyWindowsDrawn(
  ActivityRecord r, 
  long timestampNs
) {  
  TransitionInfo info = getActiveTransitionInfo(r);
  info.mWindowsDrawnDelayMs = info.calculateDelay(timestampNs);
  return new TransitionInfoSnapshot(info);
}

private static final class TransitionInfo {
 int calculateDelay(long timestampNs) {
   long delayNanos = timestampNs - mTransitionStartTimeNs;
   return (int) TimeUnit.NANOSECONDS.toMillis(delayNanos);
 }
}
```

Let's find where `timestampNs` and `mTransitionStartTimeNs` are captured.

[ActivityMetricsLogger.notifyActivityLaunching()](https://cs.android.com/android/platform/superproject/+/master:frameworks/base/services/core/java/com/android/server/wm/ActivityMetricsLogger.java;l=476;drc=35a009097530cce79b87cab469af8e62aba18e43) captures the start of the activity transition:

```java
private LaunchingState notifyActivityLaunching(
  Intent intent,
  ActivityRecord caller,
  int callingUid
) {
  long transitionStartNs = SystemClock.elapsedRealtimeNanos();
  LaunchingState launchingState = new LaunchingState();
  launchingState.mCurrentTransitionStartTimeNs = transitionStartNs;
  return launchingState;
}
```

[TransitionInfoSnapshot.notifyWindowsDrawn()](https://cs.android.com/android/platform/superproject/+/master:frameworks/base/services/core/java/com/android/server/wm/ActivityMetricsLogger.java;l=590-606;drc=35a009097530cce79b87cab469af8e62aba18e43) is called by [ActivityRecord.onWindowsDrawn()](https://cs.android.com/android/platform/superproject/+/master:frameworks/base/services/core/java/com/android/server/wm/ActivityRecord.java;l=5302;drc=35a009097530cce79b87cab469af8e62aba18e43)  which is called by [ActivityRecord.updateReportedVisibilityLocked()](https://cs.android.com/android/platform/superproject/+/master:frameworks/base/services/core/java/com/android/server/wm/ActivityRecord.java;l=5415;drc=35a009097530cce79b87cab469af8e62aba18e43):

```java
void updateReportedVisibilityLocked() {
  // ...
  if (nowDrawn != reportedDrawn) {
    onWindowsDrawn(nowDrawn, SystemClock.elapsedRealtimeNanos());
    reportedDrawn = nowDrawn;
  }
  // ...
}
```

We now know where the start and end timestamps are captured, but unfortunately `ActivityMetricsLogger.notifyActivityLaunching()` and `ActivityRecord.updateReportedVisibilityLocked()` have many call sites, so it's hard to dig further within the AOSP source.

# Debugging `system_process`

I was telling a friend I hit a dead end looking at the Android sources, and he asked me: 

> Why don't you put a breakpoint?

Duh. I have never tried to debug `system_process`, but there's no reason we can't. Thanks [Vincent](https://twitter.com/vdurmont) for the idea! Lucky for us, Android Studio is set up to find sources for the Android version the app is compiled against:

![ActivityMetricsLogger sources](https://dev-to-uploads.s3.amazonaws.com/i/hwa3p4yzwgk4piolr0y6.png)
 
I can put a breakpoint like I would in my app:

![breakpoint](https://dev-to-uploads.s3.amazonaws.com/i/rcyt2889tvejy9d8g6lj.png)

Side note: this screenshot shows `SystemClock.uptimeMillis()` while the code I shared aboved showed `SystemClock.elapsedRealtimeNanos()`. I'm using an API 29 device, and it turns out that API 29 measured startup time with `SystemClock.uptimeMillis()`, and API 30 measures it with `SystemClock.elapsedRealtimeNanos()`.

**Using a rooted device**, I can connect a debugger to `system_process`: 

![debug system_process](https://dev-to-uploads.s3.amazonaws.com/i/gbe9khu0seyxc6ksvhql.png)

When I start my app, I hit a breakpoint for `ActivityMetricsLogger.notifyActivityLaunching()`:

![ActivityMetricsLogger.notifyActivityLaunching()](https://dev-to-uploads.s3.amazonaws.com/i/1y0qst5bo7azbynb3bzu.png)

and another breakpoint for `TransitionInfoSnapshot.notifyWindowsDrawn()`:

![TransitionInfoSnapshot.notifyWindowsDrawn()](https://dev-to-uploads.s3.amazonaws.com/i/v96yl1dnme1uljemt5t0.png)
 
# Reading the stacktraces

* The first stacktrace shows that the start timestamp is captured when `system_process` receives an Intent to start an activity.
* The second stacktrace shows that the end timestamp is captured when the window of that activity is done drawing. The corresponding frame should be visible on the display within 16 ms.

# App startup time

In [Android Vitals - Diving into cold start waters 🥶](https://dev.to/pyricau/android-vitals-diving-into-cold-start-waters-5hi6), I explored what happens on app startup and concluded:

> The user experience of launching an activity starts when the user touches the screen, however app developers have little influence on the time spent before  `ActivityThread.handleBindApplication()`, so that's where app cold start monitoring should start.

![Cold start sequence diagram](https://dev-to-uploads.s3.amazonaws.com/i/puh3wi86r25lhktnnyxv.png)

`ActivityThread.handleBindApplication()` loads the APK and the app components (`AppComponentFactory`, `ContentProvider`, `Application`). Unfortunately, `ActivityTaskManager` uses `ActivityTaskManagerService.startActivity()` as start time, which happens some time before `ActivityThread.handleBindApplication()`.

# How much time is `ActivityTaskManager` adding?

In [Android Vitals - When did my app start? ⏱](https://dev.to/pyricau/android-vitals-when-did-my-app-start-24p4), I showed that we can use [Process.getStartUptimeMillis()](https://developer.android.com/reference/android/os/Process.html#getStartUptimeMillis()) to get the timestamp at which `ActivityThread.handleBindApplication()` was  called. I also shared a code snippet to read the process fork time (see [Processes.readProcessForkRealtimeMillis()](https://dev.to/pyricau/android-vitals-when-did-my-app-start-24p4#process-fork-time)). We can logs these 2 values to logcat: 

```kotlin
val forkRealtime = Processes.readProcessForkRealtimeMillis()
val nowRealtimeMs = SystemClock.elapsedRealtime()
val nowUptimeMs = SystemClock.uptimeMillis()
val elapsedRealtimeMs = nowRealtimeMs - forkRealtime
val forkUptimeMs = nowUptimeMs - elapsedRealtimeMs
Log.d("AppStart", "$forkUptimeMs fork timestamp")

val processStart = Process.getStartUptimeMillis()
Log.d("AppStart", "$processStart bindApplication() timestamp")
```

We also need to log `ActivityMetricsLogger.mCurrentTransitionStartTime`. We can make our previous `system_process` breakpoint **non-suspending** and have it log the value. The output of *Evaluate and log* goes to the debugger console. We want all logs in logcat so we're invoking `Log.d()` from there:

![log for mCurrentTransitionStartTime](https://dev-to-uploads.s3.amazonaws.com/i/2oa1c078fzdhtnnp6ogz.png)
 
## Results

```
D/AppStart: 27464211 Intent received
D/AppStart: 27464340 fork timestamp
D/AppStart: 27464533 bindApplication() timestamp
...
I/ActivityTaskManager: Displayed
com.example.logstartup/.MainActivity: +1s185ms
```

That's 129 ms from receiving the intent to forking the zygote process, and 193 ms from forking to `ActivityThread.handleBindApplication()`, i.e. 322 ms before the app starts loading its code and resources. In this example, that's ~30% of the app startup time reported by `ActivityTaskManager`.

The real number is lower than that, since `system_process` was running with a debugger connected. Still, it's significant enough that you should have this extra penalty in mind when measuring app startup with `ActivityTaskManager`.

# Measuring app startup time from within the app

In [Android Vitals - First draw time 👩‍🎨](https://dev.to/pyricau/android-vitals-first-draw-time-m1d) I showed how to determine the first draw time. I compared that timestamp with the timestamp passed to `TransitionInfoSnapshot.notifyWindowsDrawn()`, and the two values are only a few milliseconds apart.

We can put together what we've learnt to measure the app startup duration from within the app:

```kotlin
class MyApp : Application() {

  override fun onCreate() {
    super.onCreate()

    var firstDraw = false
    val handler = Handler()

    registerActivityLifecycleCallbacks(
      object : ActivityLifecycleCallbacks {
      override fun onActivityCreated(
        activity: Activity,
        savedInstanceState: Bundle?
      ) {
        if (firstDraw) return
        val name = activity::class.java.simpleName
        val window = activity.window
        window.onDecorViewReady {
          window.decorView.onNextDraw {
            if (firstDraw) return@onNextDraw
            firstDraw = true
            handler.postAtFrontOfQueue {
              val start = Process.getStartUptimeMillis()
              val now = SystemClock.uptimeMillis()
              val startDurationMs = now - start
              Log.d(
                "AppStart", 
                "Displayed $name in $startDurationMs ms"
              )
            }
          }
        }
      }
    })
  }
}
```

```
D/AppStart: Displayed MainActivity in 863 ms
```

# Conclusion

* The output from `ActivityTaskManager` is convenient, and totally worth using if you're trying to compare startup time for different versions of your app. Just be aware that there's a non-trivial portion of that time that app developers cannot affect.
* You can measure app startup time from within the app. I intend to eventually publish that code as an open source library, in the meantime the details are in [Android Vitals - First draw time 👩‍🎨](https://dev.to/pyricau/android-vitals-first-draw-time-m1d).

> Header image: *Deep Dive* [by Romain Guy](https://www.flickr.com/photos/romainguy/12599069954).