Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

core(tracehouse): expose navigationStart only as timeOrigin #11034

Merged
merged 7 commits into from
Jul 20, 2020
Merged

core(tracehouse): expose navigationStart only as timeOrigin #11034

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
a523fb0
core(tracehouse): expose navigationStart only as timeOrigin
patrickhulce Feb 12, 2020
763b19e
fix tests
patrickhulce Jun 29, 2020
011e481
fix asset saver test now that bug is gone
patrickhulce Jun 29, 2020
cb53e0e
more navStart renames
patrickhulce Jun 29, 2020
38e92da
Merge branch 'master' into time_origin_refactor
patrickhulce Jul 15, 2020
0755733
revert speed index changes
patrickhulce Jul 17, 2020
ae6cf1f
feedback
patrickhulce Jul 18, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 4 additions & 4 deletions docs/architecture.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -64,13 +64,13 @@ Trace-of-tab identifies trace events for key moments (navigation start, first me
processEvents: [/* all trace events in the main process */],
mainThreadEvents: [/* all trace events on the main thread */],
timings: {
navigationStart: 0,
firstPaint: 150, // firstPaint time in ms after nav start
timeOrigin: 0, // timeOrigin is always 0 ms
firstPaint: 150, // firstPaint time in ms after time origin
/* other key moments */
traceEnd: 16420, // traceEnd time in ms after nav start
traceEnd: 16420, // traceEnd time in ms after time origin
},
timestamps: {
navigationStart: 623000000, // navigationStart timestamp in microseconds
timeOrigin: 623000000, // timeOrigin timestamp in microseconds, marks the start of the navigation of interest
firstPaint: 623150000, // firstPaint timestamp in microseconds
/* other key moments */
traceEnd: 639420000, // traceEnd timestamp in microseconds
Expand Down
2 changes: 1 addition & 1 deletion docs/recipes/custom-audit/readme.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,7 @@ on terminology and architecture.

## What this example does

This example shows how to write a custom Lighthouse audit for a hypothetical search page. The page is considered fully initialized when the main search box (the page's "hero element") is ready to be used. When this happens, the page uses `performance.now()` to find the time since navigation start and saves the value in a global variable called `window.myLoadMetrics.searchableTime`.
This example shows how to write a custom Lighthouse audit for a hypothetical search page. The page is considered fully initialized when the main search box (the page's "hero element") is ready to be used. When this happens, the page uses `performance.now()` to mark the time it took to become ready and saves the value in a global variable called `window.myLoadMetrics.searchableTime`.

## The Audit, Gatherer, and Config

Expand Down
2 changes: 1 addition & 1 deletion docs/recipes/custom-audit/searchable-audit.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,7 @@ class LoadAudit extends Audit {
id: 'searchable-audit',
title: 'Search box initialized and ready',
failureTitle: 'Search box slow to initialize',
description: 'Used to measure time from navigationStart to when the search' +
description: 'Used to measure time to when the search' +
patrickhulce marked this conversation as resolved.
Show resolved Hide resolved
' box is initialized and ready to search.',

// The name of the custom gatherer class that provides input to this audit.
Expand Down
4 changes: 2 additions & 2 deletions lighthouse-core/audits/final-screenshot.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,7 @@ class FinalScreenshot extends Audit {
const trace = artifacts.traces[Audit.DEFAULT_PASS];
const traceOfTab = await TraceOfTab.request(trace, context);
const screenshots = await Screenshots.request(trace, context);
const {navigationStart} = traceOfTab.timestamps;
const {timeOrigin} = traceOfTab.timestamps;
const finalScreenshot = screenshots[screenshots.length - 1];

if (!finalScreenshot) {
Expand All @@ -44,7 +44,7 @@ class FinalScreenshot extends Audit {
score: 1,
details: {
type: 'screenshot',
timing: Math.round((finalScreenshot.timestamp - navigationStart) / 1000),
timing: Math.round((finalScreenshot.timestamp - timeOrigin) / 1000),
timestamp: finalScreenshot.timestamp,
data: finalScreenshot.datauri,
},
Expand Down
4 changes: 2 additions & 2 deletions lighthouse-core/computed/metrics/first-cpu-idle.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -180,7 +180,7 @@ class FirstCPUIdle extends ComputedMetric {
*/
static async computeObservedMetric(data) {
const {traceOfTab} = data;
const navStart = traceOfTab.timestamps.navigationStart;
const timeOrigin = traceOfTab.timestamps.timeOrigin;
const FMP = traceOfTab.timings.firstMeaningfulPaint;
const DCL = traceOfTab.timings.domContentLoaded;
const traceEnd = traceOfTab.timings.traceEnd;
Expand All @@ -201,7 +201,7 @@ class FirstCPUIdle extends ComputedMetric {

return Promise.resolve({
timing: valueInMs,
timestamp: valueInMs * 1000 + navStart,
timestamp: valueInMs * 1000 + timeOrigin,
});
}
}
Expand Down
14 changes: 7 additions & 7 deletions lighthouse-core/computed/metrics/interactive.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -44,11 +44,11 @@ class Interactive extends ComputedMetric {
/**
* Finds all time periods where there are no long tasks.
* @param {Array<TimePeriod>} longTasks
* @param {{timestamps: {navigationStart: number, traceEnd: number}}} traceOfTab
* @param {{timestamps: {timeOrigin: number, traceEnd: number}}} traceOfTab
* @return {Array<TimePeriod>}
*/
static _findCPUQuietPeriods(longTasks, traceOfTab) {
const navStartTsInMs = traceOfTab.timestamps.navigationStart / 1000;
const timeOriginTsInMs = traceOfTab.timestamps.timeOrigin / 1000;
const traceEndTsInMs = traceOfTab.timestamps.traceEnd / 1000;
if (longTasks.length === 0) {
return [{start: 0, end: traceEndTsInMs}];
Expand All @@ -60,19 +60,19 @@ class Interactive extends ComputedMetric {
if (index === 0) {
quietPeriods.push({
start: 0,
end: task.start + navStartTsInMs,
end: task.start + timeOriginTsInMs,
});
}

if (index === longTasks.length - 1) {
quietPeriods.push({
start: task.end + navStartTsInMs,
start: task.end + timeOriginTsInMs,
end: traceEndTsInMs,
});
} else {
quietPeriods.push({
start: task.end + navStartTsInMs,
end: longTasks[index + 1].start + navStartTsInMs,
start: task.end + timeOriginTsInMs,
end: longTasks[index + 1].start + timeOriginTsInMs,
});
}
});
Expand Down Expand Up @@ -175,7 +175,7 @@ class Interactive extends ComputedMetric {
traceOfTab.timestamps.firstContentfulPaint / 1000,
traceOfTab.timestamps.domContentLoaded / 1000
) * 1000;
const timing = (timestamp - traceOfTab.timestamps.navigationStart) / 1000;
const timing = (timestamp - traceOfTab.timestamps.timeOrigin) / 1000;
return Promise.resolve({timing, timestamp});
}
}
Expand Down
8 changes: 6 additions & 2 deletions lighthouse-core/computed/metrics/timing-summary.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -78,8 +78,12 @@ class TimingSummary {
cumulativeLayoutShift: cumulativeLayoutShiftValue,

// Include all timestamps of interest from trace of tab
observedNavigationStart: traceOfTab.timings.navigationStart,
observedNavigationStartTs: traceOfTab.timestamps.navigationStart,
observedTimeOrigin: traceOfTab.timings.timeOrigin,
observedTimeOriginTs: traceOfTab.timestamps.timeOrigin,
// For now, navigationStart is always timeOrigin.
// These properties might be undefined in a future major version, but preserve them for now.
observedNavigationStart: traceOfTab.timings.timeOrigin,
observedNavigationStartTs: traceOfTab.timestamps.timeOrigin,
patrickhulce marked this conversation as resolved.
Show resolved Hide resolved
observedFirstPaint: traceOfTab.timings.firstPaint,
observedFirstPaintTs: traceOfTab.timestamps.firstPaint,
observedFirstContentfulPaint: traceOfTab.timings.firstContentfulPaint,
Expand Down
6 changes: 3 additions & 3 deletions lighthouse-core/computed/speedline.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,11 +23,11 @@ class Speedline {
// Use a shallow copy of traceEvents so speedline can sort as it pleases.
// See https://github.com/GoogleChrome/lighthouse/issues/2333
const traceEvents = trace.traceEvents.slice();
// Force use of nav start as reference point for speedline
// Force use of timeOrigin as reference point for speedline
// See https://github.com/GoogleChrome/lighthouse/issues/2095
const navStart = traceOfTab.timestamps.navigationStart;
const timeOrigin = traceOfTab.timestamps.timeOrigin;
patrickhulce marked this conversation as resolved.
Show resolved Hide resolved
return speedline(traceEvents, {
timeOrigin: navStart,
timeOrigin,
fastMode: true,
include: 'speedIndex',
});
Expand Down
6 changes: 3 additions & 3 deletions lighthouse-core/computed/user-timings.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -67,11 +67,11 @@ class UserTimings {
}
});

// baseline the timestamps against navStart, and translate to milliseconds
// baseline the timestamps against the timeOrigin, and translate to milliseconds
userTimings.forEach(ut => {
ut.startTime = (ut.startTime - traceOfTab.navigationStartEvt.ts) / 1000;
ut.startTime = (ut.startTime - traceOfTab.timeOriginEvt.ts) / 1000;
if (!ut.isMark) {
ut.endTime = (ut.endTime - traceOfTab.navigationStartEvt.ts) / 1000;
ut.endTime = (ut.endTime - traceOfTab.timeOriginEvt.ts) / 1000;
ut.duration = ut.duration / 1000;
}
});
Expand Down
41 changes: 21 additions & 20 deletions lighthouse-core/lib/tracehouse/trace-processor.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -302,8 +302,8 @@ class TraceProcessor {
* selected percentiles within a window of the main thread.
* @see https://docs.google.com/document/d/1b9slyaB9yho91YTOkAQfpCdULFkZM9LqsipcX3t7He8/preview
* @param {Array<ToplevelEvent>} events
* @param {number} startTime Start time (in ms relative to navstart) of range of interest.
* @param {number} endTime End time (in ms relative to navstart) of range of interest.
* @param {number} startTime Start time (in ms relative to timeOrigin) of range of interest.
* @param {number} endTime End time (in ms relative to timeOrigin) of range of interest.
* @param {!Array<number>=} percentiles Optional array of percentiles to compute. Defaults to [0.5, 0.75, 0.9, 0.99, 1].
* @return {!Array<{percentile: number, time: number}>}
*/
Expand All @@ -324,8 +324,8 @@ class TraceProcessor {
/**
* Provides durations in ms of all main thread top-level events
* @param {Array<ToplevelEvent>} topLevelEvents
* @param {number} startTime Optional start time (in ms relative to navstart) of range of interest. Defaults to navstart.
* @param {number} endTime Optional end time (in ms relative to navstart) of range of interest. Defaults to trace end.
* @param {number} startTime Optional start time (in ms relative to timeOrigin) of range of interest. Defaults to 0.
* @param {number} endTime Optional end time (in ms relative to timeOrigin) of range of interest. Defaults to trace end.
* @return {{durations: Array<number>, clippedLength: number}}
*/
static getMainThreadTopLevelEventDurations(topLevelEvents, startTime = 0, endTime = Infinity) {
Expand Down Expand Up @@ -366,8 +366,8 @@ class TraceProcessor {
* Provides the top level events on the main thread with timestamps in ms relative to navigation
* start.
* @param {LH.Artifacts.TraceOfTab} tabTrace
* @param {number=} startTime Optional start time (in ms relative to navstart) of range of interest. Defaults to navstart.
* @param {number=} endTime Optional end time (in ms relative to navstart) of range of interest. Defaults to trace end.
* @param {number=} startTime Optional start time (in ms relative to timeOrigin) of range of interest. Defaults to 0.
* @param {number=} endTime Optional end time (in ms relative to timeOrigin) of range of interest. Defaults to trace end.
* @return {Array<ToplevelEvent>}
*/
static getMainThreadTopLevelEvents(tabTrace, startTime = 0, endTime = Infinity) {
Expand All @@ -376,8 +376,8 @@ class TraceProcessor {
for (const event of tabTrace.mainThreadEvents) {
if (!this.isScheduleableTask(event) || !event.dur) continue;

const start = (event.ts - tabTrace.navigationStartEvt.ts) / 1000;
const end = (event.ts + event.dur - tabTrace.navigationStartEvt.ts) / 1000;
const start = (event.ts - tabTrace.timeOriginEvt.ts) / 1000;
const end = (event.ts + event.dur - tabTrace.timeOriginEvt.ts) / 1000;
if (start > endTime || end < startTime) continue;

topLevelEvents.push({
Expand Down Expand Up @@ -494,18 +494,19 @@ class TraceProcessor {
// 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;

// Find our first paint of this frame
const firstPaint = frameEvents.find(e => e.name === 'firstPaint' && e.ts > navigationStart.ts);
const firstPaint = frameEvents.find(e => e.name === 'firstPaint' && e.ts > timeOriginEvt.ts);

// FCP will follow at/after the FP. Used in so many places we require it.
const firstContentfulPaint = frameEvents.find(
e => e.name === 'firstContentfulPaint' && e.ts > navigationStart.ts
e => e.name === 'firstContentfulPaint' && e.ts > timeOriginEvt.ts
);

// fMP will follow at/after the FP
let firstMeaningfulPaint = frameEvents.find(
e => e.name === 'firstMeaningfulPaint' && e.ts > navigationStart.ts
e => e.name === 'firstMeaningfulPaint' && e.ts > timeOriginEvt.ts
);
let fmpFellBack = false;

Expand Down Expand Up @@ -533,8 +534,8 @@ class TraceProcessor {
// Iterate the events backwards.
for (let i = frameEvents.length - 1; i >= 0; i--) {
const e = frameEvents[i];
// If the event's timestamp is before the navigation start, stop.
if (e.ts <= navigationStart.ts) break;
// If the event's timestamp is before the time origin, stop.
if (e.ts <= timeOriginEvt.ts) break;
// If the last lcp event in the trace is 'Invalidate', there is inconclusive data to determine LCP.
if (e.name === 'largestContentfulPaint::Invalidate') {
lcpInvalidated = true;
Expand All @@ -547,9 +548,9 @@ class TraceProcessor {
break;
}

const load = frameEvents.find(e => e.name === 'loadEventEnd' && e.ts > navigationStart.ts);
const load = frameEvents.find(e => e.name === 'loadEventEnd' && e.ts > timeOriginEvt.ts);
const domContentLoaded = frameEvents.find(
e => e.name === 'domContentLoadedEventEnd' && e.ts > navigationStart.ts
e => e.name === 'domContentLoadedEventEnd' && e.ts > timeOriginEvt.ts
);

// subset all trace events to just our tab's process (incl threads other than main)
Expand All @@ -560,7 +561,7 @@ class TraceProcessor {
const mainThreadEvents = processEvents
.filter(e => e.tid === mainFrameIds.tid);

// traceEnd must exist since at least navigationStart event was verified as existing.
// 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;
});
Expand All @@ -570,7 +571,7 @@ class TraceProcessor {
const getTimestamp = (event) => event && event.ts;
/** @type {TraceTimesWithoutFCP} */
const timestamps = {
navigationStart: navigationStart.ts,
timeOrigin: timeOriginEvt.ts,
firstPaint: getTimestamp(firstPaint),
firstContentfulPaint: getTimestamp(firstContentfulPaint),
firstMeaningfulPaint: getTimestamp(firstMeaningfulPaint),
Expand All @@ -581,12 +582,12 @@ class TraceProcessor {
};

/** @param {number} ts */
const getTiming = (ts) => (ts - navigationStart.ts) / 1000;
const getTiming = (ts) => (ts - timeOriginEvt.ts) / 1000;
/** @param {number=} ts */
const maybeGetTiming = (ts) => ts === undefined ? undefined : getTiming(ts);
/** @type {TraceTimesWithoutFCP} */
const timings = {
navigationStart: 0,
timeOrigin: 0,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

imagining future uses of this with non-navStart-timeOrigins, seems like we're still going to want a navStart entry? Though maybe it should be more specific, like lastNavigationStart or something.

One thing this would help with is answering the question "what's the timeOrigin being used here?". At the very least, you'd be able to compare it against navStart and see that they're equal.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

imagining future uses of this with non-navStart-timeOrigins, seems like we're still going to want a navStart entry?

Maybe. But there are certainly cases where there will be 0 navStart entries to return, and I'd rather reintroduce navStart into this chain only where absolutely necessary (similar to above explanation).

Though maybe it should be more specific, like lastNavigationStart or something.

That makes sense to me though I'm not sure anything at all would use it right now. Are you OK holding off on this one until we have the first case where something needs it to better understand the requirements?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe. But there are certainly cases where there will be 0 navStart entries to return, and I'd rather reintroduce navStart into this chain only where absolutely necessary (similar to above explanation).

It doesn't make sense to me to try to be general in solution but not report on navigationStart (if found in the trace), but I guess we'll wait for when it's needed.

One thing this PR makes harder to address is still the "what's the timeOrigin being used here?" question, though.

firstPaint: maybeGetTiming(timestamps.firstPaint),
firstContentfulPaint: maybeGetTiming(timestamps.firstContentfulPaint),
firstMeaningfulPaint: maybeGetTiming(timestamps.firstMeaningfulPaint),
Expand All @@ -610,7 +611,7 @@ class TraceProcessor {
mainThreadEvents,
mainFrameIds,
frames,
navigationStartEvt: navigationStart,
timeOriginEvt: timeOriginEvt,
firstPaintEvt: firstPaint,
firstContentfulPaintEvt: firstContentfulPaint,
firstMeaningfulPaintEvt: firstMeaningfulPaint,
Expand Down
Loading