Skip to content

Commit

Permalink
Introduce TraceOfTab computed artifact (#1549)
Browse files Browse the repository at this point in the history
* Introduce TraceOfTab computed artifact, and migrate FMP audit to it.

* Migrate user-timing to TraceOfTab artifact and off devtools-timeline-model.
  • Loading branch information
paulirish authored and brendankenny committed Jan 28, 2017
1 parent a58d7dc commit 7a3dbbd
Show file tree
Hide file tree
Showing 9 changed files with 299 additions and 187 deletions.
73 changes: 20 additions & 53 deletions lighthouse-core/audits/first-meaningful-paint.js
Original file line number Diff line number Diff line change
Expand Up @@ -26,11 +26,6 @@ const Formatter = require('../formatters/formatter');
const SCORING_POINT_OF_DIMINISHING_RETURNS = 1600;
const SCORING_MEDIAN = 4000;

// We want an fMP at or after our fCP, however we see traces with the sole fMP
// being up to 1ms BEFORE the fCP. We're okay if this happens, however if we see
// a gap of more than 2 frames (32,000 microseconds), then it's a bug that should
// be addressed in FirstMeaningfulPaintDetector.cpp
const FCPFMP_TOLERANCE = 32 * 1000;

class FirstMeaningfulPaint extends Audit {
/**
Expand All @@ -56,12 +51,26 @@ class FirstMeaningfulPaint extends Audit {
* @return {!Promise<!AuditResult>} The score from the audit, ranging from 0-100.
*/
static audit(artifacts) {
return new Promise((resolve, reject) => {
const traceContents = artifacts.traces[this.DEFAULT_PASS].traceEvents;
const evts = this.collectEvents(traceContents);
const result = this.calculateScore(evts);
const trace = artifacts.traces[this.DEFAULT_PASS];
return artifacts.requestTraceOfTab(trace).then(tabTrace => {
// Sometimes fMP is triggered before fCP
if (!tabTrace.firstMeaningfulPaintEvt) {
throw new Error('No usable `firstMeaningfulPaint` event found in trace');
}

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

const result = this.calculateScore({
navigationStart: tabTrace.navigationStartEvt,
firstMeaningfulPaint: tabTrace.firstMeaningfulPaintEvt,
firstContentfulPaint: tabTrace.firstContentfulPaintEvt
});

resolve(FirstMeaningfulPaint.generateAuditResult({
return FirstMeaningfulPaint.generateAuditResult({
score: result.score,
rawValue: parseFloat(result.duration),
displayValue: `${result.duration}ms`,
Expand All @@ -71,7 +80,7 @@ class FirstMeaningfulPaint extends Audit {
value: result.extendedInfo,
formatter: Formatter.SUPPORTED_FORMATS.NULL
}
}));
});
}).catch(err => {
// Recover from trace parsing failures.
return FirstMeaningfulPaint.generateAuditResult({
Expand Down Expand Up @@ -118,48 +127,6 @@ class FirstMeaningfulPaint extends Audit {
extendedInfo
};
}

/**
* @param {!Array<!Object>} traceData
*/
static collectEvents(traceData) {
// Parse the trace for our key events and sort them by timestamp.
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, though we allow some timestamp tolerance
const firstMeaningfulPaint = frameEvents.find(e =>
e.name === 'firstMeaningfulPaint' && e.ts >= (firstFCP.ts - FCPFMP_TOLERANCE));

// Sometimes fMP is triggered before fCP
if (!firstMeaningfulPaint) {
throw new Error('No usable `firstMeaningfulPaint` event found in trace');
}

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

return {
navigationStart,
firstMeaningfulPaint,
firstContentfulPaint: firstFCP
};
}
}

module.exports = FirstMeaningfulPaint;
171 changes: 73 additions & 98 deletions lighthouse-core/audits/user-timings.js
Original file line number Diff line number Diff line change
Expand Up @@ -19,95 +19,6 @@

const Audit = require('./audit');
const Formatter = require('../formatters/formatter');
const TimelineModel = require('../lib/traces/devtools-timeline-model');

/**
* @param {!Array<!Object>} traceData
* @return {!Array<!UserTimingsExtendedInfo>}
*/
function filterTrace(traceData) {
const userTimings = [];
const measuresStartTimes = {};
let traceStartFound = false;
let navigationStartTime;

// Fetch blink.user_timing events from the tracing data
const timelineModel = new TimelineModel(traceData);
const modeledTraceData = timelineModel.timelineModel();

// Get all blink.user_timing events
// The event phases we are interested in are mark and instant events (R, i, I)
// and duration events which correspond to measures (B, b, E, e).
// @see https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#
modeledTraceData.mainThreadEvents()
.filter(ut => {
if (ut.name === 'TracingStartedInPage' || ut.name === 'navigationStart') {
return true;
}

if (ut.hasCategory('blink.user_timing')) {
// reject these "userTiming" events that aren't really UserTiming, by nuking ones with frame data (or requestStart)
// https://cs.chromium.org/search/?q=trace_event.*?user_timing&sq=package:chromium&type=cs
return ut.name !== 'requestStart' &&
ut.name !== 'paintNonDefaultBackgroundColor' &&
ut.args.frame === undefined;
}

return false;
})
.forEach(ut => {
// Mark events fall under phases R and I (or i)
if (ut.phase === 'R' || ut.phase.toUpperCase() === 'I') {
// We only care about trace events that have to do with the page
// Sometimes other frames can show up in the frame beforehand
if (ut.name === 'TracingStartedInPage' && !traceStartFound) {
traceStartFound = true;
return;
}

// Once TraceingStartedInPage has begun, the next navigationStart event
// marks the start of navigation
// Make sure to not record such events hereafter
if (ut.name === 'navigationStart' && traceStartFound && !navigationStartTime) {
navigationStartTime = ut.startTime;
}

// Add user timings event to array
if (ut.name !== 'navigationStart') {
userTimings.push({
name: ut.name,
isMark: true, // defines type of performance metric
args: ut.args,
startTime: ut.startTime
});
}
} else if (ut.phase.toLowerCase() === 'b') {
// Beginning of measure event, keep track of this events start time
measuresStartTimes[ut.name] = ut.startTime;
} else if (ut.phase.toLowerCase() === 'e') {
// End of measure event
// Add to the array of events
userTimings.push({
name: ut.name,
isMark: false,
args: ut.args,
startTime: measuresStartTimes[ut.name],
duration: ut.startTime - measuresStartTimes[ut.name],
endTime: ut.startTime
});
}
});

userTimings.forEach(ut => {
ut.startTime -= navigationStartTime;
if (!ut.isMark) {
ut.endTime -= navigationStartTime;
ut.duration = ut.duration;
}
});

return userTimings;
}

class UserTimings extends Audit {
/**
Expand All @@ -125,21 +36,85 @@ class UserTimings extends Audit {
};
}

/**
* @param {!Object} tabTrace
* @return {!Array<!UserTimingsExtendedInfo>}
*/
static filterTrace(tabTrace) {
const userTimings = [];
const measuresStartTimes = {};

// Get all blink.user_timing events
// The event phases we are interested in are mark and instant events (R, i, I)
// and duration events which correspond to measures (B, b, E, e).
// @see https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#
tabTrace.processEvents.filter(evt => {
if (!evt.cat.includes('blink.user_timing')) {
return false;
}

// reject these "userTiming" events that aren't really UserTiming, by nuking ones with frame data (or requestStart)
// https://cs.chromium.org/search/?q=trace_event.*?user_timing&sq=package:chromium&type=cs
return evt.name !== 'requestStart' &&
evt.name !== 'navigationStart' &&
evt.name !== 'paintNonDefaultBackgroundColor' &&
evt.args.frame === undefined;
})
.forEach(ut => {
// Mark events fall under phases R and I (or i)
if (ut.ph === 'R' || ut.ph.toUpperCase() === 'I') {
userTimings.push({
name: ut.name,
isMark: true,
args: ut.args,
startTime: ut.ts
});

// Beginning of measure event, keep track of this events start time
} else if (ut.ph.toLowerCase() === 'b') {
measuresStartTimes[ut.name] = ut.ts;

// End of measure event
} else if (ut.ph.toLowerCase() === 'e') {
userTimings.push({
name: ut.name,
isMark: false,
args: ut.args,
startTime: measuresStartTimes[ut.name],
endTime: ut.ts
});
}
});

// baseline the timestamps against navStart, and translate to milliseconds
userTimings.forEach(ut => {
ut.startTime = (ut.startTime - tabTrace.navigationStartEvt.ts) / 1000;
if (!ut.isMark) {
ut.endTime = (ut.endTime - tabTrace.navigationStartEvt.ts) / 1000;
ut.duration = ut.endTime - ut.startTime;
}
});

return userTimings;
}

/**
* @param {!Artifacts} artifacts
* @return {!AuditResult}
*/
static audit(artifacts) {
const traceContents = artifacts.traces[Audit.DEFAULT_PASS].traceEvents;
const userTimings = filterTrace(traceContents);
const trace = artifacts.traces[Audit.DEFAULT_PASS];
return artifacts.requestTraceOfTab(trace).then(tabTrace => {
const userTimings = this.filterTrace(tabTrace);

return UserTimings.generateAuditResult({
rawValue: true,
displayValue: userTimings.length,
extendedInfo: {
formatter: Formatter.SUPPORTED_FORMATS.USER_TIMINGS,
value: userTimings
}
return UserTimings.generateAuditResult({
rawValue: true,
displayValue: userTimings.length,
extendedInfo: {
formatter: Formatter.SUPPORTED_FORMATS.USER_TIMINGS,
value: userTimings
}
});
});
}
}
Expand Down
2 changes: 1 addition & 1 deletion lighthouse-core/gather/computed/computed-artifact.js
Original file line number Diff line number Diff line change
Expand Up @@ -46,7 +46,7 @@ class ComputedArtifact {
return Promise.resolve(this.cache.get(artifact));
}

return Promise.resolve(this.compute_(artifact)).then(computedArtifact => {
return Promise.resolve().then(_ => this.compute_(artifact)).then(computedArtifact => {
this.cache.set(artifact, computedArtifact);
return computedArtifact;
});
Expand Down
88 changes: 88 additions & 0 deletions lighthouse-core/gather/computed/trace-of-tab.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,88 @@
/**
* @license
* Copyright 2017 Google Inc. All rights reserved.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/

'use strict';

/**
* @fileoverview Singluar helper to parse a raw trace and extract the most useful data for
* various tools. This artifact will take a trace and then:
*
* 1. Find the TracingStartedInPage and navigationStart events of our intended tab & frame.
* 2. Find the firstContentfulPaint and marked firstMeaningfulPaint events
* 3. Isolate only the trace events from the tab's process (including all threads like compositor)
* * Sort those trace events in chronological order (as order isn't guaranteed)
* 4. Return all those items in one handy bundle.
*/

const ComputedArtifact = require('./computed-artifact');

class TraceOfTab extends ComputedArtifact {

get name() {
return 'TraceOfTab';
}

// We want an fMP at or after our fCP, however we see traces with the sole fMP
// being up to 1ms BEFORE the fCP. We're okay if this happens, however if we see
// a gap of more than 2 frames (32,000 microseconds), then it's a bug that should
// be addressed in FirstMeaningfulPaintDetector.cpp
static get fmpToleranceMs() {
return 32 * 1000;
}

/**
* @param {{traceEvents: !Array}} trace
* @return {!{processEvents: !Array<TraceEvent>, startedInPageEvt: TraceEvent, navigationStartEvt: TraceEvent, firstContentfulPaintEvt: TraceEvent, firstMeaningfulPaintEvt: TraceEvent}}
*/
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.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 = 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);

// 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, though we allow some timestamp tolerance
const firstMeaningfulPaint = frameEvents.find(e =>
e.name === 'firstMeaningfulPaint' && e.ts >= (firstFCP.ts - TraceOfTab.fmpToleranceMs));

// 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);

return {
processEvents,
startedInPageEvt: startedInPageEvt,
navigationStartEvt: navigationStart,
firstContentfulPaintEvt: firstFCP,
firstMeaningfulPaintEvt: firstMeaningfulPaint
};
}
}

module.exports = TraceOfTab;
Loading

0 comments on commit 7a3dbbd

Please sign in to comment.