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

Jump to bottom

core(trace): use tracing-started event for frame tree info #13913

Merged
merged 3 commits into from
Apr 26, 2022
Merged

core(trace): use tracing-started event for frame tree info #13913

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
4920314
core(trace): use tracing-started event for frame tree info
brendankenny Apr 26, 2022
125a7e2
update sample flow report
brendankenny Apr 26, 2022
a51034f
update fallback comments and log message
brendankenny Apr 26, 2022
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
38 changes: 29 additions & 9 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 @@ -612,39 +612,59 @@ class TraceProcessor {
// Find the inspected frame
const mainFrameIds = this.findMainFrameIds(keyEvents);

const frames = keyEvents
/** @type {Map<string, {id: string, url: string, parent?: string}>} */
const framesById = new Map();
Copy link
Member

Choose a reason for hiding this comment

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

I think we can remove this warning now:

lighthouse/lighthouse-core/lib/tracehouse/trace-processor.js

Lines 645 to 647 in 6ba8dc8

log.warn(
'trace-of-tab',
'frameTreeEvents may be incomplete, make sure the trace has FrameCommittedInBrowser events'

Copy link
Member Author

Choose a reason for hiding this comment

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

I can update the message maybe? I feel like it's really just for the outdated tests now

Copy link
Member

Choose a reason for hiding this comment

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

I can update the message maybe?

SGTM


// Begin collection of frame tree information with TracingStartedInBrowser,
// which should be present even without navigations.
const tracingStartedFrames = keyEvents
.find(e => e.name === 'TracingStartedInBrowser')?.args?.data?.frames;
if (tracingStartedFrames) {
for (const frame of tracingStartedFrames) {
framesById.set(frame.frame, {
id: frame.frame,
url: frame.url,
parent: frame.parent,
});
}
}
Copy link
Collaborator

Choose a reason for hiding this comment

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

super nit: could reduce indentation if L621 did || [].

Copy link
Member Author

@brendankenny brendankenny Apr 26, 2022 •
edited
Loading

Choose a reason for hiding this comment

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

I had that originally but it was bordering on unreadable. The indent isn't ideal but it doesn't seem too bad to me


// Update known frames if FrameCommittedInBrowser events come in, typically
// with updated `url`, as well as pid, etc. Some traces (like timespans) may
// not have any committed frames.
Copy link
Member Author

Choose a reason for hiding this comment

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

somewhat debatable if we really need to "update" the known frames if there are FrameCommittedInBrowser events, because only the url changes if there are entries for a frame in both TracingStartedInBrowser and a FrameCommittedInBrowser event, and as far as I can tell we never use those urls anywhere :)

However, it seems good to do because it makes sense conceptually, not updating doesn't really make this code any simpler, this is like a few dozen events at most, so 🤷

keyEvents
.filter(/** @return {evt is FrameCommittedEvent} */ evt => {
return Boolean(
evt.name === 'FrameCommittedInBrowser' &&
evt.args.data?.frame &&
evt.args.data.url
);
})
.map(evt => {
return {
}).forEach(evt => {
framesById.set(evt.args.data.frame, {
id: evt.args.data.frame,
url: evt.args.data.url,
parent: evt.args.data.parent,
};
});
});
const frames = [...framesById.values()];
const frameIdToRootFrameId = this.resolveRootFrames(frames);

// Filter to just events matching the main frame ID, just to make sure.
const frameEvents = keyEvents.filter(e => e.args.frame === mainFrameIds.frameId);

// Filter to just events matching the main frame ID or any child frame IDs.
// In practice, there should always be FrameCommittedInBrowser events to define the frame tree.
// Unfortunately, many test traces do not include FrameCommittedInBrowser events due to minification.
// This ensures there is always a minimal frame tree and events so those tests don't fail.
let frameTreeEvents = [];
if (frameIdToRootFrameId.has(mainFrameIds.frameId)) {
frameTreeEvents = keyEvents.filter(e => {
return e.args.frame && frameIdToRootFrameId.get(e.args.frame) === mainFrameIds.frameId;
});
} else {
// In practice, there should always be TracingStartedInBrowser/FrameCommittedInBrowser events to
// define the frame tree. Unfortunately, many test traces do not that frame info due to minification.
// This ensures there is always a minimal frame tree and events so those tests don't fail.
log.warn(
'trace-of-tab',
'frameTreeEvents may be incomplete, make sure the trace has FrameCommittedInBrowser events'
'frameTreeEvents may be incomplete, make sure the trace has frame events'
);
frameIdToRootFrameId.set(mainFrameIds.frameId, mainFrameIds.frameId);
frameTreeEvents = frameEvents;
Expand Down
1 change: 0 additions & 1 deletion lighthouse-core/test/computed/metrics/cumulative-layout-shift-test.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -304,7 +304,6 @@ describe('Metrics: CLS', () => {
const cat = 'loading,rail,devtools.timeline';
trace.traceEvents.push(
/* eslint-disable max-len */
{name: 'FrameCommittedInBrowser', cat, args: {data: {frame: mainFrame, url: 'https://example.com'}}},
Copy link
Member Author

Choose a reason for hiding this comment

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

Noticed these extra test entries when comparing the before/after. They don't hurt anything with our current setup, but createTestTrace creates a mainframe FrameCommittedInBrowser event already, so these end up doubled up

{name: 'FrameCommittedInBrowser', cat, args: {data: {frame: childFrame, parent: mainFrame, url: 'https://frame.com'}}},
{name: 'FrameCommittedInBrowser', cat, args: {data: {frame: otherMainFrame, url: 'https://example.com'}}},
{name: 'LayoutShift', cat, args: {frame: mainFrame, data: {had_recent_input: false, score: 1, weighted_score_delta: 1, is_main_frame: true}}},
Expand Down
24 changes: 15 additions & 9 deletions lighthouse-core/test/fixtures/fraggle-rock/reports/sample-flow-result.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7850,7 +7850,7 @@
"description": "Consider reducing the time spent parsing, compiling, and executing JS. You may find delivering smaller JS payloads helps with this. [Learn more](https://web.dev/bootup-time/).",
"score": 1,
"scoreDisplayMode": "numeric",
"numericValue": 274.5320000000002,
"numericValue": 275.90400000000034,
Copy link
Member Author

Choose a reason for hiding this comment

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

@adamraine this looks right and the timespan wasn't looking cross frame for bootup time, but haven't verified yet. Hard to find where each step begins and ends in the big json files :)

Copy link
Member

Choose a reason for hiding this comment

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

Yeah trace processor was producing an empty list for frames in timespan

Copy link
Member

Choose a reason for hiding this comment

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

Hard to find where each step begins and ends in the big json files :)

I can open an issue for an assetSaver.saveFlowArtifacts that separates this stuff into separate files. Wouldn't hurt to have another 800,000+ line PR on my resume 😎

"numericUnit": "millisecond",
"displayValue": "0.3 s",
"details": {
Expand Down Expand Up @@ -7881,21 +7881,27 @@
}
],
"items": [
{
"url": "https://www.mikescerealshack.co/",
"total": 298.1560000000002,
"scripting": 115.99500000000005,
"scriptParseCompile": 0
},
{
"url": "https://www.mikescerealshack.co/_next/static/chunks/framework.9d524150d48315f49e80.js",
"total": 340.90100000000024,
"scripting": 254.67600000000022,
"total": 169.22000000000028,
"scripting": 150.88400000000027,
"scriptParseCompile": 0
},
{
"url": "Unattributable",
"total": 237.62699999999987,
"scripting": 19.855999999999998,
"total": 114.66900000000017,
"scripting": 9.024999999999997,
"scriptParseCompile": 0
}
],
"summary": {
"wastedMs": 274.5320000000002
"wastedMs": 275.90400000000034
}
}
},
Expand Down Expand Up @@ -8537,12 +8543,12 @@
],
"items": [
{
"url": "https://www.mikescerealshack.co/_next/static/chunks/framework.9d524150d48315f49e80.js",
"url": "https://www.mikescerealshack.co/",
Copy link
Collaborator

Choose a reason for hiding this comment

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

what audit is this second chunk?

Copy link
Member Author

Choose a reason for hiding this comment

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

long-tasks. Similar to bootup-time, it was getting an empty frames array here:

lighthouse/lighthouse-core/computed/main-thread-tasks.js

Line 19 in 90775ac

const {mainThreadEvents, frames, timestamps} = await ProcessedTrace.request(trace, context);

"duration": 75.734,
"startTime": 1765.511
},
{
"url": "https://www.mikescerealshack.co/_next/static/chunks/framework.9d524150d48315f49e80.js",
"url": "https://www.mikescerealshack.co/",
"duration": 55.073,
"startTime": 11.328
}
Expand Down Expand Up @@ -10099,7 +10105,7 @@
},
{
"values": {
"timeInMs": 274.5320000000002
"timeInMs": 275.90400000000034
},
"path": "audits[bootup-time].displayValue"
}
Expand Down
34 changes: 31 additions & 3 deletions lighthouse-core/test/lib/tracehouse/trace-processor-test.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -210,7 +210,6 @@ describe('TraceProcessor', () => {
const cat = 'loading,rail,devtools.timeline';
testTrace.traceEvents.push(
/* eslint-disable max-len */
{name: 'FrameCommittedInBrowser', cat, args: {data: {frame: mainFrame, url: 'https://example.com'}}},
{name: 'FrameCommittedInBrowser', cat, args: {data: {frame: childFrame, parent: mainFrame, url: 'https://frame.com'}}},
{name: 'FrameCommittedInBrowser', cat, args: {data: {frame: otherMainFrame, url: 'https://example.com'}}},
{name: 'Event1', cat, args: {frame: mainFrame}},
Expand Down Expand Up @@ -251,6 +250,37 @@ describe('TraceProcessor', () => {
'Event1',
]);
});

it('frameTreeEvents included even if no FrameCommittedInBrowser events', () => {
const testTrace = createTestTrace({timeOrigin: 0, traceEnd: 2000});
testTrace.traceEvents = testTrace.traceEvents
.filter(e => e.name !== 'FrameCommittedInBrowser');

const mainFrame = testTrace.traceEvents[0].args.frame;
const childFrame = 'CHILDFRAME';
const otherMainFrame = 'ANOTHERTAB';
const cat = 'loading,rail,devtools.timeline';

testTrace.traceEvents.find(e => e.name === 'TracingStartedInBrowser').args.data.frames.push(
{frame: childFrame, parent: mainFrame, url: 'https://frame.com'},
{frame: otherMainFrame, url: 'https://example.com'}
);

testTrace.traceEvents.push(
{name: 'Event1', cat, args: {frame: mainFrame}},
{name: 'Event2', cat, args: {frame: childFrame}},
{name: 'Event3', cat, args: {frame: otherMainFrame}}
);
const trace = TraceProcessor.processTrace(testTrace);
expect(trace.frameTreeEvents.map(e => e.name)).toEqual([
'navigationStart',
'domContentLoadedEventEnd',
'firstContentfulPaint',
'firstMeaningfulPaint',
'Event1',
'Event2',
]);
});
});

