Traces that are passed in through the config file are cleaned

Michael Gerakis · paulirish · commit 1c62db30b886 · 2016-07-28T15:37:10.000-04:00
Traces that are passed in through the config file are cleaned to handle
duplicate/missing TracingStartedInPage events.
diff --git a/lighthouse-core/audits/first-meaningful-paint.js b/lighthouse-core/audits/first-meaningful-paint.js
@@ -132,7 +132,12 @@ class FirstMeaningfulPaint extends Audit {
     score = Math.min(100, score);
     score = Math.max(0, score);
 
+    if (!data.navStart) {
+      throw new Error(FAILURE_MESSAGE);
+    }
+
     timings.navStart = data.navStart.ts / 1000;
+
     return {
       duration: `${firstMeaningfulPaint.toFixed(1)}`,
       score: Math.round(score),
@@ -243,7 +248,10 @@ class FirstMeaningfulPaint extends Audit {
       }
     });
 
-    const paintAfterMSLayout = evts.paints.find(e => e.ts > mostSignificantLayout.ts);
+    let paintAfterMSLayout;
+    if (mostSignificantLayout) {
+      paintAfterMSLayout = evts.paints.find(e => e.ts > mostSignificantLayout.ts);
+    }
     return paintAfterMSLayout;
   }
 }
