Skip to content

Commit

Permalink
core(tracehouse): allow child to start <1ms before parent
Browse files Browse the repository at this point in the history
  • Loading branch information
@patrickhulce
patrickhulce committed Oct 4, 2019
1 parent 84158fb commit b6ab7fe
Show file tree
Hide file tree
Showing 2 changed files with 149 additions and 3 deletions.
36 changes: 33 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 @@ -221,7 +221,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 @@ -249,16 +249,42 @@ class MainThreadTasks {
// 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 ending at traceEndTs, it means we were missing the end event. We'll truncate it to the parent.
// If the parent started less than 1ms before the child, we'll let it slide by swapping the two, and increasing the duration of the parent.
// Otherwise, throw an error.
if (timeDelta < 1000) {
currentTask.endTime = nextTask.endTime;
currentTask.duration += timeDelta;
} else if (nextTask.endTime === priorTaskData.traceEndTs) {
nextTask.endTime = currentTask.endTime;
nextTask.duration = nextTask.endTime - nextTask.startTime;
} else if (
nextTask.startTime - currentTask.startTime < 1000 &&
!currentTask.children.length
) {
// We need to swap currentTask/nextTask and update the timing to make sense.
const actualParentTask = nextTask;
const actualChildTask = currentTask;
const actualGrandparentTask = currentTask.parent;
if (actualGrandparentTask) {
if (actualGrandparentTask.children[actualGrandparentTask.children.length - 1] !== 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');
}

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

actualParentTask.parent = actualGrandparentTask;
actualParentTask.startTime = actualChildTask.startTime;
actualParentTask.duration = actualParentTask.endTime - actualParentTask.startTime;
currentTask = actualParentTask;
nextTask = actualChildTask;
} else {
// If we fell 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 @@ -301,6 +327,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 @@ -337,7 +364,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
116 changes: 116 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 @@ -422,6 +422,51 @@ describe('Main Thread Tasks', () => {
]);
});

it('should handle nested tasks of the same name', () => {
/*
An artistic rendering of the below trace:
████████████████TaskA██████████████████
███████████TaskA████████████
*/
const traceEvents = [
...boilerplateTrace,
{ph: 'B', name: 'TaskA', pid, tid, ts: baseTs, args},
{ph: 'B', name: 'TaskA', pid, tid, ts: baseTs + 25e3, args},
{ph: 'E', name: 'TaskA', pid, tid, ts: baseTs + 75e3, args},
{ph: 'E', name: 'TaskA', 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 === 'TaskA' && event.ts === baseTs),
startTime: 0,
endTime: 100,
duration: 100,
selfTime: 50,
group: taskGroups.other,
},
{
parent: tasks[0],
attributableURLs: [],

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

it('should handle child events that extend <1ms beyond parent event', () => {
/*
An artistic rendering of the below trace:
Expand Down Expand Up @@ -514,6 +559,68 @@ 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},
{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, 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,
},
{
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,
},
{
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,
},
]);
});

const invalidEventSets = [
[
// TaskA overlaps with TaskB, X first
Expand Down Expand Up @@ -549,6 +656,15 @@ describe('Main Thread Tasks', () => {
{ph: 'E', name: 'TaskB', pid, tid, ts: baseTs + 10e3, args},
{ph: 'I', name: 'MarkerToPushOutTraceEnd', pid, tid, ts: baseTs + 200e3, 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 b6ab7fe

Please sign in to comment.