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.

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(trace-processor): refactor processEvents and frameEvents #14287

Merged
merged 46 commits into from
Jan 26, 2023
Merged
Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
46 commits
Select commit Hold shift + click to select a range
e489701
wip
paulirish Aug 9, 2022
42ded03
rendererids
paulirish Aug 9, 2022
b6c6296
trying things
paulirish Aug 10, 2022
36de69b
log shit
paulirish Aug 10, 2022
e6448e4
Merge branch 'processEventLog' into processEventsfix
paulirish Aug 10, 2022
7b8a6c1
i dig it..
paulirish Aug 10, 2022
189d568
processEvents good. frame and frameTree events now still broken
paulirish Aug 10, 2022
33da7cc
all event collections now including everything they should
paulirish Aug 10, 2022
751dafd
drop duplicate test name
paulirish Aug 10, 2022
5a0e31b
starting to remove framecommitted requirement
paulirish Aug 10, 2022
e283d76
test: reformat trace fixtures
paulirish Aug 10, 2022
669806e
update lcpAllFrames expectations.
paulirish Aug 11, 2022
e04b242
finishing up my frame investigation
paulirish Aug 11, 2022
e741b82
drop a bunch of noise from my branch
paulirish Aug 11, 2022
ea88628
tests are happy
paulirish Aug 11, 2022
3d7f84c
types
paulirish Aug 11, 2022
cdaf1b1
fix frame matching in responsiveness / work-during-interaction
paulirish Aug 11, 2022
7e4deda
cleanup
paulirish Aug 11, 2022
226f4bc
Revert "test: reformat trace fixtures"
paulirish Aug 11, 2022
74261f7
cleanup
paulirish Aug 11, 2022
fb8699a
Merge remote-tracking branch 'origin/main' into processEventsfix
paulirish Dec 2, 2022
1dabd2d
add comment about EventTiming / FallbackTiming
paulirish Dec 2, 2022
bfea1c1
delete minify-trace as its unreliable
paulirish Dec 2, 2022
6b91487
some feedback from bckenny
paulirish Dec 2, 2022
7a6f743
renames. mainFrameIds => mainFrameInfo
paulirish Dec 2, 2022
6ddd040
fix no-FrameCommittedInBrowser case test
paulirish Dec 2, 2022
017ca53
add test for a pid-change trace. manually whittled down trace by drop…
paulirish Dec 2, 2022
c326c42
samplejson
paulirish Dec 2, 2022
a930350
Merge remote-tracking branch 'origin/main' into processEventsfix
paulirish Dec 3, 2022
4704811
add warning about fallback case
paulirish Jan 10, 2023
5192b76
Merge remote-tracking branch 'origin/main' into processEventsfix
paulirish Jan 10, 2023
8ea59db
minor
paulirish Jan 10, 2023
2c2f784
node id test. mostly comments. only fix is the frameID
paulirish Jan 10, 2023
6b3ac4f
toEqual -> toMatchObj
paulirish Jan 10, 2023
e1b56f5
revert all changes to computed/responsiveness
paulirish Jan 13, 2023
c01d309
apply connor's every() readability improvement. and add extra comments
paulirish Jan 13, 2023
d9e5118
samplejson - old trace, no more work-during-interaction results
paulirish Jan 13, 2023
b94a356
address nits form adam
paulirish Jan 13, 2023
b7d0579
Merge remote-tracking branch 'origin/main' into processEventsfix
paulirish Jan 13, 2023
80d3fc9
typo
paulirish Jan 13, 2023
a5c6ff6
Merge remote-tracking branch 'origin/main' into processEventsfix
paulirish Jan 25, 2023
6b5d706
cleanup w array.includes()
paulirish Jan 25, 2023
6cbf6cc
add metadata thread_name to all fixture traces, so we can loudly fail
paulirish Jan 25, 2023
4dee193
Merge remote-tracking branch 'origin/main' into processEventsfix
paulirish Jan 25, 2023
917380e
lint
paulirish Jan 25, 2023
81a92b6
Merge remote-tracking branch 'origin/main' into processEventsfix
paulirish Jan 25, 2023
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
27 changes: 9 additions & 18 deletions core/computed/metrics/responsiveness.js
Original file line number Diff line number Diff line change
Expand Up @@ -10,11 +10,11 @@
* user input in the provided trace).
*/

