Monday, January 14, 2013

Aprof : Android Profiler - A profiling tool for android native code

I am glad to introduce our new tool, Aprof : an Android profiler, it's a profiling tool for Android native code; aprof is not only another gprof implement on Android but also support for profiling shared library. The most important thing is that aport supports the profiling for JNI code!

The capability of aprof is similar to what gprof does, it provides call graph and time sampling profiling, but it's incompatible with gprof since the gprof can't profile shared library, it's limited by its representation.

Usage for aprof


If you want to profile an executable or static library, you can turn on aprof by inserting the following line to Android.mk:

LOCAL_ENABLE_APROF := true

There are two modes for profile shared library. The first one is specify for Non-JNI used shared library, it's just used like executable, but it only triggers aprof when the executable is being profiled.

The second mode is designed for JNI, it's called JNI mode, it's life-cycle-sensitive for Activity : active when onStart, stop and dump profiling when onStop; but here is one exception in JNI mode, it will trade as Non-JNI mode if the shared library are opened by the executable which is already turn on the aprof, So you can turn-on JNI mode aprof for shared library by adding the follow line to Android.mk:
LOCAL_ENABLE_APROF_JNI := true

In addition, regarding JNI-mode is you should make sure your application have the permission to write external storage. Here is the setting example in the AndroidManifest.xml.

AndroidManifest.xml:
<manifest xmlns:android="http://schemas.android.com/apk/res/android"
package="com.example.android.simplejni">
<application android:label="Simple JNI">
<activity android:name="SimpleJNI">
<intent-filter>
<action android:name="android.intent.action.MAIN" />
<category android:name="android.intent.category.LAUNCHER" />
</intent-filter>
</activity>
</application>
<uses-permission android:name="android.permission.WRITE_EXTERNAL_STORAGE" />
</manifest>

You can start profiling your program after recompiling executables with aprof and execute on the Android device, After the profiling has been accomplished, the result will be put in the /mnt/sdcard/ (according `EXTERNAL_STORAGE` environment variable), the default file name is executable name with .aprof suffix : $(progname).aprof And the next step is grabbing the data to the host, you can grab by adb
adb pull /mnt/sdcard/$(progname).aprof

# For example, you are profiling `foo`
adb pull /mnt/sdcard/foo.aprof
Note: You can also set environment variables `APROF_OUTPUT` and `APROF_OUTPUT_FILENAME` to change the default output folder and file name

And then interpret the data by aprof, the usage is as follow:

# aprof $(prog_file) $(prof_file)
aprof foo foo.aprof


And here is the example output:


  %      cumulative     self                 self       total
 time     time          time      calls    ms/call    ms/call   name
 99.52       2170       2140    2178309          0          0   fib
  0.00       2170          0          1          0        217   main
  0.48          0         30          0          0          0   <libc.so>

Call graph (explanation follows)

-------------------------------------------------------------
Image           : foo
Cumulative time : 2170 ms
Self time       : 2140 ms
  Function  % time  cumulative        self       Count  Call by
 fib                      2170        2140
            100.00        2170           0           1  main
            100.00        2170        2140     2178308  fib
 main                     2170           0
            100.00        2170           0           1  <libc.so>

Upper half part shows how many time spent in which function,
  • cumulative time : the execution time with the child function.
  • self time : the execution time for this function alone.
  • calls : the number of times this function was invoked.
  • self ms/call : the average number of milliseconds spent in this function per call.
  • total ms/call :the average number of milliseconds spent in function and its descendants per call

And the lower part shows the detail for each function.

We can see a unusual symbol in the above example output, the reason is that aprof don't load the symbol information of the shared libraries, we can specify the search path for shared libraries by -L option. In general, we can set the searching path to the out/target/product/*/symbols/system/lib.
# aprof $(prog_file) $(prof_file) -L$(lib_path)
aprof foo foo.aprof -L out/target/product/panda/symbols/system/lib We will get more details of profiling data after loading symbol, but it still imprecise info in the output since the shared libraries building without aprof, so the part of `calls` and `cumulative time` may be incorrect; however the `Self time` can show after we load the symbol info.
  %      cumulative     self                 self       total
 time     time          time      calls    ms/call    ms/call   name
 99.52       2170       2140    2178309          0          0   fib
  0.00       2170          0          1          0        217   main
  0.32          0         20          0          0          0   write
  0.16          0         10          0          0          0   memcpy

Call graph (explanation follows)

-------------------------------------------------------------
Image           : foo
Cumulative time : 2170 ms
Self time       : 2140 ms
  Function  % time  cumulative        self       Count  Call by
 fib                      2170        2140
            100.00        2170           0           1  main
            100.00        2170        2140     2178308  fib
 main                     2170           0
            100.00        2170           0           1  __libc_init
-------------------------------------------------------------
Image           : foo
Cumulative time : 2170 ms
Self time       : 30 ms
 write                       0          20
 memcpy                      0          10

And the last part is about visualization part of aprof, aprof supports the `dot` format by `-d` option, so we can use the `dot`(usually in graphviz package) program to output the call graph with timing info by the pipeline, you can reference the following command :

# aprof $(prog_file) $(prof_file) -L$(lib_path)
aprof foo foo.aprof -L out/target/product/panda/symbols/system/lib -d
| dot -Tpng -o foo.aprof.png

And here is an example output generated by md5sum of busybox.

Current State

Aprof still under review on gerrit, however you can checkout it from gerrit. Aprof support ICS, JB and Gingerbread, however if you are using Linaro, CyanogenMod (and it's derives) or Gingerbread, you may need also checkout the bellow patch-set:

Feel free to report any problem

2 comments:

  1. Dear Kito,

    I have a native C++ app I am adapting to run on Android.

    I have been looking for a profiler to analyze its performance, and aprof seems to be just the thing.

    However, I haven't been able to build it. I have tried to use ndk-build but I'm stuck.

    Could you share some build instructions for aprof, or point to a pre-built version I could use?

    Thank you.

    ReplyDelete
  2. This is not working for me detailed explanation of my problem @ http://stackoverflow.com/questions/30252198/how-to-profile-native-code-in-android

    ReplyDelete