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.