From ca2600acc5cb85094fae03b4f606e52a41f5232f Mon Sep 17 00:00:00 2001 From: Paul Irish Date: Thu, 23 Mar 2017 19:41:15 -0700 Subject: [PATCH] Improve reliability of finding navStart (#1895) * Improve reliability of finding navStart * feedback. --- .../gather/computed/trace-of-tab.js | 37 +-- .../lib/traces/pwmetrics-events.js | 67 ++--- .../backgrounded-tab-missing-paints.json | 244 ++++++++++++++++++ .../test/gather/computed/trace-of-tab-test.js | 23 +- 4 files changed, 312 insertions(+), 59 deletions(-) create mode 100644 lighthouse-core/test/fixtures/traces/backgrounded-tab-missing-paints.json diff --git a/lighthouse-core/gather/computed/trace-of-tab.js b/lighthouse-core/gather/computed/trace-of-tab.js index 4ec5cba45f91..83a5e553b313 100644 --- a/lighthouse-core/gather/computed/trace-of-tab.js +++ b/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,10 +42,13 @@ 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 @@ -54,19 +56,22 @@ class TraceOfTab extends ComputedArtifact { // 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(); + if (!navigationStart) throw new Error('navigationStart was not found in the trace'); + // 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,9 +88,9 @@ 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 => e.pid === startedInPageEvt.pid) + .sort((event0, event1) => event0.ts - event1.ts); return { processEvents, @@ -93,7 +98,7 @@ class TraceOfTab extends ComputedArtifact { navigationStartEvt: navigationStart, firstPaintEvt: firstPaint, firstContentfulPaintEvt: firstContentfulPaint, - firstMeaningfulPaintEvt: firstMeaningfulPaint + firstMeaningfulPaintEvt: firstMeaningfulPaint, }; } } diff --git a/lighthouse-core/lib/traces/pwmetrics-events.js b/lighthouse-core/lib/traces/pwmetrics-events.js index 13122e3c6c98..f7522f95142c 100644 --- a/lighthouse-core/lib/traces/pwmetrics-events.js +++ b/lighthouse-core/lib/traces/pwmetrics-events.js @@ -19,7 +19,6 @@ const log = require('../../../lighthouse-core/lib/log.js'); class Metrics { - constructor(traceEvents, auditResults) { this._traceEvents = traceEvents; this._auditResults = auditResults; @@ -37,7 +36,7 @@ class Metrics { getTs: auditResults => { const fmpExt = auditResults['first-meaningful-paint'].extendedInfo; return fmpExt.value.timestamps.navStart; - } + }, }, { name: 'First Contentful Paint', @@ -45,7 +44,7 @@ class Metrics { getTs: auditResults => { const fmpExt = auditResults['first-meaningful-paint'].extendedInfo; return fmpExt.value.timestamps.fCP; - } + }, }, { name: 'First Meaningful Paint', @@ -53,7 +52,7 @@ class Metrics { getTs: auditResults => { const fmpExt = auditResults['first-meaningful-paint'].extendedInfo; return fmpExt.value.timestamps.fMP; - } + }, }, { name: 'Perceptual Speed Index', @@ -61,7 +60,7 @@ class Metrics { getTs: auditResults => { const siExt = auditResults['speed-index-metric'].extendedInfo; return siExt.value.timestamps.perceptualSpeedIndex; - } + }, }, { name: 'First Visual Change', @@ -69,7 +68,7 @@ class Metrics { getTs: auditResults => { const siExt = auditResults['speed-index-metric'].extendedInfo; return siExt.value.timestamps.firstVisualChange; - } + }, }, { name: 'Visually Complete 85%', @@ -77,7 +76,7 @@ class Metrics { getTs: auditResults => { const siExt = auditResults['time-to-interactive'].extendedInfo; return siExt.value.timestamps.visuallyReady; - } + }, }, { name: 'Visually Complete 100%', @@ -85,7 +84,7 @@ class Metrics { getTs: auditResults => { const siExt = auditResults['speed-index-metric'].extendedInfo; return siExt.value.timestamps.visuallyComplete; - } + }, }, { name: 'Time to Interactive', @@ -93,8 +92,8 @@ class Metrics { getTs: auditResults => { const ttiExt = auditResults['time-to-interactive'].extendedInfo; return ttiExt.value.timestamps.timeToInteractive; - } - } + }, + }, ]; } @@ -111,7 +110,7 @@ class Metrics { resolvedMetrics.push({ id: metric.id, name: metric.name, - ts: metric.getTs(this._auditResults) + ts: metric.getTs(this._auditResults), }); } catch (e) { log.error('pwmetrics-events', `${metric.name} timestamp not found: ${e.message}`); @@ -121,47 +120,38 @@ 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 navStartMetric = metrics.find(e => e.id === 'navstart'); + if (!navStartMetric) return; + this._navigationStartEvt = this._traceEvents.find( + e => e.name === 'navigationStart' && e.ts === navStartMetric.ts + ); } - /** * 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"} * { "pid": 89922,"tid":1295,"ts":77176882592,"ph":"e","cat":"blink.user_timing","name":"innermeasure","args":{},"tts":1257898,"id":"0xe66c67"} * @param {{ts: number, id: string, name: string}} metric - * @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)}` + id: `0x${((Math.random() * 1000000) | 0).toString(16)}`, }; const fakeMeasureStartEvent = Object.assign({}, eventBase, { - ts: navStart.ts, - ph: 'b' + ts: this._navigationStartEvt.ts, + ph: 'b', }); const fakeMeasureEndEvent = Object.assign({}, eventBase, { ts: metric.ts, @@ -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; } diff --git a/lighthouse-core/test/fixtures/traces/backgrounded-tab-missing-paints.json b/lighthouse-core/test/fixtures/traces/backgrounded-tab-missing-paints.json new file mode 100644 index 000000000000..49557d5a2842 --- /dev/null +++ b/lighthouse-core/test/fixtures/traces/backgrounded-tab-missing-paints.json @@ -0,0 +1,244 @@ +{ + "traceEvents": [ + { + "pid": 84742, + "tid": 775, + "ts": 1966813248134, + "ph": "I", + "cat": "disabled-by-default-devtools.timeline", + "name": "TracingStartedInPage", + "args": { + "data": { + "frames": [ + { + "frame": "0x53965941e30", + "name": "", + "url": "about:blank" + } + ], + "page": "0x53965941e30", + "sessionId": "84742.1" + } + }, + "tts": 223424, + "s": "t" + }, + { + "pid": 84742, + "tid": 775, + "ts": 1966813258737, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x53965941e30" + }, + "tts": 224001 + }, + { + "pid": 84742, + "tid": 775, + "ts": 1966813258737, + "ph": "b", + "cat": "blink.user_timing", + "name": "HTML (nearly) done parsing", + "args": {}, + "tts": 302161, + "id": "0x472bc7" + }, + { + "pid": 84748, + "tid": 775, + "ts": 1966813346529, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x1aff390e1e30" + }, + "tts": 168711 + }, + { + "pid": 84748, + "tid": 775, + "ts": 1966813520313, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x1aff390e1e30" + }, + "tts": 165887 + }, + { + "pid": 84748, + "tid": 775, + "ts": 1966813681789, + "ph": "I", + "cat": "blink.user_timing,rail", + "name": "firstPaint", + "args": { + "frame": "0x1aff390e1e30" + }, + "tts": 239086, + "s": "p" + }, + { + "pid": 84748, + "tid": 775, + "ts": 1966813681796, + "ph": "I", + "cat": "blink.user_timing,rail", + "name": "firstContentfulPaint", + "args": { + "frame": "0x1aff390e1e30" + }, + "tts": 239094, + "s": "p" + }, + { + "pid": 84748, + "tid": 775, + "ts": 1966813681804, + "ph": "R", + "cat": "loading", + "name": "firstMeaningfulPaintCandidate", + "args": { + "frame": "0x1aff390e1e30" + }, + "tts": 239102 + }, + { + "pid": 84748, + "tid": 775, + "ts": 1966813681804, + "ph": "R", + "cat": "blink.user_timing", + "name": "firstMeaningfulPaint", + "args": { + "frame": "0x1aff390e1e30" + }, + "tts": 558548 + }, + { + "pid": 84748, + "tid": 775, + "ts": 1966813687842, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x1aff39202018" + }, + "tts": 244856 + }, + { + "pid": 84748, + "tid": 775, + "ts": 1966813688199, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x1aff39202018" + }, + "tts": 245213 + }, + { + "pid": 84748, + "tid": 775, + "ts": 1966813800819, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x1aff3920f270" + }, + "tts": 321306 + }, + { + "pid": 84748, + "tid": 775, + "ts": 1966813801543, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x1aff3920f270" + }, + "tts": 322028 + }, + { + "pid": 84742, + "tid": 775, + "ts": 1966813859411, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x53965a690b8" + }, + "tts": 245754 + }, + { + "pid": 84742, + "tid": 775, + "ts": 1966813860310, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x53965a690b8" + }, + "tts": 246611 + }, + { + "pid": 84742, + "tid": 775, + "ts": 1966815045592, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x53965a776c0" + }, + "tts": 310161 + }, + { + "pid": 84742, + "tid": 775, + "ts": 1966815046966, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x53965a776c0" + }, + "tts": 311533 + }, + { + "pid": 84742, + "tid": 775, + "ts": 1966823069702, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x53965a09560" + }, + "tts": 1090348 + }, + { + "pid": 84742, + "tid": 775, + "ts": 1966823070744, + "ph": "R", + "cat": "blink.user_timing", + "name": "navigationStart", + "args": { + "frame": "0x53965a09560" + }, + "tts": 1091389 + } + ] +} \ No newline at end of file diff --git a/lighthouse-core/test/gather/computed/trace-of-tab-test.js b/lighthouse-core/test/gather/computed/trace-of-tab-test.js index 3b0b6c51cc9f..5a85118da4e4 100644 --- a/lighthouse-core/test/gather/computed/trace-of-tab-test.js +++ b/lighthouse-core/test/gather/computed/trace-of-tab-test.js @@ -24,6 +24,7 @@ const lateTracingStartedTrace = require('../../fixtures/traces/tracingstarted-af const preactTrace = require('../../fixtures/traces/preactjs.com_ts_of_undefined.json'); const noFMPtrace = require('../../fixtures/traces/no_fmp_event.json'); const noFCPtrace = require('../../fixtures/traces/airhorner_no_fcp'); +const backgroundTabTrace = require('../../fixtures/traces/backgrounded-tab-missing-paints'); /* eslint-env mocha */ describe('Trace of Tab computed artifact:', () => { @@ -77,9 +78,23 @@ describe('Trace of Tab computed artifact:', () => { it('handles traces missing an FCP', () => { const trace = traceOfTab.compute_(noFCPtrace); - assert.equal(trace.startedInPageEvt.ts, 2149509117532); - assert.equal(trace.navigationStartEvt.ts, 2149509122585); - assert.equal(trace.firstContentfulPaintEvt, undefined); - assert.equal(trace.firstMeaningfulPaintEvt.ts, 2149509604903); + assert.equal(trace.startedInPageEvt.ts, 2149509117532, 'bad tracingstartedInPage'); + assert.equal(trace.navigationStartEvt.ts, 2149509122585, 'bad navStart'); + assert.equal(trace.firstContentfulPaintEvt, undefined, 'bad fcp'); + assert.equal(trace.firstMeaningfulPaintEvt.ts, 2149509604903, 'bad fmp'); + }); + + it('handles traces missing a paints (captured in background tab)', () => { + const trace = traceOfTab.compute_(backgroundTabTrace); + assert.equal(trace.startedInPageEvt.ts, 1966813248134); + assert.notEqual(trace.navigationStartEvt.ts, 1966813346529, 'picked wrong frame'); + assert.notEqual(trace.navigationStartEvt.ts, 1966813520313, 'picked wrong frame'); + assert.equal( + trace.navigationStartEvt.ts, + 1966813258737, + 'didnt select navStart event with same timestamp as usertiming measure' + ); + assert.equal(trace.firstContentfulPaintEvt, undefined, 'bad fcp'); + assert.equal(trace.firstMeaningfulPaintEvt, undefined, 'bad fmp'); }); });