From 1da5fa7597286f2dada37714dee7c935b54b4abf Mon Sep 17 00:00:00 2001 From: Patrick Hulce Date: Mon, 7 Oct 2019 15:35:36 -0500 Subject: [PATCH] core(tracehouse): allow nested trace events without an end (#9785) --- .../lib/tracehouse/main-thread-tasks.js | 29 ++++++-- .../lib/tracehouse/main-thread-tasks-test.js | 66 +++++++++++++++++-- 2 files changed, 83 insertions(+), 12 deletions(-) diff --git a/lighthouse-core/lib/tracehouse/main-thread-tasks.js b/lighthouse-core/lib/tracehouse/main-thread-tasks.js index 78ce49637cd8..653ac3930caf 100644 --- a/lighthouse-core/lib/tracehouse/main-thread-tasks.js +++ b/lighthouse-core/lib/tracehouse/main-thread-tasks.js @@ -31,6 +31,7 @@ const {taskGroups, taskNameToGroup} = require('./task-groups.js'); * @prop {LH.TraceEvent} event * @prop {TaskNode[]} children * @prop {TaskNode|undefined} parent + * @prop {boolean} unbounded Indicates that the task had an endTime that was inferred rather than specified in the trace. i.e. in the source trace this task was unbounded. * @prop {number} startTime * @prop {number} endTime * @prop {number} duration @@ -64,6 +65,7 @@ class MainThreadTasks { duration: endTime - startTime, // These properties will be filled in later + unbounded: false, parent: undefined, children: [], attributableURLs: [], @@ -181,10 +183,12 @@ class MainThreadTasks { /** @type {Pick} */ let taskEndEvent; + let unbounded = false; if (matchedEventIndex === -1) { // If we couldn't find an end event, we'll assume it's the end of the trace. // If this creates invalid parent/child relationships it will be caught in the next step. taskEndEvent = {ph: 'E', ts: traceEndTs}; + unbounded = true; } else if (matchedEventIndex === taskEndEventsReverseQueue.length - 1) { // Use .pop() in the common case where the immediately next event is needed. // It's ~25x faster, https://jsperf.com/pop-vs-splice. @@ -193,7 +197,9 @@ class MainThreadTasks { taskEndEvent = taskEndEventsReverseQueue.splice(matchedEventIndex, 1)[0]; } - tasks.push(MainThreadTasks._createNewTaskNode(taskStartEvent, taskEndEvent)); + const task = MainThreadTasks._createNewTaskNode(taskStartEvent, taskEndEvent); + task.unbounded = unbounded; + tasks.push(task); } if (taskEndEventsReverseQueue.length) { @@ -247,18 +253,29 @@ class MainThreadTasks { if (nextTask.endTime > currentTask.endTime) { const timeDelta = nextTask.endTime - currentTask.endTime; // The child task is taking longer than the parent task, which should be impossible. - // If it's less than 1ms, we'll let it slide by increasing the duration of the parent. - // If it's more, throw an error. + // In reality these situations happen, so we allow for some flexibility in trace event times. if (timeDelta < 1000) { + // It's less than 1ms, we'll let it slide by increasing the duration of the parent. currentTask.endTime = nextTask.endTime; currentTask.duration += timeDelta; + } else if (nextTask.unbounded) { + // It's ending at traceEndTs, it means we were missing the end event. We'll truncate it to the parent. + nextTask.endTime = currentTask.endTime; + nextTask.duration = nextTask.endTime - nextTask.startTime; } else { - // If we fell into this error, it's usually because of one of three reasons. - // - We were missing an E event for a child task and we assumed the child ended at the end of the trace. + // None of our workarounds matched. It's time to throw an error. + // When we fall into this error, it's usually because of one of two reasons. // - There was slop in the opposite direction (child started 1ms before parent) and the child was assumed to be parent instead. // - The child timestamp ended more than 1ms after tha parent. // These have more complicated fixes, so handling separately https://github.com/GoogleChrome/lighthouse/pull/9491#discussion_r327331204. - throw new Error('Fatal trace logic error - child cannot end after parent'); + /** @type {any} */ + const error = new Error('Fatal trace logic error - child cannot end after parent'); + error.timeDelta = timeDelta; + error.nextTaskEvent = nextTask.event; + error.nextTaskEndTime = nextTask.endTime; + error.currentTaskEvent = currentTask.event; + error.currentTaskEndTime = currentTask.endTime; + throw error; } } diff --git a/lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js b/lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js index a4a28283c83d..ad8bd8b5fa31 100644 --- a/lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js +++ b/lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js @@ -99,6 +99,7 @@ describe('Main Thread Tasks', () => { duration: 100, selfTime: 50, group: taskGroups.other, + unbounded: false, }); expect(taskB).toEqual({ @@ -112,6 +113,7 @@ describe('Main Thread Tasks', () => { duration: 50, selfTime: 20, group: taskGroups.other, + unbounded: false, }); }); @@ -232,6 +234,7 @@ describe('Main Thread Tasks', () => { duration: 110, selfTime: 5, group: taskGroups.other, + unbounded: true, }); expect(taskB).toEqual({ @@ -245,6 +248,7 @@ describe('Main Thread Tasks', () => { duration: 105, selfTime: 95, group: taskGroups.other, + unbounded: true, }); }); @@ -362,6 +366,7 @@ describe('Main Thread Tasks', () => { duration: 100, selfTime: 50, group: taskGroups.other, + unbounded: false, }, { parent: taskA, @@ -374,6 +379,7 @@ describe('Main Thread Tasks', () => { duration: 50, selfTime: 50, group: taskGroups.other, + unbounded: false, }, ]); }); @@ -406,6 +412,7 @@ describe('Main Thread Tasks', () => { duration: 100, selfTime: 100, group: taskGroups.other, + unbounded: false, }, { parent: undefined, @@ -418,6 +425,7 @@ describe('Main Thread Tasks', () => { duration: 0, selfTime: 0, group: taskGroups.other, + unbounded: false, }, ]); }); @@ -452,6 +460,7 @@ describe('Main Thread Tasks', () => { duration: 100, selfTime: 25, group: taskGroups.other, + unbounded: false, }, { parent: taskA, @@ -464,10 +473,61 @@ describe('Main Thread Tasks', () => { duration: 75, selfTime: 75, group: taskGroups.other, + unbounded: false, }, ]); }); + it('should handle child events that extend >1ms beyond parent event because missing E', () => { + /* + An artistic rendering of the below trace: + ████████████████TaskA██████████████████ + █████████TaskB██████████████████ + */ + const traceEvents = [ + ...boilerplateTrace, + {ph: 'B', name: 'TaskA', pid, tid, ts: baseTs, args}, + {ph: 'B', name: 'TaskB', pid, tid, ts: baseTs + 25e3, args}, + {ph: 'E', name: 'TaskA', pid, tid, ts: baseTs + 100e3, args}, + {ph: 'I', name: 'MarkerToPushOutTraceEnd', pid, tid, ts: baseTs + 110e3, args}, + ]; + + traceEvents.forEach(evt => Object.assign(evt, {cat: 'devtools.timeline'})); + + const tasks = run({traceEvents}); + const [taskA, taskB] = tasks; + expect(tasks).toEqual([ + { + parent: undefined, + attributableURLs: [], + + children: [taskB], + event: traceEvents.find(event => event.name === 'TaskA'), + startTime: 0, + endTime: 100, + duration: 100, + selfTime: 25, + group: taskGroups.other, + unbounded: false, + }, + { + parent: taskA, + attributableURLs: [], + + children: [], + event: traceEvents.find(event => event.name === 'TaskB' && event.ph === 'B'), + startTime: 25, + endTime: 100, + duration: 75, + selfTime: 75, + group: taskGroups.other, + unbounded: true, + }, + ]); + }); + + // Invalid sets of events. + // All of these should have `traceEnd` pushed out to avoid falling into one of our mitigation scenarios. const invalidEventSets = [ [ // TaskA overlaps with TaskB, X first @@ -499,12 +559,6 @@ describe('Main Thread Tasks', () => { {ph: 'X', name: 'TaskA', pid, tid, ts: baseTs, dur: 100e3, args}, {ph: 'E', name: 'TaskB', pid, tid, ts: baseTs + 10e3, args}, ], - [ - {ph: 'I', name: 'MarkerToPushOutTraceEnd', pid, tid, ts: baseTs + 110e3, args}, - // TaskB is missing an E event within an X - {ph: 'X', name: 'TaskA', pid, tid, ts: baseTs, dur: 100e3, args}, - {ph: 'B', name: 'TaskB', pid, tid, ts: baseTs + 10e3, args}, - ], ]; for (const invalidEvents of invalidEventSets) {