describe('getMainThreadTopLevelEvents', () => {
Expand Down Expand Up @@ -639,7 +669,6 @@ Object {

testTrace.traceEvents.push(
/* eslint-disable max-len */
{name: 'FrameCommittedInBrowser', cat, args: {data: {frame: mainFrame, url: 'https://example.com'}}, ts: 900, duration: 10},
{name: 'FrameCommittedInBrowser', cat, args: {data: {frame: childFrame, parent: mainFrame, url: 'https://frame.com'}}, ts: 910, duration: 10},
{name: 'firstContentfulPaint', cat, args: {frame: childFrame}, ts: 1000, duration: 10},
{name: 'firstContentfulPaint', cat, args: {frame: mainFrame}, ts: 1100, duration: 10}
Expand All @@ -658,7 +687,6 @@ Object {
const cat = 'loading,rail,devtools.timeline';
testTrace.traceEvents.push(
/* eslint-disable max-len */
{name: 'FrameCommittedInBrowser', cat, args: {data: {frame: mainFrame, url: 'https://example.com'}}, ts: 900, duration: 10},
{name: 'FrameCommittedInBrowser', cat, args: {data: {frame: childFrame, parent: mainFrame, url: 'https://frame.com'}}, ts: 910, duration: 10},
{name: 'largestContentfulPaint::Candidate', cat, args: {data: {size: 300}, frame: mainFrame}, ts: 1000, duration: 10},
{name: 'largestContentfulPaint::Candidate', cat, args: {data: {size: 100}, frame: childFrame}, ts: 1100, duration: 10},
Expand Down
1 change: 1 addition & 0 deletions types/artifacts.d.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -961,6 +961,7 @@ export interface TraceEvent {
documentLoaderURL?: string;
frames?: {
frame: string;
url: string;
parent?: string;
processId?: number;
}[];
Expand Down