Understanding jank in traces

[Jonah Chin]

Hi Sadrul,

 

I recently started looking at perf impacts of the Canvas OOPR project. I’m seeing some regressions in jank_count. Khushal mentioned that you recently added the jank row in traces, but I am not seeing how this row corresponds to the uptick in jank_count. Both traces look to emit a jank event every other frame? I’m curious how this row works.

 

I was also hoping you could point me to some documentation for understanding perf investigation in chromium. Specifically somewhere I can see what each of these metrics/stories/trace rows represent.

 

Thanks!

Jonah Chin

[Sadrul Chowdhury]

+Mingjing Zhang to explain the Jank trace events.

The |jank_count| metric in telemetry comes from the trace-events, and very brief documentation of this metric and other tracing-based metrics are here. The new jank-metrics reported in UMA (Graphics.Smoothness.Jank.*) metrics measure the same thing (unexpected change in frame-rate), but are reported from within chrome itself. Mingjing can share more details about it.

If you have traces, and are trying to find where the janks are, you can also look at the instructions here. If you have more questions, it'd be easier if you are able to share the traces (e.g. in this thread or in a crbug).

Regards,

Sadrul

[Khushal Sagar]

Jonah, could you share the trace we were looking at? The frequency of jank events there was much more than jank_count. The events were marked as "RAF", so main thread, while the jank_count in the benchmark is for display swaps (in the GPU process). But since the only driver of frame updates on the test case was RAF, I expected they would align. In either case, the RAF jank count was almost 30Hz which definitely didn't align with the main thread throughput we were seeing on the trace.

[Jonah Chin]

Thanks for the resources Sadrul.

 

Here are the traces (for hw_accelerated_canvas_to_sw_canvas, exp_jank_count): BEFORE TRACE, AFTER TRACE.

They were taken from this pinpoint job.

 

+Nathan and Sushanth FYI.

 

Thanks,

Jonah

[Sadrul Chowdhury]

Thanks for the traces! It does look like a bug with the Jank trace-events. I have filed https://bugs.chromium.org/p/chromium/issues/detail?id=1154492 to track fixing this. +Mingjing Zhang Mind taking a look at this issue?

Sadrul

[Jonah Chin]

Hi Sadrul,

I have a few follow up questions for you. For reference, I’m looking at the linked AFTER trace at 15,831ms.

In FrameSequenceTracker, I’m seeing a frame that is noticeably longer than others (I see a few of these, which accounts for the increased jank in the pinpoint results).

The main thread does not look too busy. I followed the viz flow events to see what caused the frame to not be produced. Here is the GPU process:

It looks like the usual steps were taken. The VizCompositorThread receives the compositor frame, and eventually CrGpuMain hits NativeViewGLSurfaceEGL:RealSwapBuffers. Despite this, a new frame is not shown in the FrameSequenceTracker. Was a frame not produced here? Is there somewhere else I should be checking to see why the frame wasn’t produced?

 

Thanks for your help,

Jonah

[Jonah Chin]

Friendly ping - in case this got lost in the backlog.

 

Thanks,

Jonah

[Sunny Sachanandani]

Hi Jonah,

I don't know why the FrameTracker shows an extra long frame as you noted, but I think the PipelineReporter traces look weird too.  We're in high latency mode, which means we draw the previous interval's frame on begin frame followed by rAF for the current interval.  In the trace, it seems we're emitting two PipelineReporter traces for each interval, there's one short one that gets completed when we submit the previous interval's frame, and a long one that tracks the full lifetime of the current interval's frame and gets completed in the subsequent interval.  We should only keep the longer one around IMO (the diagram below says merge, but the effect of merging would be the same as the longer one).  I don't know if this helps with your original question, but still worth checking.

Also, from a quick glance at the before and after traces, it does seem we're spending more time on GPU main thread.  It seems a significant portion of it is extra CPU time, but there's also a lot of time the thread is blocked waiting.  If you can reproduce some of these issues on Windows, can you collect ETW traces with full context switching call stacks (public Chrome versions so that we can get symbols from the symbol server)?  That will tell us what we're blocked on (<speculation>I suspect extra driver flushes by Skia</speculation>).

Thanks,

Sunny