diff --git a/lighthouse-core/audits/time-to-interactive.js b/lighthouse-core/audits/time-to-interactive.js
@@ -79,17 +79,22 @@ class TTIMetric extends Audit {
       const fMPts = timings.fMPfull + timings.navStart;
 
       // look at speedline results for 85% starting at FMP
-      let eightyFivePctVC = artifacts.Speedline.frames.find(frame => {
-        return frame.getTimeStamp() >= fMPts && frame.getProgress() >= 85;
-      });
+      let eightyFivePctVC;
+      let visuallyReadyTiming = 0;
 
-      // Check to avoid closure compiler null dereferencing errors
-      if (eightyFivePctVC === undefined) {
-        eightyFivePctVC = 0;
-      }
+      if (artifacts.Speedline.frames) {
+        eightyFivePctVC = artifacts.Speedline.frames.find(frame => {
+          return frame.getTimeStamp() >= fMPts && frame.getProgress() >= 85;
+        });
 
-      // TODO CHECK these units are the same
-      const visuallyReadyTiming = (eightyFivePctVC.getTimeStamp() - timings.navStart) || 0;
+        // Check to avoid closure compiler null dereferencing errors
+        if (eightyFivePctVC === undefined) {
+          eightyFivePctVC = 0;
+        }
+
+        // TODO CHECK these units are the same
+        visuallyReadyTiming = eightyFivePctVC.getTimeStamp() - timings.navStart || 0;
+      }
 
       // Find first 500ms window where Est Input Latency is <50ms at the 90% percentile.
       let startTime = Math.max(fmpTiming, visuallyReadyTiming) - 50;
@@ -150,6 +155,7 @@ class TTIMetric extends Audit {
         rawValue: timeToInteractive,
         displayValue: `${timeToInteractive}ms`,
         optimalValue: this.meta.optimalValue,
+        debugString: artifacts.Speedline.debugString,
         extendedInfo: {
           value: extendedInfo,
           formatter: Formatter.SUPPORTED_FORMATS.NULL
diff --git a/lighthouse-core/config/index.js b/lighthouse-core/config/index.js
@@ -19,9 +19,92 @@
 const defaultConfig = require('./default.json');
 const recordsFromLogs = require('../lib/network-recorder').recordsFromLogs;
 const CriticalRequestChainsGatherer = require('../driver/gatherers/critical-request-chains');
+const SpeedlineGatherer = require('../driver/gatherers/speedline');
 const Driver = require('../driver');
 const log = require('../lib/log');
 
+// cleanTrace is run to remove duplicate TracingStartedInPage events,
+// and to change TracingStartedInBrowser events into TracingStartedInPage.
+// This is done by searching for most occuring threads and basing new events
+// off of those.
+function cleanTrace(traceContents) {
+  // Keep track of most occuring threads
+  const threads = [];
+  const countsByThread = {};
+  const traceStartEvents = [];
+  const makeMockEvent = (evt, ts) => {
+    return {
+      pid: evt.pid,
+      tid: evt.tid,
+      ts: ts || 0,  // default to 0 for now
+      ph: 'I',
+      cat: 'disabled-by-default-devtools.timeline',
+      name: 'TracingStartedInPage',
+      args: {
+        data: {
+          page: evt.frame
+        }
+      },
+      s: 't'
+    };
+  };
+
+  let frame;
+  let data;
+  let name;
+  let counter;
+
+  traceContents.forEach((evt, idx) => {
+    if (evt.name.startsWith('TracingStartedIn')) {
+      traceStartEvents.push(idx);
+    }
+
+    // find the event's frame
+    data = evt.args && (evt.args.data || evt.args.beginData || evt.args.counters);
+    frame = (evt.args && evt.args.frame) || data && (data.frame || data.page);
+
+    if (!frame) {
+      return;
+    }
+
+    // Increase occurences count of the frame
+    name = `pid${evt.pid}-tid${evt.tid}-frame${frame}`;
+    counter = countsByThread[name];
+    if (!counter) {
+      counter = {
+        pid: evt.pid,
+        tid: evt.tid,
+        frame: frame,
+        count: 0
+      };
+      countsByThread[name] = counter;
+      threads.push(counter);
+    }
+    counter.count++;
+  });
+
+  // find most active thread (and frame)
+  threads.sort((a, b) => b.count - a.count);
+  const mostActiveFrame = threads[0];
+
+  // Remove all current TracingStartedIn* events, storing
+  // the first events ts.
+  const ts = traceContents[traceStartEvents[0]] && traceContents[traceStartEvents[0]].ts;
+
+  // account for offset after removing items
+  let i = 0;
+  for (let dup of traceStartEvents) {
+    traceContents.splice(dup - i, 1);
+    i++;
+  }
+
+  // Add a new TracingStartedInPage event based on most active thread
+  // and using TS of first found TracingStartedIn* event
+  traceContents.unshift(makeMockEvent(mostActiveFrame, ts));
+
+  return traceContents;
+}
+
 function filterPasses(passes, audits) {
   const requiredGatherers = getGatherersNeededByAudits(audits);
 
@@ -96,18 +179,28 @@ function expandAudits(audits) {
   });
 }
 
-function expandArtifacts(artifacts) {
+function expandArtifacts(artifacts, includeSpeedline) {
   const expandedArtifacts = Object.assign({}, artifacts);
 
   // currently only trace logs and performance logs should be imported
   if (artifacts.traces) {
+    let trace;
     Object.keys(artifacts.traces).forEach(key => {
       if (artifacts.traces[key].traceContents) {
-        expandedArtifacts.traces[key].traceContents =
-          require(artifacts.traces[key].traceContents);
+        log.log('info', 'Normalizng trace contents into expected state...');
+        trace = require(artifacts.traces[key].traceContents);
+
+        expandedArtifacts.traces[key].traceContents = cleanTrace(trace.traceEvents || trace);
       }
     });
   }
+
+  if (includeSpeedline) {
+    const speedline = new SpeedlineGatherer();
+    speedline.afterPass({}, {traceContents: expandedArtifacts.traces.defaultPass.traceContents});
+    expandedArtifacts.Speedline = speedline.artifact;
+  }
+
   if (artifacts.performanceLog) {
     expandedArtifacts.CriticalRequestChains =
       parsePerformanceLog(require(artifacts.performanceLog));
@@ -146,7 +239,12 @@ class Config {
     // filterPasses expects audits to have been expanded
     this._passes = configJSON.passes ? filterPasses(configJSON.passes, this._audits) : null;
     this._auditResults = configJSON.auditResults ? Array.from(configJSON.auditResults) : null;
-    this._artifacts = configJSON.artifacts ? expandArtifacts(configJSON.artifacts) : null;
+    this._artifacts = null;
+    if (configJSON.artifacts) {
+      this._artifacts = expandArtifacts(configJSON.artifacts,
+          // If time-to-interactive is present, add the speedline artifact
+          configJSON.audits && configJSON.audits.find(a => a === 'time-to-interactive'));
+    }
     this._aggregations = configJSON.aggregations ? Array.from(configJSON.aggregations) : null;
   }
 
diff --git a/lighthouse-core/test/config/index.js b/lighthouse-core/test/config/index.js
@@ -131,19 +131,76 @@ describe('Config', () => {
     const config = new Config({
       artifacts: {
         traces: {
-          firstPass: {
+          defaultPass: {
             traceContents: path.resolve(__dirname, '../fixtures/traces/trace-user-timings.json')
           }
         },
         performanceLog: path.resolve(__dirname, '../fixtures/perflog.json')
       }
     });
     const traceUserTimings = require('../fixtures/traces/trace-user-timings.json');
-    assert.deepStrictEqual(config.artifacts.traces.firstPass.traceContents, traceUserTimings);
+    assert.deepStrictEqual(config.artifacts.traces.defaultPass.traceContents, traceUserTimings);
     assert.ok(config.artifacts.CriticalRequestChains);
     assert.ok(config.artifacts.CriticalRequestChains['93149.1']);
     assert.ok(config.artifacts.CriticalRequestChains['93149.1'].request);
     assert.ok(config.artifacts.CriticalRequestChains['93149.1'].children);
   });
+
+  it('handles traces with no TracingStartedInPage events', () => {
+    const config = new Config({
+      artifacts: {
+        traces: {
+          defaultPass: {
+            traceContents: path.resolve(__dirname,
+                               '../fixtures/traces/trace-user-timings-no-tracingstartedinpage.json')
+          }
+        },
+        performanceLog: path.resolve(__dirname, '../fixtures/perflog.json')
+      }
+    });
+
+    assert.ok(config.artifacts.traces.defaultPass.traceContents.find(
+          e => e.name === 'TracingStartedInPage' && e.args.data.page === '0xhad00p'));
+  });
+
+  it('doesnt add speedline artifact to tests without tti audit', () => {
+    const config = new Config({
+      artifacts: {
+        traces: {
+          defaultPass: {
+            traceContents: path.resolve(__dirname,
+                               '../fixtures/traces/trace-user-timings-no-tracingstartedinpage.json')
+          }
+        },
+        performanceLog: path.resolve(__dirname, '../fixtures/perflog.json')
+      },
+      audits: [
+        'first-meaningful-paint'
+
+      ]
+    });
+
+    assert.equal(config.artifacts.Speedline, undefined);
+  });
+
+  it('does add speedline artifact to tests without tti audit', () => {
+    const config = new Config({
+      artifacts: {
+        traces: {
+          defaultPass: {
+            traceContents: path.resolve(__dirname,
+                               '../fixtures/traces/trace-user-timings-no-tracingstartedinpage.json')
+          }
+        },
+        performanceLog: path.resolve(__dirname, '../fixtures/perflog.json')
+      },
+      audits: [
+        'first-meaningful-paint',
+        'time-to-interactive'
+      ]
+    });
+
+    assert.notEqual(config.artifacts.Speedline, undefined);
+  });
 });
 
diff --git a/lighthouse-core/test/fixtures/traces/trace-user-timings-no-tracingstartedinpage.json b/lighthouse-core/test/fixtures/traces/trace-user-timings-no-tracingstartedinpage.json
@@ -0,0 +1,4 @@
+[{"pid":41904,"tid":1295,"ts":506085991145,"ph":"R","cat":"blink.user_timing","name":"navigationStart","args":{"frame": "0xhad00p"},"tts":314882},
+{"pid":41904,"tid":1295,"ts":506086992099,"ph":"R","cat":"blink.user_timing","name":"mark_test","args":{},"tts":331149},
+{"pid":41904,"tid":1295,"ts":506085991147,"ph":"b","cat":"blink.user_timing","name":"measure_test","args":{},"tts":331184,"id":"0x73b016"},
+{"pid":41904,"tid":1295,"ts":506086992112,"ph":"e","cat":"blink.user_timing","name":"measure_test","args":{},"tts":331186,"id":"0x73b016"}]
