core(tracehouse): allow child to start <1ms before parent

lighthouse-core/lib/tracehouse/main-thread-tasks.js

@@ -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.
@@ -262,10 +262,36 @@ 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 parent started less than 1ms before the child, we'll let it slide by swapping the two,
+            // and increasing the duration of the parent.
+            const parentTask = nextTask;
+            const childTask = currentTask;
+            const grandparentTask = currentTask.parent;
+            if (grandparentTask) {
+              if (grandparentTask.children[grandparentTask.children.length - 1] !== childTask) {
+                // 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(parentTask);
+            }
+
+            parentTask.parent = grandparentTask;
+            parentTask.startTime = childTask.startTime;
+            parentTask.duration = parentTask.endTime - parentTask.startTime;
+            currentTask = parentTask;
+            nextTask = childTask;
           } 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} */
@@ -310,6 +336,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
@@ -346,7 +373,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
+    );
   }
 
   /**

lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js

@@ -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:
@@ -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 = [
@@ -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) {