/** @typedef {LH.Trace.CompleteEvent & {name: 'Responsiveness.Renderer.UserInteraction', args: {frame?: string, data: {interactionType: 'drag'|'keyboard'|'tapOrClick', maxDuration: number, frame?: string}}}} ResponsivenessEvent */
/** @typedef {LH.Trace.CompleteEvent & {name: 'Responsiveness.Renderer.UserInteraction', args: {frame: string, data: {interactionType: 'drag'|'keyboard'|'tapOrClick', maxDuration: number}}}} ResponsivenessEvent */
/** @typedef {'keydown'|'keypress'|'keyup'|'mousedown'|'mouseup'|'pointerdown'|'pointerup'|'click'} EventTimingType */
/**
* @typedef EventTimingData
* @property {string=} frame
* @property {string} frame
* @property {number} timeStamp The time of user interaction (in ms from navStart).
* @property {number} processingStart The start of interaction handling (in ms from navStart).
* @property {number} processingEnd The end of interaction handling (in ms from navStart).
Expand All @@ -23,7 +23,7 @@
* @property {number} nodeId
* @property {number} interactionId
*/
/** @typedef {LH.Trace.AsyncEvent & {name: 'EventTiming', args: {data: EventTimingData, frame?: string}}} EventTimingEvent */
/** @typedef {LH.Trace.AsyncEvent & {name: 'EventTiming', args: {data: EventTimingData}}} EventTimingEvent */
/**
* A fallback EventTiming placeholder, used if updated EventTiming events are not available.
* TODO: Remove once 103.0.5052.0 is sufficiently released.
Expand Down Expand Up @@ -87,14 +87,11 @@ class Responsiveness {
return evt.name === 'EventTiming' && evt.ph !== 'e';
});

// If trace is from < m103, the timestamps cannot be trusted
// If trace is from < m103, the timestamps cannot be trusted, so we craft a fallback
// <m103 traces (bad) had a args.frame
// m103+ traces (good) have a args.data.frame (https://crrev.com/c/3632661)
// TODO(compat): remove FallbackTiming handling when we don't care about <m103
if (
candidates.length &&
// !some == none. If none of the candidates have a frame, bail.
!candidates.some(candidate => candidate.args.frame || candidate.args.data?.frame)
) {
// Full EventTiming data added in https://crrev.com/c/3632661. Shipped in m103
if (candidates.length && candidates.every(candidate => !candidate.args.data?.frame)) {
return {
name: 'FallbackTiming',
duration: responsivenessEvent.args.data.maxDuration,
Expand All @@ -104,16 +101,10 @@ class Responsiveness {
const {maxDuration, interactionType} = responsivenessEvent.args.data;
let bestMatchEvent;
let minDurationDiff = Number.POSITIVE_INFINITY;

/** @param {LH.TraceEvent} e */
function residesInSameFrame(e) {
return e.args?.data?.frame === responsivenessEvent.args.frame ||
e.args.frame === responsivenessEvent.args.frame;
}

for (const candidate of candidates) {
// Must be from same frame.
if (!residesInSameFrame(candidate)) continue;
if (candidate.args.data.frame !== responsivenessEvent.args.frame) continue;

// TODO(bckenny): must be in same navigation as well.

const {type, duration} = candidate.args.data;
Expand Down
22 changes: 10 additions & 12 deletions core/lib/tracehouse/trace-processor.js
Original file line number Diff line number Diff line change
Expand Up @@ -482,7 +482,7 @@ class TraceProcessor {
}

/**
* If there were multiple cross-origin navigations in the trace, there'll be more than one pid returned
* If there were a any cross-origin navigations, there'll be more than one pid returned
paulirish marked this conversation as resolved.
Show resolved Hide resolved
* @param {{startingPid: number, frameId: string}} mainFrameInfo
* @param {LH.TraceEvent[]} keyEvents
* @return {Map<number, number>} Map where keys are process IDs and their values are thread IDs
Expand Down Expand Up @@ -634,6 +634,9 @@ class TraceProcessor {
while (parentFrames.has(cur)) {
cur = /** @type {string} */ (parentFrames.get(cur));
}
if (cur === undefined) {
throw new Error('Unexpected undefined frameId');
}
frameIdToRootFrameId.set(frame.id, cur);
}

