Android developer page: understanding traceview profiling example

Question

I am looking at this page: Profiling with Traceview and dmtracedump

Under "Profile Panel" it has the following text that refers to the sample profiling result below the text:

The last column in the table shows the number of calls to this method plus the number of recursive calls. The last column shows the number of calls out of the total number of calls made to that method. In this view, we can see that there were 14 calls to LoadListener.nativeFinished(); looking at the timeline panel shows that one of those calls took an unusually long time.

I am confused by this description. First, the 1st two sentences in this quote seem to be referring to the same column. So what does this last column actually contain? Second, I don't understand where exactly in the "timeline panel" I have to look to see that it "shows that one of those calls took an unusually long time".

Can you please help me make sense of this text.

Answer 1

First off, the same article tells us that:

Parents are shown with a purple background and children with a yellow background

So LoadListener.nativeFinished is the parent function and all of the indented rows underneath it are children, or functions that the parent has called.

Profile Panel

Here's a clip of the Profile Panel from the article:

The last column in the table shows the number of calls to this method plus the number of recursive calls.

The last column of the first row (parent) indicates the number of calls and recursive calls made to this function: 14 iterative and 0 recursive calls, separated by a plus symbol (14+14).

I think the author of the article accidentally a few words and as a result, the next line is a bit confusing:

The last column shows the number of calls out of the total number of calls made to that method.

In the yellow-backgrounded child rows below the parent, the last column does not actually indicate Calls+Rec. Note the change in notation - a fraction is used versus the plus symbol syntax. In the case of LoadListener.tearDown, 14/14 indicates that LoadListener.tearDown was called by the parent function 14 times. The LoadListener.tearDown function was called 14 times in total within this trace, hence LoadListener.nativeFinished is the only function to have called LoadListener.tearDown in this trace.

Let's look at the another row. The last column of the (child) function View.invalidate has a value of 2413/2853. This doesn't mean that View.invalidate was called 2413 times iteratively and 2853 times recursively. Instead it means that the parent function, LoadListener.nativeFinished, called View.invalidate 2413 times.

Now take a look at row #6 and you'll see that View.invalidate was called 2853 times iteratively and 0 times recursively. Therefore the parent function, LoadListener.nativeFinished, is the only function to have ever called LoadListener.tearDown within this trace.

Timeline Panel

Here's a clip of the Timeline Panel from the article:

From the same article,

The thin lines underneath the first row show the extent (entry to exit) of all the calls to the selected method

Notice the thin, brace-like pink lines that span horizontally directly below the highlighted section of the Main thread. The leftmost pink braces are very short; these represent 13/14 calls to LoadListener.nativeFinished that finished relatively quickly. The last brace - the one furthest to the right - is considerably longer than any of the others. This is the call to LoadListener.nativeFinished that "took an unusually long time."