Skip to content

Commit

Permalink
core(tracehouse): allow child to start <1ms before parent (#9786)
Browse files Browse the repository at this point in the history
  • Loading branch information
@patrickhulce
patrickhulce authored Oct 15, 2019
1 parent 2a3cc4c commit 85b8a92
Show file tree
Hide file tree
Showing 2 changed files with 163 additions and 3 deletions.
46 changes: 43 additions & 3 deletions lighthouse-core/lib/tracehouse/main-thread-tasks.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -227,7 +227,7 @@ class MainThreadTasks {
const timerInstallEventsReverseQueue = timerInstallEvents.slice().reverse();

for (let i = 0; i < sortedTasks.length; i++) {
const nextTask = sortedTasks[i];
let nextTask = sortedTasks[i];

// This inner loop updates what our `currentTask` is at `nextTask.startTime - ε`.
// While `nextTask` starts after our `currentTask`, close out the task, popup to the parent, and repeat.
Expand Down Expand Up @@ -262,10 +262,46 @@ class MainThreadTasks {
// 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 (
nextTask.startTime - currentTask.startTime < 1000 &&
!currentTask.children.length
) {
// The true parent started less than 1ms before the true child, so we're looking at the relationship backwards.
// We'll let it slide and fix the situation by swapping the two tasks into their correct positions
// and increasing the duration of the parent.

// Below is an artistic rendition of the heirarchy we are trying to create.
// ████████████currentTask.parent██████████████████
// █████████nextTask██████████████
// ███████currentTask███████
const actualParentTask = nextTask;
const actualChildTask = currentTask;

// We'll grab the grandparent task to see if we need to fix it.
// We'll reassign it to be the parent of `actualParentTask` in a bit.
const grandparentTask = currentTask.parent;
if (grandparentTask) {
const lastGrandparentChildIndex = grandparentTask.children.length - 1;
if (grandparentTask.children[lastGrandparentChildIndex] !== actualChildTask) {
// The child we need to swap should always be the most recently added child.
// But if not then there's a serious bug in this code, so double-check.
throw new Error('Fatal trace logic error - impossible children');
}

grandparentTask.children.pop();
grandparentTask.children.push(actualParentTask);
}

actualParentTask.parent = grandparentTask;
actualParentTask.startTime = actualChildTask.startTime;
actualParentTask.duration = actualParentTask.endTime - actualParentTask.startTime;
currentTask = actualParentTask;
nextTask = actualChildTask;
} else {
// 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.
// - There was slop in the opposite direction (child started 1ms before parent),
// the child was assumed to be parent instead, and another task already started.
// - 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.
/** @type {any} */
Expand Down Expand Up @@ -310,6 +346,7 @@ class MainThreadTasks {
* 2. Create tasks for each X/B event, throwing if a matching E event cannot be found for a given B.
* 3. Sort the tasks by ↑ startTime, ↓ duration.
* 4. Match each task to its parent, throwing if there is any invalid overlap between tasks.
* 5. Sort the tasks once more by ↑ startTime, ↓ duration in case they changed during relationship creation.
*
* @param {LH.TraceEvent[]} mainThreadEvents
* @param {PriorTaskData} priorTaskData
Expand Down Expand Up @@ -346,7 +383,10 @@ class MainThreadTasks {
// Phase 4 - Match each task to its parent.
MainThreadTasks._createTaskRelationships(sortedTasks, timerInstallEvents, priorTaskData);

return sortedTasks;
// Phase 5 - Sort once more in case the order changed after wiring up relationships.
return sortedTasks.sort(
(taskA, taskB) => taskA.startTime - taskB.startTime || taskB.duration - taskA.duration
);
}

/**
Expand Down
120 changes: 120 additions & 0 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 @@ -430,6 +430,53 @@ describe('Main Thread Tasks', () => {
]);
});

it('should handle nested tasks of the same name', () => {
/*
An artistic rendering of the below trace:
████████████████SameName██████████████████
███████████SameName████████████
*/
const traceEvents = [
...boilerplateTrace,
{ph: 'B', name: 'SameName', pid, tid, ts: baseTs, args},
{ph: 'B', name: 'SameName', pid, tid, ts: baseTs + 25e3, args},
{ph: 'E', name: 'SameName', pid, tid, ts: baseTs + 75e3, args},
{ph: 'E', name: 'SameName', pid, tid, ts: baseTs + 100e3, args},
];

traceEvents.forEach(evt => Object.assign(evt, {cat: 'devtools.timeline'}));

const tasks = run({traceEvents});
expect(tasks).toEqual([
{
parent: undefined,
attributableURLs: [],

children: [tasks[1]],
event: traceEvents.find(event => event.name === 'SameName' && event.ts === baseTs),
startTime: 0,
endTime: 100,
duration: 100,
selfTime: 50,
group: taskGroups.other,
unbounded: false,
},
{
parent: tasks[0],
attributableURLs: [],

children: [],
event: traceEvents.find(event => event.ts === baseTs + 25e3),
startTime: 25,
endTime: 75,
duration: 50,
selfTime: 50,
group: taskGroups.other,
unbounded: false,
},
]);
});

it('should handle child events that extend <1ms beyond parent event', () => {
/*
An artistic rendering of the below trace:
Expand Down Expand Up @@ -526,6 +573,70 @@ describe('Main Thread Tasks', () => {
]);
});

it('should handle child events that start <1ms before parent event', () => {
/*
An artistic rendering of the below trace:
████████████████TaskA██████████████████
█████████TaskB██████████████
████████TaskC█████████
*/
const traceEvents = [
...boilerplateTrace,
{ph: 'B', name: 'TaskA', pid, tid, ts: baseTs, args},
{ph: 'B', name: 'TaskB', pid, tid, ts: baseTs + 25e3 + 50, args}, // this is invalid, but happens in practice
{ph: 'B', name: 'TaskC', pid, tid, ts: baseTs + 25e3, args},
{ph: 'E', name: 'TaskC', pid, tid, ts: baseTs + 60e3, args},
{ph: 'E', name: 'TaskB', pid, tid, ts: baseTs + 90e3, args},
{ph: 'E', name: 'TaskA', pid, tid, ts: baseTs + 100e3, args},
];

traceEvents.forEach(evt => Object.assign(evt, {cat: 'devtools.timeline'}));

const tasks = run({traceEvents});
const [taskA, taskB, taskC] = tasks;
expect(tasks).toEqual([
{
parent: undefined,
attributableURLs: [],

children: [taskB],
event: traceEvents.find(event => event.name === 'TaskA'),
startTime: 0,
endTime: 100,
duration: 100,
selfTime: 35,
group: taskGroups.other,
unbounded: false,
},
{
parent: taskA,
attributableURLs: [],

children: [taskC],
event: traceEvents.find(event => event.name === 'TaskB' && event.ph === 'B'),
startTime: 25,
endTime: 90,
duration: 65,
selfTime: 30,
group: taskGroups.other,
unbounded: false,
},
{
parent: taskB,
attributableURLs: [],

children: [],
event: traceEvents.find(event => event.name === 'TaskC' && event.ph === 'B'),
startTime: 25,
endTime: 60,
duration: 35,
selfTime: 35,
group: taskGroups.other,
unbounded: false,
},
]);
});

// Invalid sets of events.
// All of these should have `traceEnd` pushed out to avoid falling into one of our mitigation scenarios.
const invalidEventSets = [
Expand Down Expand Up @@ -559,6 +670,15 @@ 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},
],
[
// TaskA is starting .5ms too late, but TaskB already has a child
{ph: 'B', name: 'TaskA', pid, tid, ts: baseTs + 500, args},
{ph: 'B', name: 'TaskB', pid, tid, ts: baseTs, args},
{ph: 'X', name: 'TaskC', pid, tid, ts: baseTs + 50, dur: 100, args},
{ph: 'E', name: 'TaskB', pid, tid, ts: baseTs + 100e3, args},
{ph: 'E', name: 'TaskA', pid, tid, ts: baseTs + 115e3, args},
{ph: 'I', name: 'MarkerToPushOutTraceEnd', pid, tid, ts: baseTs + 200e3, args},
],
];

for (const invalidEvents of invalidEventSets) {
Expand Down

0 comments on commit 85b8a92

Please sign in to comment.