Expand Down Expand Up @@ -661,12 +664,12 @@ class TraceProcessor {

// Find the inspected frame
const mainFrameInfo = this.findMainFrameIds(keyEvents);
const rendererPidTids = this.findMainFramePidTids(mainFrameInfo, keyEvents);
const rendererPidToTid = this.findMainFramePidTids(mainFrameInfo, keyEvents);

// Subset all trace events to just our tab's process (incl threads other than main)
// stable-sort events to keep them correctly nested.
const processEvents = TraceProcessor
.filteredTraceSort(trace.traceEvents, e => rendererPidTids.has(e.pid));
.filteredTraceSort(trace.traceEvents, e => rendererPidToTid.has(e.pid));

// TODO(paulirish): filter down frames (and subsequent actions) to the primary process tree & frame tree

Expand Down Expand Up @@ -709,13 +712,8 @@ class TraceProcessor {
const frameIdToRootFrameId = this.resolveRootFrames(frames);

const inspectedTreeFrameIds = [...frameIdToRootFrameId.entries()]
.filter(([childFrameId, rootFrameId]) => rootFrameId === mainFrameInfo.frameId) // eslint-disable-line no-unused-vars
.map(([child, root]) => child); // eslint-disable-line no-unused-vars

// @ts-expect-error frameIdToRootFrameId's values were casted to string. Runtime check here to confirm.
if (inspectedTreeFrameIds.includes(undefined)) {
throw new Error('Unexpected undefined in frameIdToRootFrameId');
}
.filter(([, rootFrameId]) => rootFrameId === mainFrameInfo.frameId)
.map(([child]) => child);

// Filter to just events matching the main frame ID, just to make sure.
/** @param {LH.TraceEvent} e */
Expand Down Expand Up @@ -753,7 +751,7 @@ class TraceProcessor {
timeOriginDeterminationMethod
);

const mainThreadEvents = processEvents.filter(e => e.tid === rendererPidTids.get(e.pid));
const mainThreadEvents = processEvents.filter(e => e.tid === rendererPidToTid.get(e.pid));

// Ensure our traceEnd reflects all page activity.
const traceEnd = this.computeTraceEnd(trace.traceEvents, timeOriginEvt);
Expand All @@ -777,7 +775,7 @@ class TraceProcessor {
traceEnd: traceEnd.timestamp,
},
_keyEvents: keyEvents,
_rendererPidTids: rendererPidTids,
_rendererPidToTid: rendererPidToTid,
};
}

