Improve reliability of finding navStart

lighthouse-core/gather/computed/trace-of-tab.js

@@ -32,7 +32,6 @@ const ComputedArtifact = require('./computed-artifact');
 const log = require('../../lib/log');
 
 class TraceOfTab extends ComputedArtifact {
-
   get name() {
     return 'TraceOfTab';
   }
@@ -43,30 +42,35 @@ class TraceOfTab extends ComputedArtifact {
   */
   compute_(trace) {
     // Parse the trace for our key events and sort them by timestamp.
-    const keyEvents = trace.traceEvents.filter(e => {
-      return e.cat.includes('blink.user_timing') || e.cat.includes('loading') ||
+    const keyEvents = trace.traceEvents
+      .filter(e => {
+        return e.cat.includes('blink.user_timing') ||
+          e.cat.includes('loading') ||
           e.name === 'TracingStartedInPage';
-    }).sort((event0, event1) => event0.ts - event1.ts);
+      })
+      .sort((event0, event1) => event0.ts - event1.ts);
 
     // The first TracingStartedInPage in the trace is definitely our renderer thread of interest
     // Beware: the tracingStartedInPage event can appear slightly after a navigationStart
     const startedInPageEvt = keyEvents.find(e => e.name === 'TracingStartedInPage');
     // Filter to just events matching the frame ID for sanity
     const frameEvents = keyEvents.filter(e => e.args.frame === startedInPageEvt.args.data.page);
 
+    // Our navStart will be the last frame navigation in the trace
+    const navigationStart = frameEvents.filter(e => e.name === 'navigationStart').pop();
+
     // Find our first paint of this frame
-    const firstPaint = frameEvents.find(e => e.name === 'firstPaint');
-    // Our navStart will be the latest one before fP.
-    const navigationStart = frameEvents.filter(e =>
-        e.name === 'navigationStart' && e.ts < firstPaint.ts).pop();
+    const firstPaint = frameEvents.find(e => e.name === 'firstPaint' && e.ts > navigationStart.ts);
 
     // FCP will follow at/after the FP
-    const firstContentfulPaint = frameEvents.find(e =>
-      e.name === 'firstContentfulPaint' && e.ts >= firstPaint.ts);
+    const firstContentfulPaint = frameEvents.find(
+      e => e.name === 'firstContentfulPaint' && e.ts > navigationStart.ts
+    );
 
     // fMP will follow at/after the FP
-    let firstMeaningfulPaint = frameEvents.find(e =>
-        e.name === 'firstMeaningfulPaint' && e.ts >= firstPaint.ts);
+    let firstMeaningfulPaint = frameEvents.find(
+      e => e.name === 'firstMeaningfulPaint' && e.ts > navigationStart.ts
+    );
 
     // If there was no firstMeaningfulPaint event found in the trace, the network idle detection
     // may have not been triggered before Lighthouse finished tracing.
@@ -83,17 +87,19 @@ class TraceOfTab extends ComputedArtifact {
     }
 
     // subset all trace events to just our tab's process (incl threads other than main)
-    const processEvents = trace.traceEvents.filter(e => {
-      return e.pid === startedInPageEvt.pid;
-    }).sort((event0, event1) => event0.ts - event1.ts);
+    const processEvents = trace.traceEvents
+      .filter(e => {
+        return e.pid === startedInPageEvt.pid;
+      })
+      .sort((event0, event1) => event0.ts - event1.ts);
 
     return {
       processEvents,
       startedInPageEvt: startedInPageEvt,
       navigationStartEvt: navigationStart,
       firstPaintEvt: firstPaint,
       firstContentfulPaintEvt: firstContentfulPaint,
-      firstMeaningfulPaintEvt: firstMeaningfulPaint
+      firstMeaningfulPaintEvt: firstMeaningfulPaint,
     };
   }
 }

lighthouse-core/lib/traces/pwmetrics-events.js

@@ -121,25 +121,15 @@ class Metrics {
   }
 
   /**
-   * Getter for our navigationStart trace event
+   * Get the full trace event for our navigationStart
+   * @param {!Array<{ts: number, id: string, name: string}>} metrics
    */
-  getNavigationStartEvt() {
-    if (!this._navigationStartEvt) {
-      const filteredEvents = this._traceEvents.filter(e => {
-        return e.name === 'TracingStartedInPage' || e.cat === 'blink.user_timing';
-      });
-
-      const tracingStartedEvt = filteredEvents.filter(e => e.name === 'TracingStartedInPage')[0];
-      const navigationStartEvt = filteredEvents.filter(e => {
-        return e.name === 'navigationStart' &&
-            e.pid === tracingStartedEvt.pid && e.tid === tracingStartedEvt.tid;
-      })[0];
-      this._navigationStartEvt = navigationStartEvt;
-    }
-    return this._navigationStartEvt;
+  identifyNavigationStartEvt(metrics) {
+    const navStartTs = metrics.find(e => e.id === 'navstart').ts;
+    this._navigationStartEvt = this._traceEvents
+        .find(e => e.name === 'navigationStart' && e.ts === navStartTs);
   }
 
-
   /**
    * Constructs performance.measure trace events, which have start/end events as follows:
    *     { "pid": 89922,"tid":1295,"ts":77176783452,"ph":"b","cat":"blink.user_timing","name":"innermeasure","args":{},"tts":1257886,"id":"0xe66c67"}
@@ -148,19 +138,19 @@ class Metrics {
    * @param {{ts: number, id: string, name: string}} navStart
    * @return {!Array} Pair of trace events (start/end)
    */
-  synthesizeEventPair(metric, navStart) {
+  synthesizeEventPair(metric) {
     // We'll masquerade our fake events to look mostly like navigationStart
     const eventBase = {
-      pid: this.getNavigationStartEvt().pid,
-      tid: this.getNavigationStartEvt().tid,
+      pid: this._navigationStartEvt.pid,
+      tid: this._navigationStartEvt.tid,
       cat: 'blink.user_timing',
       name: metric.name,
       args: {},
       // randomized id is same for the pair
       id: `0x${((Math.random() * 1000000) | 0).toString(16)}`
     };
     const fakeMeasureStartEvent = Object.assign({}, eventBase, {
-      ts: navStart.ts,
+      ts: this._navigationStartEvt.ts,
       ph: 'b'
     });
     const fakeMeasureEndEvent = Object.assign({}, eventBase, {
@@ -181,10 +171,9 @@ class Metrics {
       return [];
     }
 
-    // confirm our navStart's correctly match
-    const navStartEvt = metrics.find(e => e.id === 'navstart');
-    if (!navStartEvt || this.getNavigationStartEvt().ts !== navStartEvt.ts) {
-      log.error('pwmetrics-events', 'Reference navigationStart doesn\'t match fMP\'s navStart');
+    this.identifyNavigationStartEvt(metrics);
+    if (!this._navigationStartEvt) {
+      log.error('pwmetrics-events', 'Reference navigationStart not found');
       return [];
     }
 
@@ -197,7 +186,7 @@ class Metrics {
         return;
       }
       log.verbose('pwmetrics-events', `Sythesizing trace events for ${metric.name}`);
-      fakeEvents.push(...this.synthesizeEventPair(metric, navStartEvt));
+      fakeEvents.push(...this.synthesizeEventPair(metric));
     });
     return fakeEvents;
   }