Skip to content

Commit

Permalink
core(tracehouse): allow nested trace events without an end (#9785)
Browse files Browse the repository at this point in the history
  • Loading branch information
@patrickhulce @paulirish
patrickhulce authored and paulirish committed Nov 6, 2019
1 parent 12def6f commit 8211a08
Show file tree
Hide file tree
Showing 2 changed files with 83 additions and 12 deletions.
29 changes: 23 additions & 6 deletions lighthouse-core/lib/tracehouse/main-thread-tasks.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -64,6 +65,7 @@ class MainThreadTasks {
duration: endTime - startTime,

// These properties will be filled in later
unbounded: false,
parent: undefined,
children: [],
attributableURLs: [],
Expand Down Expand Up @@ -181,10 +183,12 @@ class MainThreadTasks {

/** @type {Pick<LH.TraceEvent, 'ph'|'ts'>} */
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.
Expand All @@ -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) {
Expand Down Expand Up @@ -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;
}
}

Expand Down
66 changes: 60 additions & 6 deletions lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -99,6 +99,7 @@ describe('Main Thread Tasks', () => {
duration: 100,
selfTime: 50,
group: taskGroups.other,
unbounded: false,
});

expect(taskB).toEqual({
Expand All @@ -112,6 +113,7 @@ describe('Main Thread Tasks', () => {
duration: 50,
selfTime: 20,
group: taskGroups.other,
unbounded: false,
});
});

Expand Down Expand Up @@ -232,6 +234,7 @@ describe('Main Thread Tasks', () => {
duration: 110,
selfTime: 5,
group: taskGroups.other,
unbounded: true,
});

expect(taskB).toEqual({
Expand All @@ -245,6 +248,7 @@ describe('Main Thread Tasks', () => {
duration: 105,
selfTime: 95,
group: taskGroups.other,
unbounded: true,
});
});

Expand Down Expand Up @@ -362,6 +366,7 @@ describe('Main Thread Tasks', () => {
duration: 100,
selfTime: 50,
group: taskGroups.other,
unbounded: false,
},
{
parent: taskA,
Expand All @@ -374,6 +379,7 @@ describe('Main Thread Tasks', () => {
duration: 50,
selfTime: 50,
group: taskGroups.other,
unbounded: false,
},
]);
});
Expand Down Expand Up @@ -406,6 +412,7 @@ describe('Main Thread Tasks', () => {
duration: 100,
selfTime: 100,
group: taskGroups.other,
unbounded: false,
},
{
parent: undefined,
Expand All @@ -418,6 +425,7 @@ describe('Main Thread Tasks', () => {
duration: 0,
selfTime: 0,
group: taskGroups.other,
unbounded: false,
},
]);
});
Expand Down Expand Up @@ -452,6 +460,7 @@ describe('Main Thread Tasks', () => {
duration: 100,
selfTime: 25,
group: taskGroups.other,
unbounded: false,
},
{
parent: taskA,
Expand All @@ -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
Expand Down Expand Up @@ -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) {
Expand Down

0 comments on commit 8211a08

Please sign in to comment.