Expand Down
169 changes: 9 additions & 160 deletions core/test/fixtures/fraggle-rock/reports/sample-flow-result.json
Original file line number Diff line number Diff line change
Expand Up @@ -7561,7 +7561,7 @@
"description": "Interaction to Next Paint measures page responsiveness, how long it takes the page to visibly respond to user input. [Learn more about the Interaction to Next Paint metric](https://web.dev/inp/).",
"score": 1,
"scoreDisplayMode": "numeric",
"numericValue": 64,
"numericValue": 60,
"numericUnit": "millisecond",
"displayValue": "60 ms"
},
Expand Down Expand Up @@ -9105,151 +9105,9 @@
"id": "work-during-interaction",
"title": "Minimizes work during key interaction",
"description": "This is the thread-blocking work occurring during the Interaction to Next Paint measurement. [Learn more about the Interaction to Next Paint metric](https://web.dev/inp/).",
"score": 1,
"scoreDisplayMode": "numeric",
"displayValue": "60 ms spent on event 'keypress'",
"details": {
"type": "list",
"items": [
{
"type": "table",
"headings": [
{
"key": "phase",
"valueType": "text",
"subItemsHeading": {
"key": "url",
"valueType": "url"
},
"label": "Phase"
},
{
"key": "total",
"valueType": "ms",
"subItemsHeading": {
"key": "total",
"granularity": 1,
"valueType": "ms"
},
"granularity": 1,
"label": "Total time"
},
{
"key": null,
"valueType": "ms",
"subItemsHeading": {
"key": "scripting",
"granularity": 1,
"valueType": "ms"
},
"label": "Script evaluation"
},
{
"key": null,
"valueType": "ms",
"subItemsHeading": {
"key": "layout",
"granularity": 1,
"valueType": "ms"
},
"label": "Style & Layout"
},
{
"key": null,
"valueType": "ms",
"subItemsHeading": {
"key": "render",
"granularity": 1,
"valueType": "ms"
},
"label": "Rendering"
}
],
"items": [
{
"phase": "Input delay",
"total": 14,
"subItems": {
"type": "subitems",
"items": [
{
"url": "https://www.mikescerealshack.co/_next/static/chunks/framework.9d524150d48315f49e80.js",
"total": 11.665999986231327,
"scripting": 9.986999996006489,
"layout": 0,
"render": 0
},
{
"url": "https://www.mikescerealshack.co/",
"total": 1.2910000085830688,
"scripting": 0,
"layout": 1.2370000034570694,
"render": 0
}
]
}
},
{
"phase": "Processing time",
"total": 43,
"subItems": {
"type": "subitems",
"items": [
{
"url": "https://www.mikescerealshack.co/_next/static/chunks/framework.9d524150d48315f49e80.js",
"total": 37.968000024557114,
"scripting": 35.80400001257658,
"layout": 0,
"render": 0
},
{
"url": "https://www.mikescerealshack.co/",
"total": 4.112999990582466,
"scripting": 0.5260000005364418,
"layout": 1.3629999905824661,
"render": 0.3139999955892563
}
]
}
},
{
"phase": "Presentation delay",
"total": 7,
"subItems": {
"type": "subitems",
"items": [
{
"url": "https://www.mikescerealshack.co/_next/static/chunks/framework.9d524150d48315f49e80.js",
"total": 5.60700000077486,
"scripting": 5.240000002086163,
"layout": 0,
"render": 0
}
]
}
}
]
},
{
"type": "debugdata",
"interactionType": "keypress",
"phases": {
"inputDelay": {
"startTs": 49219856985,
"endTs": 49219870985
},
"processingTime": {
"startTs": 49219870985,
"endTs": 49219913985
},
"presentationDelay": {
"startTs": 49219913985,
"endTs": 49219920985
}
}
}
]
}
"score": null,
"scoreDisplayMode": "error",
"errorMessage": "This version of Chrome is too old to support 'detailed EventTiming trace events'. Use a newer version to see full results."
}
},
"configSettings": {
Expand Down Expand Up @@ -10204,7 +10062,7 @@
},
{
"values": {
"timeInMs": 64
"timeInMs": 60
},
"path": "audits[experimental-interaction-to-next-paint].displayValue"
},
Expand Down Expand Up @@ -10618,24 +10476,15 @@
"core/audits/work-during-interaction.js | description": [
"audits[work-during-interaction].description"
],
"core/audits/work-during-interaction.js | displayValue": [
"core/lib/lh-error.js | oldChromeDoesNotSupportFeature": [
{
"values": {
"timeInMs": 64,
"interactionType": "keypress"
"errorCode": "UNSUPPORTED_OLD_CHROME",
"featureName": "detailed EventTiming trace events"
},
"path": "audits[work-during-interaction].displayValue"
"path": "audits[work-during-interaction].errorMessage"
}
],
"core/audits/work-during-interaction.js | inputDelay": [
"audits[work-during-interaction].details.items[0].items[0].phase"
],
"core/audits/work-during-interaction.js | processingTime": [
"audits[work-during-interaction].details.items[0].items[1].phase"
],
"core/audits/work-during-interaction.js | presentationDelay": [
"audits[work-during-interaction].details.items[0].items[2].phase"
],
"core/config/default-config.js | performanceCategoryTitle": [
"categories.performance.title"
],
Expand Down
2 changes: 1 addition & 1 deletion core/test/lib/tracehouse/trace-processor-test.js
Original file line number Diff line number Diff line change
Expand Up @@ -942,7 +942,7 @@ Object {

const mainFramePids = new Set();
mainFramePids.add(processed.mainFrameInfo.startingPid);
[...processed._rendererPidTids.keys()].forEach(pid => mainFramePids.add(pid));
[...processed._rendererPidToTid.keys()].forEach(pid => mainFramePids.add(pid));

return {processEventsPct, frameEventsPct, mainFramePids};
}
Expand Down
2 changes: 1 addition & 1 deletion types/artifacts.d.ts
Original file line number Diff line number Diff line change
Expand Up @@ -727,7 +727,7 @@ declare module Artifacts {
/** All received trace events subsetted to important categories. */
_keyEvents: Array<TraceEvent>;
/** Map where keys are process IDs and their values are thread IDs */
_rendererPidTids: Map<number, number>;
_rendererPidToTid: Map<number, number>;
}

interface ProcessedNavigation {
Expand Down