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

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

@@ -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
@@ -64,6 +65,7 @@ class MainThreadTasks {
       duration: endTime - startTime,
 
       // These properties will be filled in later
+      unbounded: false,
       parent: undefined,
       children: [],
       attributableURLs: [],
@@ -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.
@@ -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) {
@@ -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;
           }
         }
 

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

@@ -99,6 +99,7 @@ describe('Main Thread Tasks', () => {
       duration: 100,
       selfTime: 50,
       group: taskGroups.other,
+      unbounded: false,
     });
 
     expect(taskB).toEqual({
@@ -112,6 +113,7 @@ describe('Main Thread Tasks', () => {
       duration: 50,
       selfTime: 20,
       group: taskGroups.other,
+      unbounded: false,
     });
   });
 
@@ -232,6 +234,7 @@ describe('Main Thread Tasks', () => {
       duration: 110,
       selfTime: 5,
       group: taskGroups.other,
+      unbounded: true,
     });
 
     expect(taskB).toEqual({
@@ -245,6 +248,7 @@ describe('Main Thread Tasks', () => {
       duration: 105,
       selfTime: 95,
       group: taskGroups.other,
+      unbounded: true,
     });
   });
 
@@ -362,6 +366,7 @@ describe('Main Thread Tasks', () => {
         duration: 100,
         selfTime: 50,
         group: taskGroups.other,
+        unbounded: false,
       },
       {
         parent: taskA,
@@ -374,6 +379,7 @@ describe('Main Thread Tasks', () => {
         duration: 50,
         selfTime: 50,
         group: taskGroups.other,
+        unbounded: false,
       },
     ]);
   });
@@ -406,6 +412,7 @@ describe('Main Thread Tasks', () => {
         duration: 100,
         selfTime: 100,
         group: taskGroups.other,
+        unbounded: false,
       },
       {
         parent: undefined,
@@ -418,6 +425,7 @@ describe('Main Thread Tasks', () => {
         duration: 0,
         selfTime: 0,
         group: taskGroups.other,
+        unbounded: false,
       },
     ]);
   });
@@ -452,6 +460,7 @@ describe('Main Thread Tasks', () => {
         duration: 100,
         selfTime: 25,
         group: taskGroups.other,
+        unbounded: false,
       },
       {
         parent: taskA,
@@ -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
@@ -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) {