[LoadingMetric] Paint metrics sometimes calculated against wrong NavigationStart event

irori commented 6 years ago

test.html:

<!DOCTYPE html>
<p id="text" hidden>Hello, world!</p>
<script>
  setTimeout(() => {
    document.getElementById('text').hidden = false;
    if (!window.location.search)
      window.location.href = 'test.html?2';
  }, 2000);
</script>

This displays some text (to trigger First Paint / First Contentful Paint) after 2 seconds from load, and then navigates to "test.html?2". The distination page (test.html?2) also displays some text after 2 seconds.

trace_fcp.json.gz is taken with this test page (served from a localhost server). Here's a screenshot of the loadingMetric view of this trace: screenshot from 2018-05-29 10-13-37

In the trace there're two FCP samples, one for test.html and another for test.html?2. The sample for test.html?2 is 2,123ms, which is expected (because of 2 seconds delay). However, The FCP sample for test.html is 68ms although test.html does not paint anything until 2 seconds after load.

By clicking "firstContentfulPaint 0.000 ms" or "navigationStart 0.000 ms" in the Metrics view, you can check trace events associated with the FCP sample. Both FCP samples are associated with the same navigationStart event at 4,747 ms, which is for the navigation to "test.html?2". The first FCP should be computed against the navigationStart at 2,650ms instead.

I guess this is a bug introduced when we changed FCP to use "GPU swap" timestamp instead of blink's paint timestamp (http://crbug.com/738235). When swap happened in GPU process, a new navigation may have already started. Currently FCP is computed by finding latest navigationStart event with the same frame ID, but it seems not sufficient.

farahcharab commented 6 years ago

I ran an experiment and this issue was pretty frequent. I can't give an approximation of how often was that happening, since I ran into this issue few weeks ago.

However, I just looked into one of my experiments, and looked at the first four/five traces, and three of them had this issue i.e. they were computed with respect to the wrong navigationStart event.

farahcharab commented 6 years ago

So three out of five traces doesn't look like a rare case, if this trend is consistent.

tdresser commented 6 years ago

@deepanjanroy

Interesting. We really need some non-heuristic driven way of associating NavStart events with other timestamps. Should we just be using some kind of navigation ID?

catapult-project / catapult

[LoadingMetric] Paint metrics sometimes calculated against wrong NavigationStart event #4490