core(tracehouse): sort trace events by nesting order

lighthouse-core/lib/tracehouse/trace-processor.js

@@ -62,10 +62,110 @@ class TraceProcessor {
   }
 
   /**
+   * This method sorts a group of trace events that have the same timestamp. We want to...
+   *
+   * 1. Put E events first, we finish off our existing events before we start new ones.
+   * 2. Order B/X events by their duration, we want parents to start before child events.
+   * 3. If we don't have any of this to go on, just use the position in the original array (stable sort).
+   *
+   * @param {number[]} tsGroupIndices
+   * @param {number[]} timestampSortedIndices
+   * @param {number} indexOfTsGroupIndicesStart
+   * @param {LH.TraceEvent[]} traceEvents
+   * @return {number[]}
+   */
+  static _sortTimestampEventGroup(
+      tsGroupIndices,
+      timestampSortedIndices,
+      indexOfTsGroupIndicesStart,
+      traceEvents
+  ) {
+    /*
+     * We have two different sets of indices going on here.
+
+     *    1. There's the index for an element of `traceEvents`, referred to here as an `ArrayIndex`.
+     *       `timestampSortedIndices` is an array of `ArrayIndex` elements.
+     *    2. There's the index for an element of `timestampSortedIndices`, referred to here as a `TsIndex`.
+     *       A `TsIndex` is therefore an index to an element which is itself an index.
+     *
+     * These two helper functions help resolve this layer of indirection.
+     * Our final return value is an array of `ArrayIndex` in their final sort order.
+     */
+    /** @param {number} i */
+    const lookupArrayIndexByTsIndex = i => timestampSortedIndices[i];
+    /** @param {number} i */
+    const lookupEventByTsIndex = i => traceEvents[lookupArrayIndexByTsIndex(i)];
+
+    /** @type {Array<number>} */
+    const eEventIndices = [];
+    /** @type {Array<number>} */
+    const bxEventIndices = [];
+    /** @type {Array<number>} */
+    const otherEventIndices = [];
+
+    for (const tsIndex of tsGroupIndices) {
+      // See comment above for the distinction between `tsIndex` and `arrayIndex`.
+      const arrayIndex = lookupArrayIndexByTsIndex(tsIndex);
+      const event = lookupEventByTsIndex(tsIndex);
+      if (event.ph === 'E') eEventIndices.push(arrayIndex);
+      else if (event.ph === 'X' || event.ph === 'B') bxEventIndices.push(arrayIndex);
+      else otherEventIndices.push(arrayIndex);
+    }
+
+    /** @type {Map<number, number>} */
+    const effectiveDuration = new Map();
+    for (const index of bxEventIndices) {
+      const event = traceEvents[index];
+      if (event.ph === 'X') {
+        effectiveDuration.set(index, event.dur);
+      } else {
+        // Find the next available 'E' event *after* the current group of events that matches our name, pid, and tid.
+        let duration = Number.MAX_SAFE_INTEGER;
+        // To find the next "available" 'E' event, we need to account for nested events of the same name.
+        let additionalNestedEventsWithSameName = 0;
+        const startIndex = indexOfTsGroupIndicesStart + tsGroupIndices.length;
+        for (let j = startIndex; j < timestampSortedIndices.length; j++) {
+          const potentialMatchingEvent = lookupEventByTsIndex(j);
+          const eventMatches = potentialMatchingEvent.name === event.name &&
+            potentialMatchingEvent.pid === event.pid &&
+            potentialMatchingEvent.tid === event.tid;
+
+          // The event doesn't match, just skip it.
+          if (!eventMatches) continue;
+
+          if (potentialMatchingEvent.ph === 'E' && additionalNestedEventsWithSameName === 0) {
+            // It's the next available 'E' event for us, so set the duration and break the loop.
+            duration = potentialMatchingEvent.ts - event.ts;
+            break;
+          } else if (potentialMatchingEvent.ph === 'E') {
+            // It's an 'E' event but for a nested event. Decrement our counter and move on.
+            additionalNestedEventsWithSameName--;
+          } else if (potentialMatchingEvent.ph === 'B') {
+            // It's a nested 'B' event. Increment our counter and move on.
+            additionalNestedEventsWithSameName++;
+          }
+        }
+
+        effectiveDuration.set(index, duration);
+      }
+    }
+
+    bxEventIndices.sort((indexA, indexB) => ((effectiveDuration.get(indexB) || 0) -
+      (effectiveDuration.get(indexA) || 0) || (indexA - indexB)));
+
+    otherEventIndices.sort((indexA, indexB) => indexA - indexB);
+
+    return [...eEventIndices, ...bxEventIndices, ...otherEventIndices];
+  }
+
+  /**
+   * Sorts and filters trace events by timestamp and respecting the nesting structure inherent to
+   * parent/child event relationships.
+   *
    * @param {LH.TraceEvent[]} traceEvents
    * @param {(e: LH.TraceEvent) => boolean} filter
    */
