Android Eclipse: Traceview, I just don't get it

Question

I just don't get the various elements of the traceview output, and I can't find a tutorial. Could someone please explain the following with reference to the diagram below:

1. The width of the bars corresponds to the time the function takes. What does the height correspond to?
2. What is specific difference between Inclusive and Exclusive. I assumed that inclusive includes the calls of all the children functions?
3. Would this be true: The sum of (Time per call times Calls) = time the program runs (what about async tasks?)
4. Can async tasks be ignored when debugging slowdown on the main thread ?
5. Should the sum of all the percents in Excl% equal 100%?
6. What happens when there are gaps (white in the midst of black)? Is that when other android processes are running, or just your own async tasks (it looks like the gaps in one are aligned with the filled in part in the other, if thats the case then is there any point in moving intensive tasks to an AsyncTask)?

Answer 1

(I would have added this as a comment to @ron's answer, but my reputation is still not high enough that I can comment ;)).

Since July 2011, you can in fact get traceview and VMDebug to give you wall clock time as well as cpu usage time, thanks to a code change by Jeff Brown. I'm afraid the necessary permissions require a rooted device however. This also leads to a slightly different traceview window than the post by tjb above.

http://git.insignal.co.kr/?p=mirror/aosp/platform/dalvik.git;a=commitdiff;h=9f640af99bebc6e96f6e1e9903557e2c8f567483

TLDR; adb shell setprop dalvik.vm.extra-opts -Xprofile:dualclock and reboot your device.

HRM, since I'm technically supposed to help answer the question:

1. My understanding of the heights of bars is that it's related to parent functions. Suppose a() calls b(). Then a() is running while b() is also running. While b() is running traceview will show b's color; but when a is running (i.e. excl time) it will draw a's color, and it will draw a's bar slightly higher than b's bar. At least, this is definitely how things work when you zoom in; If you click on the function corresponding to the taller bar it will put brackets underneath the small bars near it showing that the parent was responsible for all of it; and the parent is always shown as the taller bar.

2. yes :). Inclusive is time spent executing the function or any thing called by that function; Exclusive is 'exclusive of called functions', and is just the time spent in the function proper (or switching into/out of it).

3. Only for the toplevel, which I think you implied; and even then see @ron's answer - this is cpu usage time, not wall clock time. AsyncTasks run in the main thread, and so will be included somewhere in the toplevel breakdown. Same for Handlers

4. answered by Eric

5. No, because of round up / round down (ie 1.87% would display as 1.9%); but the sum of the entries in "Exclusive" should add up to the total time shown in the upper right corner, which is the same as the number calculated for your question (3)

6. answered by Eric

Answer 2

I cant answer all your questions, but I can say...

for #4 no, You're running a single core processor (or at least emulating one) so async tasks on their own thread have to interrupt main thread to get processing time. Any time another thread executes will be "slowdown" on the main thread, so you should be watching that.

for #6, those gaps you see in your main threads execution trace correlate exactly to the times when your asynctask is getting processor time. Again, single core, can only do 1 thread at a time. In this time slice it doesnt look like any other process got any processor time at all, but those threads were still sleeping in the background. Since this was (likely) an emulator, thats common. On a live phone you will see many more :)

I'm also fairly sure for #1 that the height of each spike in the thread's execution is the %processor utilization. For example the main thread's "black" area is system idle. Edit: Ok, i'm for sure now. This is what that is. So in your main thread, that area that is solid pink is solid 100% processor utilization.

Answer 3

An other important know-how about the traceview graph (as mentioned here): The time displayed by traceview is not real-world wall clock time, but used CPU time.

For example, by reducing the FPS the shape of the traceview graph may not change, since it does not include the idle duty cycles. Therefore when measuring performance, it is also recommended to run the app for a fixed amount of time (10 sec, 60 sec, etc), and check if the time taken by 100% inclusive calls is lower than before.