use a stable sort for trace events (#2415)

* use stable sort for trace events

* isolate speedline's trace sorting from LH

* add tests

lighthouse-core/gather/computed/speedline.js

@@ -21,10 +21,13 @@ class Speedline extends ComputedArtifact {
     // speedline() may throw without a promise, so we resolve immediately
     // to get in a promise chain.
     return computedArtifacts.requestTraceOfTab(trace).then(traceOfTab => {
+      // Use a shallow copy of traceEvents so speedline can sort as it pleases.
+      // See https://github.com/GoogleChrome/lighthouse/issues/2333
+      const traceEvents = trace.traceEvents.slice();
       // Force use of nav start as reference point for speedline
       // See https://github.com/GoogleChrome/lighthouse/issues/2095
       const navStart = traceOfTab.timestamps.navigationStart;
-      return speedline(trace.traceEvents, {
+      return speedline(traceEvents, {
         timeOrigin: navStart,
         fastMode: true,
       });

lighthouse-core/gather/computed/trace-of-tab.js

@@ -19,6 +19,11 @@
 const ComputedArtifact = require('./computed-artifact');
 const log = require('lighthouse-logger');
 
+// Bring in web-inspector for side effect of adding [].stableSort
+// See https://github.com/GoogleChrome/lighthouse/pull/2415
+// eslint-disable-next-line no-unused-vars
+const WebInspector = require('../../lib/web-inspector');
+
 class TraceOfTab extends ComputedArtifact {
   get name() {
     return 'TraceOfTab';
@@ -31,15 +36,16 @@ class TraceOfTab extends ComputedArtifact {
    * @return {!TraceOfTabArtifact}
   */
   compute_(trace) {
-    // Parse the trace for our key events and sort them by timestamp.
+    // Parse the trace for our key events and sort them by timestamp. Note: sort
+    // *must* be stable to keep events correctly nested.
     const keyEvents = trace.traceEvents
       .filter(e => {
         return e.cat.includes('blink.user_timing') ||
           e.cat.includes('loading') ||
           e.cat.includes('devtools.timeline') ||
           e.name === 'TracingStartedInPage';
       })
-      .sort((event0, event1) => event0.ts - event1.ts);
+      .stableSort((event0, event1) => event0.ts - event1.ts);
 
     // The first TracingStartedInPage in the trace is definitely our renderer thread of interest
     // Beware: the tracingStartedInPage event can appear slightly after a navigationStart
@@ -84,9 +90,10 @@ class TraceOfTab extends ComputedArtifact {
     );
 
     // 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 = trace.traceEvents
       .filter(e => e.pid === startedInPageEvt.pid)
-      .sort((event0, event1) => event0.ts - event1.ts);
+      .stableSort((event0, event1) => event0.ts - event1.ts);
 
     const mainThreadEvents = processEvents
       .filter(e => e.tid === startedInPageEvt.tid);

lighthouse-core/test/gather/computed/speedline-test.js

@@ -8,6 +8,7 @@
 /* eslint-env mocha */
 
 const assert = require('assert');
+const fs = require('fs');
 const pwaTrace = require('../../fixtures/traces/progressive-app.json');
 const threeFrameTrace = require('../../fixtures/traces/threeframes-blank_content_more.json');
 const Runner = require('../../../runner.js');
@@ -61,4 +62,20 @@ describe('Speedline gatherer', () => {
         return assert.equal(Math.floor(speedline.speedIndex), 561);
       });
   });
+
+  it('does not change order of events in traces', () => {
+    // Use fresh trace in case it has been altered by other require()s.
+    const pwaJson = fs.readFileSync(__dirname +
+        '/../../fixtures/traces/progressive-app.json', 'utf8');
+    const pwaTrace = JSON.parse(pwaJson);
+    return computedArtifacts.requestSpeedline({traceEvents: pwaTrace})
+      .then(_ => {
+        // assert.deepEqual has issue with diffing large array, so manually loop.
+        const freshTrace = JSON.parse(pwaJson);
+        assert.strictEqual(pwaTrace.length, freshTrace.length);
+        for (let i = 0; i < pwaTrace.length; i++) {
+          assert.deepStrictEqual(pwaTrace[i], freshTrace[i]);
+        }
+      });
+  });
 });

lighthouse-core/test/gather/computed/trace-of-tab-test.js

@@ -9,6 +9,7 @@ const TraceOfTab = require('../../../gather/computed/trace-of-tab');
 const traceOfTab = new TraceOfTab();
 
 const assert = require('assert');
+const fs = require('fs');
 const badNavStartTrace = require('../../fixtures/traces/bad-nav-start-ts.json');
 const lateTracingStartedTrace = require('../../fixtures/traces/tracingstarted-after-navstart.json');
 const preactTrace = require('../../fixtures/traces/preactjs.com_ts_of_undefined.json');
@@ -105,4 +106,34 @@ describe('Trace of Tab computed artifact:', () => {
     assert.equal(trace.firstContentfulPaintEvt, undefined, 'bad fcp');
     assert.equal(trace.firstMeaningfulPaintEvt, undefined, 'bad fmp');
   });
+
+  it('stably sorts events', () => {
+    const traceJson = fs.readFileSync(__dirname +
+        '/../../fixtures/traces/tracingstarted-after-navstart.json', 'utf8');
+    const trace = traceOfTab.compute_(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);
+    }
+
+    // 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;
+      }
+
+      // .filter overhead could be slow, but only a handful of tsGroups.
+      const sortedEvents = trace.processEvents.filter(e => e.ts === ts);
+      assert.deepStrictEqual(sortedEvents, tsGroup);
+    }
+  });
 });