-  static _filteredStableSort(traceEvents, filter) {
+  static filteredTraceSort(traceEvents, filter) {
     // create an array of the indices that we want to keep
     const indices = [];
     for (let srcIndex = 0; srcIndex < traceEvents.length; srcIndex++) {
@@ -74,11 +174,33 @@ class TraceProcessor {
       }
     }
 
-    // sort by ts, if there's no ts difference sort by index
-    indices.sort((indexA, indexB) => {
-      const result = traceEvents[indexA].ts - traceEvents[indexB].ts;
-      return result ? result : indexA - indexB;
-    });
+    // Sort by ascending timestamp first.
+    indices.sort((indexA, indexB) => traceEvents[indexA].ts - traceEvents[indexB].ts);
+
+    // Now we find groups with equal timestamps and order them by their nesting structure.
+    for (let i = 0; i < indices.length - 1; i++) {
+      const ts = traceEvents[indices[i]].ts;
+      const tsGroupIndices = [i];
+      for (let j = i + 1; j < indices.length; j++) {
+        if (traceEvents[indices[j]].ts !== ts) break;
+        tsGroupIndices.push(j);
+      }
+
+      // We didn't find any other events with the same timestamp, just keep going.
+      if (tsGroupIndices.length === 1) continue;
+
+      // Sort the group by other criteria and replace our index array with it.
+      const finalIndexOrder = TraceProcessor._sortTimestampEventGroup(
+        tsGroupIndices,
+        indices,
+        i,
+        traceEvents
+      );
+      indices.splice(i, finalIndexOrder.length, ...finalIndexOrder);
+      // We just sorted this set of identical timestamps, so skip over the rest of the group.
+      // -1 because we already have i++.
+      i += tsGroupIndices.length - 1;
+    }
 
     // create a new array using the target indices from previous sort step
     const sorted = [];
@@ -352,7 +474,7 @@ class TraceProcessor {
   static computeTraceOfTab(trace) {
     // Parse the trace for our key events and sort them by timestamp. Note: sort
     // *must* be stable to keep events correctly nested.
-    const keyEvents = this._filteredStableSort(trace.traceEvents, e => {
+    const keyEvents = this.filteredTraceSort(trace.traceEvents, e => {
       return e.cat.includes('blink.user_timing') ||
           e.cat.includes('loading') ||
           e.cat.includes('devtools.timeline') ||
@@ -406,7 +528,7 @@ class TraceProcessor {
     // subset all trace events to just our tab's process (incl threads other than main)
     // stable-sort events to keep them correctly nested.
     const processEvents = TraceProcessor
-      ._filteredStableSort(trace.traceEvents, e => e.pid === mainFrameIds.pid);
+      .filteredTraceSort(trace.traceEvents, e => e.pid === mainFrameIds.pid);
 
     const mainThreadEvents = processEvents
       .filter(e => e.tid === mainFrameIds.tid);

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

@@ -198,6 +198,76 @@ describe('Main Thread Tasks', () => {
     });
   });
 
+  it('should handle nested events *starting* at the same timestamp correctly', () => {
+    const traceEvents = [
+      ...boilerplateTrace,
+      {ph: 'B', name: 'TaskB', pid, tid, ts: baseTs, args},
+      {ph: 'B', name: 'TaskC', pid, tid, ts: baseTs, args},
+      {ph: 'X', name: 'TaskA', pid, tid, ts: baseTs, dur: 100e3, args},
+      {ph: 'E', name: 'TaskB', pid, tid, ts: baseTs + 50e3, args},
+      {ph: 'E', name: 'TaskC', pid, tid, ts: baseTs + 25e3, args},
+      {ph: 'X', name: 'TaskD', pid, tid, ts: baseTs + 100e3, dur: 100e3, args},
+    ];
+
+    traceEvents.forEach(evt => Object.assign(evt, {cat: 'devtools.timeline'}));
+
+    const tasks = run({traceEvents});
+    expect(tasks).toMatchObject([
+      {event: {name: 'TaskA'}, parent: undefined, startTime: 0, endTime: 100},
+      {event: {name: 'TaskB'}, parent: {event: {name: 'TaskA'}}, startTime: 0, endTime: 50},
+      {event: {name: 'TaskC'}, parent: {event: {name: 'TaskB'}}, startTime: 0, endTime: 25},
+      {event: {name: 'TaskD'}, parent: undefined, startTime: 100, endTime: 200},
+    ]);
+  });
+
+  it('should handle nested events *ending* at the same timestamp correctly', () => {
+    const traceEvents = [
+      ...boilerplateTrace,
+      {ph: 'B', name: 'TaskA', pid, tid, ts: baseTs, args},
+      {ph: 'X', name: 'TaskB', pid, tid, ts: baseTs + 50e3, dur: 50e3, args},
+      {ph: 'B', name: 'TaskC', pid, tid, ts: baseTs + 75e3, args},
+      {ph: 'X', name: 'TaskD', pid, tid, ts: baseTs + 100e3, dur: 100e3, args},
+      {ph: 'E', name: 'TaskA', pid, tid, ts: baseTs + 100e3, args},
+      {ph: 'E', name: 'TaskC', pid, tid, ts: baseTs + 100e3, args},
+    ];
+
+    traceEvents.forEach(evt => Object.assign(evt, {cat: 'devtools.timeline'}));
+
+    const tasks = run({traceEvents});
+    expect(tasks).toMatchObject([
+      {event: {name: 'TaskA'}, parent: undefined, startTime: 0, endTime: 100},
+      {event: {name: 'TaskB'}, parent: {event: {name: 'TaskA'}}, startTime: 50, endTime: 100},
+      {event: {name: 'TaskC'}, parent: {event: {name: 'TaskB'}}, startTime: 75, endTime: 100},
+      {event: {name: 'TaskD'}, parent: undefined, startTime: 100, endTime: 200},
+    ]);
+  });
+
+  it('should handle nested events of the same name', () => {
+    /*
+    An artistic rendering of the below trace:
+    █████████████████████████████TaskANested██████████████████████████████████████████████
+    ████████████████TaskB███████████████████
+               ████TaskANested██████
+    */
+    const traceEvents = [
+      ...boilerplateTrace,
+      {ph: 'B', name: 'TaskANested', pid, tid, ts: baseTs, args},
+      {ph: 'X', name: 'TaskB', pid, tid, ts: baseTs, dur: 50e3, args},
+      {ph: 'B', name: 'TaskANested', pid, tid, ts: baseTs + 25e3, args},
+      {ph: 'E', name: 'TaskANested', pid, tid, ts: baseTs + 45e3, args},
+      {ph: 'E', name: 'TaskANested', pid, tid, ts: baseTs + 100e3, args},
+    ];
+
+    traceEvents.forEach(evt => Object.assign(evt, {cat: 'devtools.timeline'}));
+
+    const tasks = run({traceEvents});
+    expect(tasks).toMatchObject([
+      {event: {name: 'TaskANested'}, parent: undefined, startTime: 0, endTime: 100},
+      {event: {name: 'TaskB'}, parent: {event: {name: 'TaskANested'}}, startTime: 0, endTime: 50},
+      {event: {name: 'TaskANested'}, parent: {event: {name: 'TaskB'}}, startTime: 25, endTime: 45},
+    ]);
+  });
+
   const invalidEventSets = [
     [
       // TaskA overlaps with TaskB, X first

lighthouse-core/test/lib/tracehouse/trace-processor-test.js

@@ -401,36 +401,125 @@ describe('TraceProcessor', () => {
       expect(trace.firstContentfulPaintEvt.ts).toEqual(2610265036367);
     });
 
-    it('stably sorts events', () => {
-      const traceJson = fs.readFileSync(__dirname +
-          '/../../fixtures/traces/tracingstarted-after-navstart.json', 'utf8');
-      const trace = TraceProcessor.computeTraceOfTab(JSON.parse(traceJson));
-      const mainPid = trace.mainThreadEvents[0].pid;
-
-      const freshProcessEvents = JSON.parse(traceJson).traceEvents
-          .filter(e => e.pid === mainPid);
-
-      // Group all events with the same timestamp in original trace order.
-      const tsMap = new Map();
-      for (const event of freshProcessEvents) {
-        const tsGroup = tsMap.get(event.ts) || [];
-        tsGroup.push(event);
-        tsMap.set(event.ts, tsGroup);
+    it('sorts events by increasing timestamp', () => {
+      const trace = JSON.parse(fs.readFileSync(__dirname +
+          '/../../fixtures/traces/tracingstarted-after-navstart.json', 'utf8'));
+      const shuffledEvents = trace.traceEvents.slice().sort(() => Math.random() * 2 - 1);
+      const traceOfTab = TraceProcessor.computeTraceOfTab({traceEvents: shuffledEvents});
+
+      let lastTs = -Infinity;
+      for (const event of traceOfTab.processEvents) {
+        if (!event.ts) continue;
+        expect(event.ts).toBeGreaterThanOrEqual(lastTs);
+        lastTs = event.ts;
       }
+    });
 
-      // Assert that groups of same-timestamped events are in the same order in
-      // processed events.
-      for (const [ts, tsGroup] of tsMap) {
-        if (tsGroup.length === 1) {
-          continue;
-        }
+    describe('#filteredTraceSort', () => {
+      it('sorts by ts', () => {
+        const events = [
+          {pid: 3, ts: 10},
+          {pid: 1, ts: 5},
+          {pid: 4, ts: 11},
+          {pid: 2, ts: 7},
+        ];
+
+        expect(TraceProcessor.filteredTraceSort(events, () => true)).toEqual([
+          {pid: 1, ts: 5},
+          {pid: 2, ts: 7},
+          {pid: 3, ts: 10},
+          {pid: 4, ts: 11},
+        ]);
+      });
 
-        // .filter overhead could be slow, but only a handful of tsGroups.
-        const sortedEvents = trace.processEvents.filter(e => e.ts === ts);
-        assert.deepStrictEqual(sortedEvents, tsGroup);
-      }
+      it('sorts within timestamp groups', () => {
+        const events = [
+          {pid: 3, ts: 10, dur: 0, ph: 'X'},
+          {pid: 2, ts: 5, dur: 0, ph: 'X'},
+          {pid: 4, ts: 11, dur: 5, ph: 'X'},
+          {pid: 1, ts: 5, dur: 10, ph: 'X'},
+          {pid: 5, ts: 11, dur: 3, ph: 'X'},
+        ];
+
+        expect(TraceProcessor.filteredTraceSort(events, () => true)).toEqual([
+          {pid: 1, ts: 5, dur: 10, ph: 'X'},
+          {pid: 2, ts: 5, dur: 0, ph: 'X'},
+          {pid: 3, ts: 10, dur: 0, ph: 'X'},
+          {pid: 4, ts: 11, dur: 5, ph: 'X'},
+          {pid: 5, ts: 11, dur: 3, ph: 'X'},
+        ]);
+      });
+
+      it('filters', () => {
+        const events = [
+          {pid: 3, ts: 10, dur: 0},
+          {pid: 2, ts: 5, dur: 0},
+          {pid: 4, ts: 11, dur: 5},
+          {pid: 1, ts: 5, dur: 10},
+          {pid: 5, ts: 11, dur: 3},
+        ];
+
+        // Just keep odd pids
+        expect(TraceProcessor.filteredTraceSort(events, evt => evt.pid % 2 === 1)).toEqual([
+          {pid: 1, ts: 5, dur: 10},
+          {pid: 3, ts: 10, dur: 0},
+          {pid: 5, ts: 11, dur: 3},
+        ]);
+      });
+
+      it('sorts timestamp groups with E events first', () => {
+        const events = [
+          {pid: 2, ts: 1, ph: 'B', name: 'UpdateLayer'},
+          {pid: 4, ts: 1, ph: 'B', name: 'CompositeLayers'},
+          {pid: 3, ts: 1, dur: 5, ph: 'X'},
+          {pid: 1, ts: 1, dur: 10, ph: 'X'},
+          {pid: 5, ts: 1, dur: 3, ph: 'X'},
+          {pid: 0, ts: 1, ph: 'E'},
+          {pid: 2, ts: 8, ph: 'E', name: 'UpdateLayer'},
+          {pid: 4, ts: 5, ph: 'E', name: 'CompositeLayers'},
+        ];
+
+        expect(TraceProcessor.filteredTraceSort(events, () => true)).toEqual([
+          {pid: 0, ts: 1, ph: 'E'},
+          {pid: 1, ts: 1, dur: 10, ph: 'X'},
+          {pid: 2, ts: 1, ph: 'B', name: 'UpdateLayer'},
+          {pid: 3, ts: 1, dur: 5, ph: 'X'},
+          {pid: 4, ts: 1, ph: 'B', name: 'CompositeLayers'},
+          {pid: 5, ts: 1, dur: 3, ph: 'X'},
+          {pid: 4, ts: 5, ph: 'E', name: 'CompositeLayers'},
+          {pid: 2, ts: 8, ph: 'E', name: 'UpdateLayer'},
+        ]);
+      });
+
+      it('sorts timestamp groups with unmatched B events', () => {
+        const events = [
+          {pid: 3, ts: 1, ph: 'B', name: 'CompositeLayers'},
+          {pid: 2, ts: 1, dur: 5, ph: 'X'},
+          {pid: 1, ts: 1, ph: 'B', name: 'UpdateLayer'},
+          {pid: 3, ts: 5, ph: 'E', name: 'CompositeLayers'},
+        ];
+
+        expect(TraceProcessor.filteredTraceSort(events, () => true)).toEqual([
+          {pid: 1, ts: 1, ph: 'B', name: 'UpdateLayer'},
+          {pid: 2, ts: 1, dur: 5, ph: 'X'},
+          {pid: 3, ts: 1, ph: 'B', name: 'CompositeLayers'},
+          {pid: 3, ts: 5, ph: 'E', name: 'CompositeLayers'},
+        ]);
+      });
+
+      it('sorts timestamp groups with stable sort when all else fails', () => {
+        const events = [
+          {pid: 3, ts: 1, ph: 'D', name: 'CompositeLayers'},
+          {pid: 2, ts: 1, dur: 5, ph: 'M'},
+          {pid: 1, ts: 1, ph: 'M', name: 'UpdateLayer'},
+          {pid: 3, ts: 5, ph: 'M', name: 'CompositeLayers'},
+        ];
+
+        expect(TraceProcessor.filteredTraceSort(events, () => true)).toEqual(events);
+      });
     });
 
+
     it('throws on traces missing a navigationStart', () => {
       expect(() => TraceProcessor.computeTraceOfTab(noNavStartTrace))
         .toThrowError('navigationStart');