You can use the output from ActivityTaskManager to get the application startup duration.

Whenever an Activity starts, you see something similar in the logcat output:

ActivityTaskManager: Displayed
com.android.samples.mytest/.MainActivity: +1s380ms
Copy the code

This duration (1,380 milliseconds in this example) represents the time from the time the application is started until the system considers it “started,” including drawing the first frame (and thus “displayed”).

This article delves into this question:

What exactly does ActivityTaskManager measure?

ActivityTaskManager measures the time from when system_Process receives the intention to start an activity until the window for that activity completes drawing (uptime on API < 30, real-time time on API 30+).

Key points:

This measure includes the few hundred milliseconds before the application code and resources are loaded, the time that the application developer has no influence over.

Measurements can be made within the application without extra time, and I’ll share how at the end.

ActivityTaskManager log

ActivityTaskManager: Displayed
com.android.samples.mytest/.MainActivity: +1s380ms
Copy the code

We know what the log looks like, so we can search for it on cs.android.com: “Displayed”

This lead us to the ActivityTaskManager logAppDisplayed () :

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());
}
Copy the code

Start the duration for TransitionInfoSnapshot windowsDrawnDelayMs. . It’s in TransitionInfoSnapshot notifyWindowsDrawn () calculation:

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); }}Copy the code

Let’s find out where timestampNs and mTransitionStartTimeNs are caught.

ActivityMetricsLogger. NotifyActivityLaunching () to capture activity conversion start:

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

TransitionInfoSnapshot. NotifyWindowsDrawn () by ActivityRecord. OnWindowsDrawn () call, The latter by ActivityRecord. UpdateReportedVisibilityLocked () call:

void updateReportedVisibilityLocked() { // ... if (nowDrawn ! = reportedDrawn) { onWindowsDrawn(nowDrawn, SystemClock.elapsedRealtimeNanos()); reportedDrawn = nowDrawn; } / /... }Copy the code

We now know where to capture the start and end timestamps, But unfortunately ActivityMetricsLogger. NotifyActivityLaunching () and ActivityRecord updateReportedVisibilityLocked () there are a lot of calls, Therefore, it is difficult to further mine AOSP sources.

Debugging system_process

I told a friend that I was running into a dead end looking at Android resources and he asked me:

Why not set breakpoints?

I’ve never tried to debug system_process, but there’s no reason we can’t. Thanks Vincent for the idea! Fortunately, Android Studio is set up to find the source code for the version of Android for which the application was compiled.

Using the Root device, I can connect the debugger to system_process.

When I start my application, I met ActivityMetricsLogger notifyActivityLaunching breakpoint ().

And TransitionInfoSnapshot notifyWindowsDrawn another breakpoint ().

Read stack trace

The first stack trace shows that the start timestamp is captured when system_Process receives an Intent that starts an activity.

The second stack trace shows the capture of the end timestamp when the active window is finished drawing. The corresponding frame should be visible on the display within 16 milliseconds.

Application startup time

Start the Activity of the user experience in the user touching the screen, but the application developers to ActivityThread. HandleBindApplication before () the time spent almost no effect, so the application cold start monitoring should start from here.

ActivityThread. HandleBindApplication () loading APK and Application components (AppComponentFactory, ContentProvider, Application). Unfortunately, ActivityTaskManager use ActivityTaskManagerService. StartActivity () as the start time, It happens in ActivityThread. HandleBindApplication () before a period of time.

How much time does ActivityTaskManager add?

I shows we can use the Process getStartUptimeMillis () to obtain call ActivityThread. HandleBindApplication timestamp (). I also share a code snippet to read process fork time (see the Processes. The readProcessForkRealtimeMillis ()). We can record these two values to logcat:

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")
Copy the code

We also need to record ActivityMetricsLogger mCurrentTransitionStartTime. We can unsuspend our previous system_process breakpoint and let it record the value. The Evaluate and log output goes to the debugger console. We want all logs to be in logcat, so we call log.d () from there.

The results of

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

From receiving the bifurcate the intention of the zygote process need 129 milliseconds, from bifurcation to ActivityThread. HandleBindApplication () needs to 193 milliseconds, namely the application before you start to load the code and resources of 322 milliseconds. In this example, this is about 30% of the application startup time reported by ActivityTaskManager.

The actual number is lower than this because system_process is running and connecting to the debugger.

Measure application startup time from within the application

I pass the timestamp and TransitionInfoSnapshot. NotifyWindowsDrawn () by comparing the timestamp of the these two values separated by only a few milliseconds.

We can put together what we’ve learned to measure application startup duration within an application:

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" ) } } } } }) } }Copy the code
D/AppStart: Displayed MainActivity in 863 ms
Copy the code

conclusion

The output from ActivityTaskManager is handy and well worth using if you’re trying to compare startup times between different versions of your application. Note that the application developer cannot influence important parts of that time.

Application startup time can be measured from within the application.