Cause of performTraversals recursion, long egl buffer swap times

Question

I am measuring the performance of my app with systrace on a non-rooted Nexus 4 on Android 4.2.2. I'm seeing a few things in the reports that don't make sense to me and I'm wondering if they might be systrace bugs or if anyone might know of any possible root causes for these symptoms.

1- Large recursion under performTraversals at the end of a run

Link to Report - Please see the big curve at the end of the run (~18s). My understanding was that performTraversals is at the framework level, where it draws a single frame of the user interface. So it didn't make sense to me that there could be recursive calls beneath it. Also because I get this kind of exponential stacking at the end of a run, I assumed this was really just a defect in systrace for data at the end of a run. Is this kind of recursion possible? What does it mean?

2- performTraversals recursion in the middle of a run with long buffer swap times

Link to Report - Interesting behavior starting around the 12 second mark. When I saw something similar in the middle of a run it made me think maybe I shouldn't be writing this off. Also, I spent a lot of time trying to figure out what might account for such a long eglSwapBuffers/queueBuffer (my app doesn't use openGL and just uses the framework directly) to no avail, when a colleague told me to just ignore it because swapping buffers will always be instantaneous. Might there be more to it? Is there something to investigate here?

Apostle

Answer 1

In report #1, the trace buffer for CPU 0 filled up about 5 seconds in (note the absence of data in the "CPU 0" line). You're going to start seeing stuff that starts and never ends, because the end record didn't get recorded. That's why you get the big "performTraversals (Did Not Finish)" blobs.

Same story in report #2 -- ran out around 10 seconds in.

You can increase the buffer size with the "-b" flag, e.g. -b 8192 would give you an 8MB buffer. The default size is 2MB.

Orotund

Fascinating, thanks! I had previously assumed that with systrace android was internally filling a buffer and then flushing it asynchronously as it gets close to being full. But I gather from your answer that that is wrong, and the buffers just fill up and when that happens it effectively stops tracing. I gather also that this is on a per-cpu basis, so activity on cpu 1 might continue to be traced after cpu 0 has filled up if cpu 1 has had less activity since the beginning of the trace. Is this correct? – Apostle

Yes. Each CPU core has a separate buffer so the logging code can write to it without needing to use locks or atomic ops. – Orotund