core(tracehouse): split timeOrigin determination out of computeTraceO…

…fTab (#11253)

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

@@ -19,6 +19,16 @@ class LHTraceProcessor extends TraceProcessor {
     return new LHError(LHError.errors.NO_NAVSTART);
   }
 
+  /**
+   * This isn't currently used, but will be when the time origin of trace processing is changed.
+   * @see {TraceProcessor.computeTimeOrigin}
+   * @see https://github.com/GoogleChrome/lighthouse/pull/11253#discussion_r507985527
+   * @return {Error}
+   */
+  static createNoResourceSendRequestError() {
+    return new LHError(LHError.errors.NO_RESOURCE_REQUEST);
+  }
+
   /**
    * @return {Error}
    */

lighthouse-core/lib/lh-error.js

@@ -242,6 +242,11 @@ const ERRORS = {
     message: UIStrings.badTraceRecording,
     lhrRuntimeError: true,
   },
+  NO_RESOURCE_REQUEST: {
+    code: 'NO_RESOURCE_REQUEST',
+    message: UIStrings.badTraceRecording,
+    lhrRuntimeError: true,
+  },
   NO_NAVSTART: {
     code: 'NO_NAVSTART',
     message: UIStrings.badTraceRecording,

lighthouse-core/lib/tracehouse/trace-processor.js

@@ -17,7 +17,9 @@
  */
 
 /** @typedef {Omit<LH.Artifacts.TraceTimes, 'firstContentfulPaint'> & {firstContentfulPaint?: number}} TraceTimesWithoutFCP */
+/** @typedef {Omit<TraceTimesWithoutFCP, 'traceEnd'>} TraceTimesWithoutFCPAndTraceEnd */
 /** @typedef {Omit<LH.Artifacts.TraceOfTab, 'firstContentfulPaintEvt'|'timings'|'timestamps'> & {timings: TraceTimesWithoutFCP, timestamps: TraceTimesWithoutFCP, firstContentfulPaintEvt?: LH.Artifacts.TraceOfTab['firstContentfulPaintEvt']}} TraceOfTabWithoutFCP */
+/** @typedef {'lastNavigationStart'|'firstResourceSendRequest'} TimeOriginDeterminationMethod */
 
 const log = require('lighthouse-logger');
 
@@ -43,6 +45,13 @@ class TraceProcessor {
     return new Error('No navigationStart event found');
   }
 
+  /**
+   * @return {Error}
+   */
+  static createNoResourceSendRequestError() {
+    return new Error('No ResourceSendRequest event found');
+  }
+
   /**
    * @return {Error}
    */
@@ -471,11 +480,14 @@ class TraceProcessor {
 
   /**
    * Finds key trace events, identifies main process/thread, and returns timings of trace events
-   * in milliseconds since navigation start in addition to the standard microsecond monotonic timestamps.
+   * in milliseconds since the time origin in addition to the standard microsecond monotonic timestamps.
    * @param {LH.Trace} trace
+   * @param {{timeOriginDeterminationMethod?: TimeOriginDeterminationMethod}} [options]
    * @return {TraceOfTabWithoutFCP}
   */
-  static computeTraceOfTab(trace) {
+  static computeTraceOfTab(trace, options) {
+    const {timeOriginDeterminationMethod = 'lastNavigationStart'} = options || {};
+
     // Parse the trace for our key events and sort them by timestamp. Note: sort
     // *must* be stable to keep events correctly nested.
     const keyEvents = this.filteredTraceSort(trace.traceEvents, e => {
@@ -491,10 +503,139 @@ class TraceProcessor {
     // Filter to just events matching the frame ID, just to make sure.
     const frameEvents = keyEvents.filter(e => e.args.frame === mainFrameIds.frameId);
 
-    // Our navStart will be the last frame navigation in the trace
-    const navigationStart = frameEvents.filter(this._isNavigationStartOfInterest).pop();
-    if (!navigationStart) throw this.createNoNavstartError();
-    const timeOriginEvt = navigationStart;
+    // Compute our time origin to use for all relative timings.
+    const timeOriginEvt = this.computeTimeOrigin(
+      {keyEvents, frameEvents, mainFrameIds},
+      timeOriginDeterminationMethod
+    );
+
+    // Compute the key frame timings for the main frame.
+    const frameTimings = this.computeKeyTimingsForFrame(frameEvents, {timeOriginEvt});
+
+    // Subset all trace events to just our tab's process (incl threads other than main)
+    // stable-sort events to keep them correctly nested.
+    const processEvents = TraceProcessor
+      .filteredTraceSort(trace.traceEvents, e => e.pid === mainFrameIds.pid);
+
+    const mainThreadEvents = processEvents
+      .filter(e => e.tid === mainFrameIds.tid);
+
+    const frames = keyEvents
+      .filter(evt => evt.name === 'FrameCommittedInBrowser')
+      .map(evt => evt.args.data)
+      .filter(/** @return {data is {frame: string, url: string}} */ data => {
+        return Boolean(data && data.frame && data.url);
+      });
+
+    // Ensure our traceEnd reflects all page activity.
+    const traceEnd = this.computeTraceEnd(trace.traceEvents, timeOriginEvt);
+
+    // This could be much more concise with object spread, but the consensus is that explicitness is
+    // preferred over brevity here.
+    return {
+      frames,
+      mainThreadEvents,
+      processEvents,
+      mainFrameIds,
+      timings: {
+        timeOrigin: frameTimings.timings.timeOrigin,
+        firstPaint: frameTimings.timings.firstPaint,
+        firstContentfulPaint: frameTimings.timings.firstContentfulPaint,
+        firstMeaningfulPaint: frameTimings.timings.firstMeaningfulPaint,
+        largestContentfulPaint: frameTimings.timings.largestContentfulPaint,
+        traceEnd: traceEnd.timing,
+        load: frameTimings.timings.load,
+        domContentLoaded: frameTimings.timings.domContentLoaded,
+      },
+      timestamps: {
+        timeOrigin: frameTimings.timestamps.timeOrigin,
+        firstPaint: frameTimings.timestamps.firstPaint,
+        firstContentfulPaint: frameTimings.timestamps.firstContentfulPaint,
+        firstMeaningfulPaint: frameTimings.timestamps.firstMeaningfulPaint,
+        largestContentfulPaint: frameTimings.timestamps.largestContentfulPaint,
+        traceEnd: traceEnd.timestamp,
+        load: frameTimings.timestamps.load,
+        domContentLoaded: frameTimings.timestamps.domContentLoaded,
+      },
+      timeOriginEvt: frameTimings.timeOriginEvt,
+      firstPaintEvt: frameTimings.firstPaintEvt,
+      firstContentfulPaintEvt: frameTimings.firstContentfulPaintEvt,
+      firstMeaningfulPaintEvt: frameTimings.firstMeaningfulPaintEvt,
+      largestContentfulPaintEvt: frameTimings.largestContentfulPaintEvt,
+      loadEvt: frameTimings.loadEvt,
+      domContentLoadedEvt: frameTimings.domContentLoadedEvt,
+      fmpFellBack: frameTimings.fmpFellBack,
+      lcpInvalidated: frameTimings.lcpInvalidated,
+    };
+  }
+
+  /**
+   * Computes the last observable timestamp in a set of trace events.
+   *
+   * @param {Array<LH.TraceEvent>} events
+   * @param {LH.TraceEvent} timeOriginEvt
+   * @return {{timing: number, timestamp: number}}
+   */
+  static computeTraceEnd(events, timeOriginEvt) {
+    let maxTs = -Infinity;
+    for (const event of events) {
+      maxTs = Math.max(event.ts + (event.dur || 0), maxTs);
+    }
+
+    return {timestamp: maxTs, timing: (maxTs - timeOriginEvt.ts) / 1000};
+  }
+
+  /**
+   * Computes the time origin using the specified method.
+   *
+   *    - firstResourceSendRequest
+   *      Uses the time that the very first network request is sent in the main frame.
+   *      Eventually should be used in place of lastNavigationStart as the default for navigations.
+   *      This method includes the cost of all redirects when evaluating a navigation (which matches lantern behavior).
+   *      The only difference between firstResourceSendRequest and the first `navigationStart` is
+   *      the unload time of `about:blank` (which is a Lighthouse implementation detail and shouldn't be included).
+   *
+   *    - lastNavigationStart
+   *      Uses the time of the last `navigationStart` event in the main frame.
+   *      The historical time origin of Lighthouse from 2016-Present.
+   *      This method excludes the cost of client-side redirects when evaluating a navigation.
+   *      Can also be skewed by several hundred milliseconds or even seconds when the browser takes a long
+   *      time to unload `about:blank`.
+   *
+   * @param {{keyEvents: Array<LH.TraceEvent>, frameEvents: Array<LH.TraceEvent>, mainFrameIds: {frameId: string}}} traceEventSubsets
+   * @param {TimeOriginDeterminationMethod} method
+   * @return {LH.TraceEvent}
+   */
+  static computeTimeOrigin(traceEventSubsets, method) {
+    switch (method) {
+      case 'firstResourceSendRequest': {
+        // Our time origin will be the timestamp of the first request that's sent in the frame.
+        const fetchStart = traceEventSubsets.keyEvents.find(event => {
+          if (event.name !== 'ResourceSendRequest') return false;
+          const data = event.args.data || {};
+          return data.frame === traceEventSubsets.mainFrameIds.frameId;
+        });
+        if (!fetchStart) throw this.createNoResourceSendRequestError();
+        return fetchStart;
+      }
+      case 'lastNavigationStart': {
+        // Our time origin will be the last frame navigation in the trace
+        const frameEvents = traceEventSubsets.frameEvents;
+        const navigationStart = frameEvents.filter(this._isNavigationStartOfInterest).pop();
+        if (!navigationStart) throw this.createNoNavstartError();
+        return navigationStart;
+      }
+    }
+  }
+
+  /**
+   * Computes timings of trace events of key trace events in milliseconds since the time origin
+   * in addition to the standard microsecond monotonic timestamps.
+   * @param {Array<LH.TraceEvent>} frameEvents
+   * @param {{timeOriginEvt: LH.TraceEvent}} options
+  */
+  static computeKeyTimingsForFrame(frameEvents, options) {
+    const {timeOriginEvt} = options;
 
     // Find our first paint of this frame
     const firstPaint = frameEvents.find(e => e.name === 'firstPaint' && e.ts > timeOriginEvt.ts);
@@ -553,64 +694,35 @@ class TraceProcessor {
       e => e.name === 'domContentLoadedEventEnd' && e.ts > timeOriginEvt.ts
     );
 
-    // subset all trace events to just our tab's process (incl threads other than main)
-    // stable-sort events to keep them correctly nested.
-    const processEvents = TraceProcessor
-      .filteredTraceSort(trace.traceEvents, e => e.pid === mainFrameIds.pid);
-
-    const mainThreadEvents = processEvents
-      .filter(e => e.tid === mainFrameIds.tid);
-
-    // traceEnd must exist since at least timeOrigin event was verified as existing.
-    const traceEnd = trace.traceEvents.reduce((max, evt) => {
-      return max.ts > evt.ts ? max : evt;
-    });
-    const fakeEndOfTraceEvt = {ts: traceEnd.ts + (traceEnd.dur || 0)};
-
     /** @param {{ts: number}=} event */
     const getTimestamp = (event) => event && event.ts;
-    /** @type {TraceTimesWithoutFCP} */
+    /** @type {TraceTimesWithoutFCPAndTraceEnd} */
     const timestamps = {
       timeOrigin: timeOriginEvt.ts,
       firstPaint: getTimestamp(firstPaint),
       firstContentfulPaint: getTimestamp(firstContentfulPaint),
       firstMeaningfulPaint: getTimestamp(firstMeaningfulPaint),
       largestContentfulPaint: getTimestamp(largestContentfulPaint),
-      traceEnd: fakeEndOfTraceEvt.ts,
       load: getTimestamp(load),
       domContentLoaded: getTimestamp(domContentLoaded),
     };
 
-    /** @param {number} ts */
-    const getTiming = (ts) => (ts - timeOriginEvt.ts) / 1000;
     /** @param {number=} ts */
-    const maybeGetTiming = (ts) => ts === undefined ? undefined : getTiming(ts);
-    /** @type {TraceTimesWithoutFCP} */
+    const maybeGetTiming = (ts) => ts === undefined ? undefined : (ts - timeOriginEvt.ts) / 1000;
+    /** @type {TraceTimesWithoutFCPAndTraceEnd} */
     const timings = {
       timeOrigin: 0,
       firstPaint: maybeGetTiming(timestamps.firstPaint),
       firstContentfulPaint: maybeGetTiming(timestamps.firstContentfulPaint),
       firstMeaningfulPaint: maybeGetTiming(timestamps.firstMeaningfulPaint),
       largestContentfulPaint: maybeGetTiming(timestamps.largestContentfulPaint),
-      traceEnd: getTiming(timestamps.traceEnd),
       load: maybeGetTiming(timestamps.load),
       domContentLoaded: maybeGetTiming(timestamps.domContentLoaded),
     };
 
-    const frames = keyEvents
-      .filter(evt => evt.name === 'FrameCommittedInBrowser')
-      .map(evt => evt.args.data)
-      .filter(/** @return {data is {frame: string, url: string}} */ data => {
-        return Boolean(data && data.frame && data.url);
-      });
-
     return {
       timings,
       timestamps,
-      processEvents,
-      mainThreadEvents,
-      mainFrameIds,
-      frames,
       timeOriginEvt: timeOriginEvt,
       firstPaintEvt: firstPaint,
       firstContentfulPaintEvt: firstContentfulPaint,

lighthouse-core/test/audits/__snapshots__/metrics-test.js.snap

@@ -40,7 +40,7 @@ Object {
   "observedTimeOrigin": 0,
   "observedTimeOriginTs": 713037023064,
   "observedTraceEnd": 7416,
-  "observedTraceEndTs": 713044438781,
+  "observedTraceEndTs": 713044439102,
   "speedIndex": 3681,
   "speedIndexTs": undefined,
   "totalBlockingTime": 1167,

lighthouse-core/test/lib/tracehouse/trace-processor-test.js

@@ -253,6 +253,13 @@ describe('TraceProcessor', () => {
     });
   });
 
+  describe('computeTraceEnd', () => {
+    it('computes the last timestamp within the bounds of the trace', () => {
+      const events = [{ts: 1000}, {ts: 999, dur: 1001}];
+      expect(TraceProcessor.computeTraceEnd(events, {ts: 0})).toEqual({timestamp: 2000, timing: 2});
+    });
+  });
+
   describe('computeTraceOfTab', () => {
     it('gathers the events from the tab\'s process', () => {
       const trace = TraceProcessor.computeTraceOfTab(lateTracingStartedTrace);
@@ -283,7 +290,34 @@ describe('TraceProcessor', () => {
       assert.equal(Math.round(trace.timestamps.firstPaint), 29343620997);
       assert.equal(Math.round(trace.timestamps.firstContentfulPaint), 29343621005);
       assert.equal(Math.round(trace.timestamps.firstMeaningfulPaint), 29344070867);
-      assert.equal(Math.round(trace.timestamps.traceEnd), 29344190223);
+      assert.equal(Math.round(trace.timestamps.traceEnd), 29344190232);
+    });
+
+    describe('timeOriginDeterminationMethod', () => {
+      it('supports lastNavigationStart', () => {
+        const trace = TraceProcessor.computeTraceOfTab(lcpTrace);
+        expect(trace.timings).toMatchObject({
+          largestContentfulPaint: 1121.711,
+          load: 2159.007,
+          traceEnd: 7416.038,
+        });
+
+        expect(trace.timestamps.timeOrigin).toEqual(713037023064);
+      });
+
+      it('supports firstResourceSendRequest', () => {
+        const trace = TraceProcessor.computeTraceOfTab(lcpTrace, {
+          timeOriginDeterminationMethod: 'firstResourceSendRequest',
+        });
+
+        expect(trace.timings).toMatchObject({
+          largestContentfulPaint: 812.683,
+          load: 1849.979,
+          traceEnd: 7107.01,
+        });
+
+        expect(trace.timestamps.timeOrigin).toEqual(713037332092);
+      });
     });
 
     describe('finds correct FMP', () => {
@@ -604,6 +638,17 @@ Object {
         .toThrowError('navigationStart');
     });
 
+    it('throws on traces missing a ResourceSendRequest', () => {
+      const traceWithoutResourceSend = {
+        traceEvents: pwaTrace.filter(e => e.name !== 'ResourceSendRequest'),
+      };
+
+      expect(() => TraceProcessor.computeTraceOfTab(traceWithoutResourceSend, {
+        timeOriginDeterminationMethod: 'firstResourceSendRequest',
+      }))
+        .toThrowError('ResourceSendRequest');
+    });
+
     it('does not throw on traces missing an FCP', () => {
       expect(() => TraceProcessor.computeTraceOfTab(noFCPtrace)).not.toThrow();
     });

proto/lighthouse-result.proto

@@ -57,6 +57,8 @@ enum LighthouseError {
   CRI_TIMEOUT = 20;
   // The page requested was not HTML. 
   NOT_HTML = 21;
+  // The trace did not contain a ResourceSendRequest event.
+  NO_RESOURCE_REQUEST = 22;
 }
 
 // The overarching Lighthouse Response object (LHR)