diff --git a/lighthouse-core/computed/trace-of-tab.js b/lighthouse-core/computed/trace-of-tab.js index 519e96569abe..eb63b974292b 100644 --- a/lighthouse-core/computed/trace-of-tab.js +++ b/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} */ diff --git a/lighthouse-core/lib/lh-error.js b/lighthouse-core/lib/lh-error.js index 5384b8cb8e7d..4fb7a6ba4487 100644 --- a/lighthouse-core/lib/lh-error.js +++ b/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, diff --git a/lighthouse-core/lib/tracehouse/trace-processor.js b/lighthouse-core/lib/tracehouse/trace-processor.js index ae6f95438b2d..cf7100cbf369 100644 --- a/lighthouse-core/lib/tracehouse/trace-processor.js +++ b/lighthouse-core/lib/tracehouse/trace-processor.js @@ -17,7 +17,9 @@ */ /** @typedef {Omit & {firstContentfulPaint?: number}} TraceTimesWithoutFCP */ +/** @typedef {Omit} TraceTimesWithoutFCPAndTraceEnd */ /** @typedef {Omit & {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} 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, frameEvents: Array, 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} 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, diff --git a/lighthouse-core/test/audits/__snapshots__/metrics-test.js.snap b/lighthouse-core/test/audits/__snapshots__/metrics-test.js.snap index faf715c0a589..67d3c4d9cc8b 100644 --- a/lighthouse-core/test/audits/__snapshots__/metrics-test.js.snap +++ b/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, diff --git a/lighthouse-core/test/lib/tracehouse/trace-processor-test.js b/lighthouse-core/test/lib/tracehouse/trace-processor-test.js index 98687450f3a6..f0544bdceae9 100644 --- a/lighthouse-core/test/lib/tracehouse/trace-processor-test.js +++ b/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(); }); diff --git a/proto/lighthouse-result.proto b/proto/lighthouse-result.proto index 4ccdc075a182..c103c44ef87a 100644 --- a/proto/lighthouse-result.proto +++ b/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)