Skip to content

Commit

Permalink
FMP metrics: Don't require tracingStartedInPage to precede navStart (G…
Browse files Browse the repository at this point in the history 
…oogleChrome#1152)

* fix fmp calculation.

* add more tests for finding fmp in tricky cases.

* Expose timestamps and timings in the FMP extendedInfo.

* add timestamps to TTI as well.
  • Loading branch information
@paulirish @andrewrota
paulirish authored and andrewrota committed Jan 13, 2017
1 parent 2d837b3 commit b9176a4
Show file tree
Hide file tree
Showing 5 changed files with 67,439 additions and 86 deletions.
86 changes: 40 additions & 46 deletions lighthouse-core/audits/first-meaningful-paint.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -52,16 +52,7 @@ class FirstMeaningfulPaint extends Audit {
return new Promise((resolve, reject) => {
const traceContents = artifacts.traces[this.DEFAULT_PASS].traceEvents;
const evts = this.collectEvents(traceContents);

const navStart = evts.navigationStart;
const fMP = evts.firstMeaningfulPaint;

const data = {
navStart,
fMP,
};

const result = this.calculateScore(data);
const result = this.calculateScore(evts);

resolve(FirstMeaningfulPaint.generateAuditResult({
score: result.score,
Expand All @@ -83,9 +74,23 @@ class FirstMeaningfulPaint extends Audit {
});
}

static calculateScore(data) {
// First meaningful paint is the last timestamp observed from the candidates
const firstMeaningfulPaint = (data.fMP.ts - data.navStart.ts) / 1000;
static calculateScore(evts) {
const firstMeaningfulPaint = (evts.firstMeaningfulPaint.ts - evts.navigationStart.ts) / 1000;
const firstContentfulPaint = (evts.firstContentfulPaint.ts - evts.navigationStart.ts) / 1000;

// Expose the raw, unchanged monotonic timestamps from the trace, along with timing durations
const extendedInfo = {
timestamps: {
navStart: evts.navigationStart.ts,
fCP: evts.firstContentfulPaint.ts,
fMP: evts.firstMeaningfulPaint.ts
},
timings: {
navStart: 0,
fCP: parseFloat(firstContentfulPaint.toFixed(3)),
fMP: parseFloat(firstMeaningfulPaint.toFixed(3))
}
};

// Use the CDF of a log-normal distribution for scoring.
// < 1100ms: score≈100
Expand All @@ -99,59 +104,48 @@ class FirstMeaningfulPaint extends Audit {
score = Math.min(100, score);
score = Math.max(0, score);

data.fMP = firstMeaningfulPaint;
data.navStart = data.navStart.ts / 1000;

return {
duration: `${firstMeaningfulPaint.toFixed(1)}`,
score: Math.round(score),
rawValue: firstMeaningfulPaint.toFixed(1),
extendedInfo: {timings: data}
rawValue: parseFloat(firstMeaningfulPaint.toFixed(1)),
extendedInfo
};
}

/**
* @param {!Array<!Object>} traceData
*/
static collectEvents(traceData) {
let mainFrameID;
let navigationStart;
let firstMeaningfulPaint;

// const model = new DevtoolsTimelineModel(traceData);
// const events = model.timelineModel().mainThreadEvents();
const events = traceData;

// Parse the trace for our key events and sort them by timestamp.
events.filter(e => e.cat.includes('blink.user_timing') || e.name === 'TracingStartedInPage')
.sort((event0, event1) => {
return event0.ts - event1.ts;
}).forEach(event => {
// Grab the page's ID from the first TracingStartedInPage in the trace
if (event.name === 'TracingStartedInPage' && !mainFrameID) {
mainFrameID = event.args.data.page;
}

// Record the navigationStart, but only once TracingStartedInPage has started
// which is when mainFrameID exists
if (event.name === 'navigationStart' && !!mainFrameID && !navigationStart) {
navigationStart = event;
}
if (event.name === 'firstMeaningfulPaint' && event.args.frame === mainFrameID &&
!!navigationStart && event.ts >= navigationStart.ts) {
firstMeaningfulPaint = event;
}
});
const events = traceData.filter(e => {
return e.cat.includes('blink.user_timing') || e.name === 'TracingStartedInPage';
}).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 = events.find(e => e.name === 'TracingStartedInPage');
// Filter to just events matching the frame ID for sanity
const frameEvents = events.filter(e => e.args.frame === startedInPageEvt.args.data.page);

// Find our first FCP
const firstFCP = frameEvents.find(e => e.name === 'firstContentfulPaint');
// Our navStart will be the latest one before fCP.
const navigationStart = frameEvents.filter(e =>
e.name === 'navigationStart' && e.ts < firstFCP.ts).pop();
// FMP will follow at/after the FCP
const firstMeaningfulPaint = frameEvents.find(e =>
e.name === 'firstMeaningfulPaint' && e.ts >= firstFCP.ts);

// navigationStart is currently essential to FMP calculation.
// see: https://github.com/GoogleChrome/lighthouse/issues/753
if (!navigationStart) {
throw new Error('No `navigationStart` event found after `TracingStartedInPage` in trace');
throw new Error('No `navigationStart` event found in trace');
}

return {
navigationStart,
firstMeaningfulPaint,
firstContentfulPaint: firstFCP
};
}
}
Expand Down
38 changes: 22 additions & 16 deletions lighthouse-core/audits/time-to-interactive.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -71,29 +71,29 @@ class TTIMetric extends Audit {
if (fmpResult.rawValue === -1) {
return generateError(fmpResult.debugString);
}
const fmpTiming = parseFloat(fmpResult.rawValue);
const timings = fmpResult.extendedInfo && fmpResult.extendedInfo.value &&
fmpResult.extendedInfo.value.timings;

// Process the trace
const tracingProcessor = new TracingProcessor();
const trace = artifacts.traces[Audit.DEFAULT_PASS];
const model = tracingProcessor.init(trace);
const endOfTraceTime = model.bounds.max;

// TODO: Wait for DOMContentLoadedEndEvent
const fMPts = timings.fMP + timings.navStart;
const fmpTiming = fmpResult.rawValue;
const fmpResultExt = fmpResult.extendedInfo.value;

// frame monotonic timestamps from speedline are in ms (ts / 1000), so we'll match
// https://github.com/pmdartus/speedline/blob/123f512632a/src/frame.js#L86
const fMPtsInMS = fmpResultExt.timestamps.fMP / 1000;
const navStartTsInMS = fmpResultExt.timestamps.navStart / 1000;

// look at speedline results for 85% starting at FMP
let visuallyReadyTiming = 0;

if (speedline.frames) {
const eightyFivePctVC = speedline.frames.find(frame => {
return frame.getTimeStamp() >= fMPts && frame.getProgress() >= 85;
return frame.getTimeStamp() >= fMPtsInMS && frame.getProgress() >= 85;
});

if (eightyFivePctVC) {
visuallyReadyTiming = eightyFivePctVC.getTimeStamp() - timings.navStart;
visuallyReadyTiming = eightyFivePctVC.getTimeStamp() - navStartTsInMS;
}
}

Expand All @@ -117,7 +117,7 @@ class TTIMetric extends Audit {
// Get our expected latency for the time window
const latencies = TracingProcessor.getRiskToResponsiveness(
model, trace, startTime, endTime, percentiles);
const estLatency = latencies[0].time.toFixed(2);
const estLatency = latencies[0].time;
foundLatencies.push({
estLatency: estLatency,
startTime: startTime.toFixed(1)
Expand All @@ -126,7 +126,8 @@ class TTIMetric extends Audit {
// Grab this latency and try the threshold again
currentLatency = estLatency;
}
const timeToInteractive = parseFloat(startTime.toFixed(1));
// The start of our window is our TTI
const timeToInteractive = startTime;

// Use the CDF of a log-normal distribution for scoring.
// < 1200ms: score≈100
Expand All @@ -143,17 +144,22 @@ class TTIMetric extends Audit {

const extendedInfo = {
timings: {
fMP: fmpTiming.toFixed(1),
visuallyReady: visuallyReadyTiming.toFixed(1),
mainThreadAvail: startTime.toFixed(1)
fMP: parseFloat(fmpTiming.toFixed(3)),
visuallyReady: parseFloat(visuallyReadyTiming.toFixed(3)),
timeToInteractive: parseFloat(startTime.toFixed(3))
},
timestamps: {
fMP: fMPtsInMS * 1000,
visuallyReady: (visuallyReadyTiming + navStartTsInMS) * 1000,
timeToInteractive: (timeToInteractive + navStartTsInMS) * 1000
},
expectedLatencyAtTTI: currentLatency,
expectedLatencyAtTTI: parseFloat(currentLatency.toFixed(3)),
foundLatencies
};

return TTIMetric.generateAuditResult({
score,
rawValue: timeToInteractive,
rawValue: parseFloat(timeToInteractive.toFixed(1)),
displayValue: `${timeToInteractive}ms`,
optimalValue: this.meta.optimalValue,
debugString: speedline.debugString,
Expand Down
64 changes: 45 additions & 19 deletions lighthouse-core/test/audits/first-meaningful-paint-test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,32 +20,23 @@ const Audit = require('../../audits/audit.js');
const assert = require('assert');
const traceEvents = require('../fixtures/traces/progressive-app.json');
const badNavStartTrace = require('../fixtures/traces/bad-nav-start-ts.json');
const lateTracingStartedTrace = require('../fixtures/traces/tracingstarted-after-navstart.json');

function getArtifacts(trace) {
return {
traces: {
[Audit.DEFAULT_PASS]: {traceEvents: Array.isArray(trace) ? trace : trace.traceEvents}
}
};
}

/* eslint-env mocha */
describe('Performance: first-meaningful-paint audit', () => {
it('scores a -1 and returns an error when navigation start is before trace start', () => {
const artifacts = {
traces: {
[Audit.DEFAULT_PASS]: badNavStartTrace
}
};
return FMPAudit.audit(artifacts).then(result => {
assert.equal(result.rawValue, -1);
assert.ok(/navigationStart/.test(result.debugString));
});
});

describe('measures the pwa.rocks example correctly', () => {
let fmpResult;

it('processes a valid trace file', () => {
const artifacts = {
traces: {
[Audit.DEFAULT_PASS]: {traceEvents}
}
};

return FMPAudit.audit(artifacts).then(result => {
return FMPAudit.audit(getArtifacts(traceEvents)).then(result => {
fmpResult = result;
}).catch(_ => {
assert.ok(false);
Expand All @@ -61,8 +52,43 @@ describe('Performance: first-meaningful-paint audit', () => {
assert.equal(fmpResult.extendedInfo.value.timings.fMP, 1099.523);
});

it('exposes the FCP timing', () => {
assert.equal(fmpResult.extendedInfo.value.timings.fCP, 461.901);
});

it('exposes the navStart timestamp', () => {
assert.equal(fmpResult.extendedInfo.value.timestamps.navStart, 668545382727);
});

it('scores the fMP correctly', () => {
assert.equal(fmpResult.score, 99);
});
});

describe('finds correct FMP in various traces', () => {
it('finds the fMP if there was a tracingStartedInPage after the frame\'s navStart', () => {
return FMPAudit.audit(getArtifacts(lateTracingStartedTrace)).then(result => {
assert.equal(result.displayValue, '529.9ms');
assert.equal(result.rawValue, 529.9);
assert.equal(result.extendedInfo.value.timestamps.navStart, 29343540951);
assert.equal(result.extendedInfo.value.timings.fCP, 80.054);
assert.ok(!result.debugString);
}).catch(_ => {
console.error(_);
assert.ok(false);
});
});

it('finds the fMP if there was a tracingStartedInPage after the frame\'s navStart #2', () => {
return FMPAudit.audit(getArtifacts(badNavStartTrace)).then(result => {
assert.equal(result.displayValue, '632.4ms');
assert.equal(result.rawValue, 632.4);
assert.equal(result.extendedInfo.value.timestamps.navStart, 8885424467);
assert.equal(result.extendedInfo.value.timings.fCP, 632.419);
assert.ok(!result.debugString);
}).catch(_ => {
assert.ok(false);
});
});
});
});
10 changes: 5 additions & 5 deletions lighthouse-core/test/audits/time-to-interactive-test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -50,11 +50,11 @@ describe('Performance: time-to-interactive audit', () => {
};

return Audit.audit(artifacts).then(output => {
assert.equal(output.rawValue, '1105.8', output.debugString);
assert.equal(output.extendedInfo.value.expectedLatencyAtTTI, '20.72');
assert.equal(output.extendedInfo.value.timings.fMP, '1099.5');
assert.equal(output.extendedInfo.value.timings.mainThreadAvail, '1105.8');
assert.equal(output.extendedInfo.value.timings.visuallyReady, '1105.8');
assert.equal(output.rawValue, 1105.8, output.debugString);
assert.equal(output.extendedInfo.value.expectedLatencyAtTTI, 20.724);
assert.equal(output.extendedInfo.value.timings.fMP, 1099.5);
assert.equal(output.extendedInfo.value.timings.timeToInteractive, 1105.798);
assert.equal(output.extendedInfo.value.timings.visuallyReady, 1105.798);
});
});
});
Loading

0 comments on commit b9176a4

Please sign in to comment.