Monday, December 31, 2007

Activity invocation performance

Intent-based programming is a great thing and the Android tutorials are encouraging programmers to take advantage of it. Behind the scenes, however, a complex choreography occurs to implement it so I was curious, what the limits of the Android intent system may be. I extended the example program in the Playing with Intents blog entry so that I can measure the performance of the intent invocation.

The principle of the measurement is simple. Instead of invoking the target activity only once, it will be invoked repeatedly to average out measurement error. I ran the measurements on the emulator whose performance compared to the target mobile device is unknown therefore I compared the activity invocation performance to plain Java method invocations, also running on the emulator. There is a fourth button therefore to launch the plain Java invocation measurement.

Let's see now, how the Playing with Intents example program was extended so that it can make this measurement. The modifications are not all that trivial and as I am not (yet :-)) an experienced Android programmer, I ran into common mistakes too. The measurement program can be found here. Similarly to the Playing with Intents version, there are actually two applications that need to be compiled and deployed separately, see the Playing with Intents blog entry for details.

I innocently started by organizing a loop around the intent invocation in the Button's onClick method. This did not work at all and the reason is the relatively complex lifecycle of the Android applications. The following log demonstrates, how complex an activity invocation really is. You can generate this log by setting the debug variable in IntentMeasSend's aexp.intentmeassend.IntentSender class to true. Then you can follow the events in the log by launching the fantastic adb logcat tool. Note the usage of android.util.Log class that provides logging functions.

Let's see the log now.

D/INTENTMEASSEND( 547): onStart
D/INTENTMEASSEND( 547): onResume
I/ActivityManager( 461): Displayed activity {aexp.intentmeassend/aexp.intentmeassend.IntentSender}: 685 ms
I/ActivityManager( 461): Done launching {aexp.intentmeassend/aexp.intentmeassend.IntentSender}: 694 ms
D/ActivityManager( 461): Stopping: HistoryRecord{401be290 {com.google.android.home/com.google.android.home.AllApps}}
D/INTENTMEASSEND( 547): Before starting subactivity
I/ActivityManager( 461): Starting activity: Intent { comp={aexp.intentmeassend/aexp.intentmeassend.IntentReceiver} extras=android.os.Bundle@4018e0e0 }
D/INTENTMEASSEND( 547): After starting subactivity
D/INTENTMEASSEND( 547): onFreeze
D/INTENTMEASSEND( 547): onPause
D/ActivityThread( 547): Performing launch of ActivityRecord{40047d38 {aexp.intentmeassend/aexp.intentmeassend.IntentReceiver}}
D/INTENTRECEIVER(INT)( 547): Activity invoked
D/INTENTRECEIVER(INT)( 547): Activity done
D/ActivityManager( 461): Resuming: HistoryRecord{40110618 {aexp.intentmeassend/aexp.intentmeassend.IntentSender}}
D/INTENTMEASSEND( 547): ACTIVITY_INVOKE event
D/INTENTMEASSEND( 547): onResume
I/ActivityManager( 461): Removing activity: Intent { comp={aexp.intentmeassend/aexp.intentmeassend.IntentReceiver} extras=android.os.Bundle@4018e0e0 }

Some of the log entries are marked as bold by me to emphasize key events. Activity invocation is an asynchronous process. It involves pausing the invoking activity, invoking the target activity, delivering the onActivityResult event to the invoking activity then resuming the invoking activity. This complex dance of events simply does not work if the target activity is invoked in a loop repeatedly in an event handler (onClick) because there are no further event deliveries before onClick finishes. It was necessary to reorganize the program so that the next activity invocation occurs only in the onActivityResult handler.

Now the results. I emphasize one more time that the actual numbers are not very much important, all the more so their proportions to the plain Java invocation running on the same emulator.

Explicit intent addressing, internal activity: about 23 msec/activity invocation
Explicit intent addressing, external activity: about 30 msec/activity invocation
Implicit intent addressing, external activity: about 30 msec/activity invocation
Direct Java call: about 3 microsec/method call

(Note that the measurement program does 100 activity invocations per measurement vs. 100000 Java method invocations so the measured times have to be divided by these numbers).

The measurement does demonstrate that invoking an activity is a relatively costly procedure. There is no problem if the activity invocation is related to some user action but one may run into performance problems if the activity invocation facility is used too frequently.

1 comment:

Robert Green said...

Ok so I know this is not exactly what you were testing for, but since I found your performance testing page when I was looking for a performance testing utility for my game development and couldn't find one, I decided to write my own.

My utility lets you test any loops or drawing code and will show you what kind of FPS you'd get if your game used that. It's really handy to test out new algorithms or bits of drawing.

The code is here - How To Test Android Performance Using FPSI hope it's as useful to others as it is to me. Thanks!