core(tracehouse): allow nested trace events without an end

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

@@ -39,7 +39,7 @@ const {taskGroups, taskNameToGroup} = require('./task-groups.js');
  * @prop {TaskGroup} group
  */
 
-/** @typedef {{timers: Map<string, TaskNode>}} PriorTaskData */
+/** @typedef {{timers: Map<string, TaskNode>, traceEndTs: number}} PriorTaskData */
 
 class MainThreadTasks {
   /**
@@ -248,17 +248,25 @@ class MainThreadTasks {
           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.
+          //    If it's ending at traceEndTs, it means we were missing the end event. We'll truncate it to 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 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.
+            // 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.
             //    - 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.nextTask = nextTask;
+            error.currentTask = currentTask;
+            throw error;
           }
         }
 
@@ -421,7 +429,7 @@ class MainThreadTasks {
    */
   static getMainThreadTasks(mainThreadEvents, traceEndTs) {
     const timers = new Map();
-    const priorTaskData = {timers};
+    const priorTaskData = {timers, traceEndTs};
     const tasks = MainThreadTasks._createTasksFromEvents(
       mainThreadEvents,
       priorTaskData,

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

@@ -468,25 +468,74 @@ describe('Main Thread Tasks', () => {
     ]);
   });
 
+  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,
+      },
+      {
+        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,
+      },
+    ]);
+  });
+
   const invalidEventSets = [
     [
       // TaskA overlaps with TaskB, X first
       {ph: 'X', name: 'TaskA', pid, tid, ts: baseTs, dur: 100e3, args},
       {ph: 'B', name: 'TaskB', pid, tid, ts: baseTs + 5e3, args},
       {ph: 'E', name: 'TaskB', pid, tid, ts: baseTs + 115e3, args},
+      {ph: 'I', name: 'MarkerToPushOutTraceEnd', pid, tid, ts: baseTs + 200e3, args},
     ],
     [
       // TaskA overlaps with TaskB, B first
       {ph: 'B', name: 'TaskA', pid, tid, ts: baseTs, args},
       {ph: 'X', name: 'TaskB', pid, tid, ts: baseTs + 5e3, dur: 100e3, args},
       {ph: 'E', name: 'TaskA', pid, tid, ts: baseTs + 90e3, args},
+      {ph: 'I', name: 'MarkerToPushOutTraceEnd', pid, tid, ts: baseTs + 200e3, args},
     ],
     [
       // TaskA overlaps with TaskB, both B/E
       {ph: 'B', name: 'TaskA', pid, tid, ts: baseTs, args},
       {ph: 'B', name: 'TaskB', pid, tid, ts: baseTs + 5e3, args},
       {ph: 'E', name: 'TaskA', pid, tid, ts: baseTs + 90e3, args},
       {ph: 'E', name: 'TaskB', pid, tid, ts: baseTs + 95e3, args},
+      {ph: 'I', name: 'MarkerToPushOutTraceEnd', pid, tid, ts: baseTs + 200e3, args},
     ],
     [
       // TaskA is missing a B event
@@ -498,12 +547,7 @@ describe('Main Thread Tasks', () => {
       // TaskB is missing a B event after an X
       {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},
+      {ph: 'I', name: 'MarkerToPushOutTraceEnd', pid, tid, ts: baseTs + 200e3, args},
     ],
   ];