Last week, Chet Haase published a great blog post: Testing App Startup Performance. 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 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:
This leads us to 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());
}
The startup duration is TransitionInfoSnapshot.windowsDrawnDelayMs. It's calculated in TransitionInfoSnapshot.notifyWindowsDrawn():
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() captures the start of the activity transition:
private LaunchingState notifyActivityLaunching(
Intent intent,
ActivityRecord caller,
int callingUid
) {
long transitionStartNs = SystemClock.elapsedRealtimeNanos();
LaunchingState launchingState = new LaunchingState();
launchingState.mCurrentTransitionStartTimeNs = transitionStartNs;
return launchingState;
}
TransitionInfoSnapshot.notifyWindowsDrawn() is called by ActivityRecord.onWindowsDrawn() which is called by ActivityRecord.updateReportedVisibilityLocked():
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 for the idea! Lucky for us, Android Studio is set up to find sources for the Android version the app is compiled against:
I can put a breakpoint like I would in my app:
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:
When I start my app, I hit a breakpoint for ActivityMetricsLogger.notifyActivityLaunching():
and another breakpoint for TransitionInfoSnapshot.notifyWindowsDrawn():
Reading the stacktraces
- The first stacktrace shows that the start timestamp is captured when
system_processreceives 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 🥶, 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.
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? ⏱, I showed that we can use Process.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()). We can logs these 2 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")
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:
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 👩🎨 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:
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
ActivityTaskManageris 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 👩🎨.
Header image: Deep Dive by Romain Guy.
Top comments (2)
Why not put the registration on ContentProvider, and have a high order number?
In the real world application, most the application utilize ContentProvider. If we install the app startup time on the Application, we miss few calculation that happening on ContentProviders.
How to calculate lukeWarm start time, as in warm start Process is already created?