Thursday, October 29, 2015

Measuring Activity Startup Time

In recent talks I've given, as well as the Developing for Android series, I talk about the need to launch quickly, and about how to ensure that you're testing the right launch speed (cold start, like after reboot and (mostly) after killing a task, vs. warm start, which is way faster because the activity just has to be brought to the foreground).

Then someone asked me, quite reasonably, "So how do I get my app's launch time?"

Then I paused and wondered the same thing...

Whenever I've done this kind of benchmarking on framework code, I've had the ability to instrument exactly the bits I needed to. But how can non-framework developers get the information they need from just running the normal build?

Fortunately, this information exists, and has since API 19. So if you're running on any release later than 4.4 (Kitkat), you should be set.

All you have to do is launch your activity and look in logcat for something like this:

ActivityManager: Displayed com.android.myexample/.StartupTiming: +768ms
Update 11/18/20: This log is now issued by ActivityTaskManager, not ActivityManager]

This information is output whenever an activity window is first drawn, after it goes through all of the startup stuff. This time includes the entire time that it took to launch the process, until the application ran layout and drew for the first time. This is basically the main information you need. It doesn't include the amount of time it took between the user clicking your app icon and the system getting ready to launch your activity, which is fine, because you cannot (as an app developer) affect that time, so there's no need to measure it. Instead, it includes all of the time it took to load your code, initialize your classes that are used at start time, run layout, and draw your app that first time. All of which is really what you want to measure, because that's what you can and should try to optimize.

There's an additional option to be aware of. The 'Displayed' time is automatically reported, to give you a quick measure of how long that initial launch took. But what if you are also loading in some other content asynchronously and want to know how long it took for everything to be loaded, drawn, and ready to go? In that case, you'll want to additionally call Activity.reportFullyDrawn(), which will then report, in the log, the time between that initial apk start (the same time as that used for the Displayed time) and the time when you call the onReportFullyDrawn() method. This secondary time is a superset of the initial one (assuming you call it after the initial launch time, which is preferred), giving you the additional information about how long it took to do everything, including the follow-on work after the app was first displayed.

There is another way of measuring startup time which is worth mentioning for completeness, especially since it uses my favorite device tool, screenrecord. This technique involves recording the entire experience of tapping on your app's icon to launch it and waiting until your app window is up and ready to go.

First, start screenrecord with the --bugreport option (which adds timestamps to the frames - this was a feature added in L. I think):
$ adb shell screenrecord --bugreport /sdcard/launch.mp4

Then tap your app icon, wait until your app is displayed, ctrl-C screenrecord, and pull the file up onto your host system with adb pull:
$ adb pull /sdcard/launch.mp4

Now you can open the resulting video and see what's happening when. To do this effectively, you'll need to have a video player that allows you to step frame-by-frame (Quicktime does this, not sure what the best player with this feature is on other OSs). Now step through the frames, noticing that there's a frame timestamp at the top of the video window.

Step forward until you see the app icon highlighted - this happens after the system has processed the click event on the icon and has started to launch the app. Note the frame time when this happened. Now frame-step forward until you see the first frame that your application's full UI begins to be visible. Depending on your launch experience (whether you have a starting window, a splash screen, etc.), the exact sequence of events and windows may vary. For a simple application you'll see the starting window come up first, then a cross-fade with the real UI in your application when it's ready. You want to note the first frame where you see any of the real UI content of your app. This happens when your app has finished layout and drawn itself, and is now ready to be shown. Note the time at this frame as well.

Now subtract the two times ((UI displayed) - (icon tapped)); this is the full time that it took for your app to go all the way from the initial user tap to being drawn and ready. It is a superset of the "Displayed" log described above, since it includes time before the process launches and after that first rendering (when the system starts the cross-fade animation), but it is at least something that you can use for comparison purposes with other launches after you make things faster and want to see how much better it is.

As with any performance testing, it's good to try to run your tests in similar situations multiple times (including making sure you're testing 'cold start' as noted above), as various things can happen to vary the results on any one run.

Now that you know how to figure out your launch times, whichever approach you use, go make it faster.
Please.

14 comments:

Anonymous said...

which values can be considered acceptable from the UX point?

Snild said...
This comment has been removed by the author.
Snild said...

On KitKat, there's a caveat for reportFullyDrawn(); it required the UPDATE_DEVICE_STATS permission. It still gets far enough to print the log, so it can be worked around by just wrapping the call with a try-catch(SecurityException). But if you don't, your activity will crash on KitKat. :/

Kiran said...

@Snild, which is why you probably want to add this log only in your debug builds. Gradle to the rescue :)

Chet Haase said...

@Hintersteiner: Thanks, fixed.

Anonymous said...
This comment has been removed by the author.
Anonymous said...

Also you replied: Thanks, fixed to @Hintersteiner.

But in fact the post still has the mistake.

Anonymous said...

I just tried on 3 devices: Nexus 6P, Galaxy S5, and LG Leon.

I couldn't find StartupTiming in the LogCat of any of them. This was runnning a debug version of my app if that makes any difference.

I also added the extra code:
if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.KITKAT) {
// Report to the system that the app is now fully drawn, purely for diagnostic purposes.
//
reportFullyDrawn();
}

And haven't seen anything trace of that in LogCat either. I did kill the app each time.

Anonymous said...

Extra comment just to subscribe to email updates.

Unknown said...
This comment has been removed by the author.
Unknown said...

No StartupTiming on HTC devices (M8) either. I suspect Chet saw this in "special" builds...

Anonymous said...

Thank you for writing this informational post. I have a question: when running the Topeka app on a Nexus 6P emulator (API 23), the Displayed line shows "CategorySelectionActivity: +1s97ms". Is that fast or slow? How do we know what startup time to shoot for?

Chet Haase said...
This comment has been removed by the author.
Chet Haase said...

@Frank: Are you looking at the log on the command line ('adb logcat') or in Android Studio? The default settings in Studio constrain the logs to only the launched app (which does not show this log because it is information coming from the system server). Also, the log level must be set to show I (informational) logs. Meanwhile, logcat on the command line should show everything.
I tested this on different builds to make sure; we issue this log all the time. I do not know the situation on non-Google phones (e.g., Samsung); it's possible that they do not issue the same logs on their devices. But at least on Nexus phones you should see this log on all builds since KitKat.