Skip to content

Commit

Permalink
Improve reliability of finding navStart (#1895)
Browse files Browse the repository at this point in the history 
* Improve reliability of finding navStart

* feedback.
  • Loading branch information
@paulirish
paulirish committed Mar 24, 2017
1 parent 44a2d3b commit ca2600a
Show file tree
Hide file tree
Showing 4 changed files with 312 additions and 59 deletions.
37 changes: 21 additions & 16 deletions lighthouse-core/gather/computed/trace-of-tab.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -32,7 +32,6 @@ const ComputedArtifact = require('./computed-artifact');
const log = require('../../lib/log');

class TraceOfTab extends ComputedArtifact {

get name() {
return 'TraceOfTab';
}
Expand All @@ -43,30 +42,36 @@ 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();
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.
Expand All @@ -83,17 +88,17 @@ 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,
startedInPageEvt: startedInPageEvt,
navigationStartEvt: navigationStart,
firstPaintEvt: firstPaint,
firstContentfulPaintEvt: firstContentfulPaint,
firstMeaningfulPaintEvt: firstMeaningfulPaint
firstMeaningfulPaintEvt: firstMeaningfulPaint,
};
}
}
Expand Down
67 changes: 28 additions & 39 deletions lighthouse-core/lib/traces/pwmetrics-events.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,6 @@
const log = require('../../../lighthouse-core/lib/log.js');

class Metrics {

constructor(traceEvents, auditResults) {
this._traceEvents = traceEvents;
this._auditResults = auditResults;
Expand All @@ -37,64 +36,64 @@ class Metrics {
getTs: auditResults => {
const fmpExt = auditResults['first-meaningful-paint'].extendedInfo;
return fmpExt.value.timestamps.navStart;
}
},
},
{
name: 'First Contentful Paint',
id: 'ttfcp',
getTs: auditResults => {
const fmpExt = auditResults['first-meaningful-paint'].extendedInfo;
return fmpExt.value.timestamps.fCP;
}
},
},
{
name: 'First Meaningful Paint',
id: 'ttfmp',
getTs: auditResults => {
const fmpExt = auditResults['first-meaningful-paint'].extendedInfo;
return fmpExt.value.timestamps.fMP;
}
},
},
{
name: 'Perceptual Speed Index',
id: 'psi',
getTs: auditResults => {
const siExt = auditResults['speed-index-metric'].extendedInfo;
return siExt.value.timestamps.perceptualSpeedIndex;
}
},
},
{
name: 'First Visual Change',
id: 'fv',
getTs: auditResults => {
const siExt = auditResults['speed-index-metric'].extendedInfo;
return siExt.value.timestamps.firstVisualChange;
}
},
},
{
name: 'Visually Complete 85%',
id: 'vc85',
getTs: auditResults => {
const siExt = auditResults['time-to-interactive'].extendedInfo;
return siExt.value.timestamps.visuallyReady;
}
},
},
{
name: 'Visually Complete 100%',
id: 'vc100',
getTs: auditResults => {
const siExt = auditResults['speed-index-metric'].extendedInfo;
return siExt.value.timestamps.visuallyComplete;
}
},
},
{
name: 'Time to Interactive',
id: 'tti',
getTs: auditResults => {
const ttiExt = auditResults['time-to-interactive'].extendedInfo;
return ttiExt.value.timestamps.timeToInteractive;
}
}
},
},
];
}

Expand All @@ -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}`);
Expand All @@ -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,
Expand All @@ -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 [];
}

Expand All @@ -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;
}
Expand Down
Loading

0 comments on commit ca2600a

Please sign in to comment.