Measure and visualize perf metrics

.eslintignore

@@ -21,3 +21,6 @@ lighthouse-cli/types/*.js
 # Handlebar-templates
 lighthouse-core/report/templates/report-templates.js
 lighthouse-core/report/partials/templates/report-partials.js
+
+# Generated files
+plots/out/**

.gitignore

@@ -41,3 +41,5 @@ lighthouse-cli/types/*.map
 
 lighthouse-core/report/partials/templates/
 lighthouse-core/report/templates/*.js
+
+plots/out/

.npmignore

@@ -27,6 +27,8 @@ lighthouse-cli/types/*.map
 node_modules/
 results/
 
+plots/
+
 # generated files
 **/pages/scripts/lighthouse-report.js
 *.report.html

lighthouse-core/audits/time-to-interactive.js

@@ -175,6 +175,7 @@ class TTIMetric extends Audit {
         throw new Error('No firstMeaningfulPaint event found in trace');
       }
 
+      const onLoadTiming = tabTrace.timings.onLoad;
       const fmpTiming = tabTrace.timings.firstMeaningfulPaint;
       const traceEndTiming = tabTrace.timings.traceEnd;
 
@@ -214,6 +215,7 @@ class TTIMetric extends Audit {
 
       const extendedInfo = {
         timings: {
+          onLoad: onLoadTiming,
           fMP: parseFloat(fmpTiming.toFixed(3)),
           visuallyReady: parseFloat(visuallyReadyTiming.toFixed(3)),
           timeToInteractive: parseFloat(timeToInteractive.timeInMs.toFixed(3)),
@@ -222,6 +224,7 @@ class TTIMetric extends Audit {
           endOfTrace: traceEndTiming,
         },
         timestamps: {
+          onLoad: (onLoadTiming + navStartTsInMS) * 1000,
           fMP: fMPtsInMS * 1000,
           visuallyReady: (visuallyReadyTiming + navStartTsInMS) * 1000,
           timeToInteractive: (timeToInteractive.timeInMs + navStartTsInMS) * 1000,

lighthouse-core/config/plots.json

@@ -0,0 +1,16 @@
+{
+  "passes": [{
+    "recordNetwork": true,
+    "recordTrace": true,
+    "pauseBeforeTraceEndMs": 5000,
+    "useThrottling": true,
+    "gatherers": []
+  }],
+
+  "audits": [
+    "first-meaningful-paint",
+    "speed-index-metric",
+    "estimated-input-latency",
+    "time-to-interactive"
+  ]
+}

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

@@ -46,6 +46,7 @@ class TraceOfTab extends ComputedArtifact {
       .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);
@@ -87,6 +88,8 @@ class TraceOfTab extends ComputedArtifact {
       firstMeaningfulPaint = lastCandidate;
     }
 
+    const onLoad = keyEvents.find(e => e.name === 'MarkLoad' && e.ts > navigationStart.ts);
+
     // subset all trace events to just our tab's process (incl threads other than main)
     const processEvents = trace.traceEvents
       .filter(e => e.pid === startedInPageEvt.pid)
@@ -102,6 +105,7 @@ class TraceOfTab extends ComputedArtifact {
       firstContentfulPaint,
       firstMeaningfulPaint,
       traceEnd,
+      onLoad,
     };
 
     const timings = {};
@@ -121,6 +125,7 @@ class TraceOfTab extends ComputedArtifact {
       firstPaintEvt: firstPaint,
       firstContentfulPaintEvt: firstContentfulPaint,
       firstMeaningfulPaintEvt: firstMeaningfulPaint,
+      onLoadEvt: onLoad,
     };
   }
 }

lighthouse-core/lib/traces/pwmetrics-events.js

@@ -18,6 +18,22 @@
 
 const log = require('../../../lighthouse-core/lib/log.js');
 
+/**
+ * @param {!Object} object
+ * @param {string} path
+ * @return {*}
+ */
+function safeGet(object, path) {
+  const components = path.split('.');
+  for (const component of components) {
+    if (!object) {
+      return null;
+    }
+    object = object[component];
+  }
+  return object;
+}
+
 class Metrics {
   constructor(traceEvents, auditResults) {
     this._traceEvents = traceEvents;
@@ -35,81 +51,145 @@ class Metrics {
         id: 'navstart',
         getTs: auditResults => {
           const fmpExt = auditResults['first-meaningful-paint'].extendedInfo;
-          return fmpExt.value.timestamps.navStart;
+          return safeGet(fmpExt, 'value.timestamps.navStart');
         },
+        getTiming: auditResults => {
+          const fmpExt = auditResults['first-meaningful-paint'].extendedInfo;
+          return safeGet(fmpExt, 'value.timings.navStart');
+        }
       },
       {
         name: 'First Contentful Paint',
         id: 'ttfcp',
         getTs: auditResults => {
           const fmpExt = auditResults['first-meaningful-paint'].extendedInfo;
-          return fmpExt.value.timestamps.fCP;
+          return safeGet(fmpExt, 'value.timestamps.fCP');
         },
+        getTiming: auditResults => {
+          const fmpExt = auditResults['first-meaningful-paint'].extendedInfo;
+          return safeGet(fmpExt, 'value.timings.fCP');
+        }
       },
       {
         name: 'First Meaningful Paint',
         id: 'ttfmp',
         getTs: auditResults => {
           const fmpExt = auditResults['first-meaningful-paint'].extendedInfo;
-          return fmpExt.value.timestamps.fMP;
+          return safeGet(fmpExt, 'value.timestamps.fMP');
         },
+        getTiming: auditResults => {
+          const fmpExt = auditResults['first-meaningful-paint'].extendedInfo;
+          return safeGet(fmpExt, 'value.timings.fMP');
+        }
       },
       {
         name: 'Perceptual Speed Index',
         id: 'psi',
         getTs: auditResults => {
           const siExt = auditResults['speed-index-metric'].extendedInfo;
-          return siExt.value.timestamps.perceptualSpeedIndex;
+          return safeGet(siExt, 'value.timestamps.perceptualSpeedIndex');
         },
+        getTiming: auditResults => {
+          const siExt = auditResults['speed-index-metric'].extendedInfo;
+          return safeGet(siExt, 'value.timings.perceptualSpeedIndex');
+        }
       },
       {
         name: 'First Visual Change',
         id: 'fv',
         getTs: auditResults => {
           const siExt = auditResults['speed-index-metric'].extendedInfo;
-          return siExt.value.timestamps.firstVisualChange;
+          return safeGet(siExt, 'value.timestamps.firstVisualChange');
         },
+        getTiming: auditResults => {
+          const siExt = auditResults['speed-index-metric'].extendedInfo;
+          return safeGet(siExt, 'value.timings.firstVisualChange');
+        }
       },
       {
         name: 'Visually Complete 85%',
         id: 'vc85',
         getTs: auditResults => {
           const siExt = auditResults['time-to-interactive'].extendedInfo;
-          return siExt.value.timestamps.visuallyReady;
+          return safeGet(siExt, 'value.timestamps.visuallyReady');
         },
+        getTiming: auditResults => {
+          const siExt = auditResults['time-to-interactive'].extendedInfo;
+          return safeGet(siExt, 'value.timings.visuallyReady');
+        }
       },
       {
         name: 'Visually Complete 100%',
         id: 'vc100',
         getTs: auditResults => {
           const siExt = auditResults['speed-index-metric'].extendedInfo;
-          return siExt.value.timestamps.visuallyComplete;
+          return safeGet(siExt, 'value.timestamps.visuallyComplete');
         },
+        getTiming: auditResults => {
+          const siExt = auditResults['speed-index-metric'].extendedInfo;
+          return safeGet(siExt, 'value.timings.visuallyComplete');
+        }
       },
       {
         name: 'Time to Interactive (vAlpha)',
         id: 'tti',
         getTs: auditResults => {
           const ttiExt = auditResults['time-to-interactive'].extendedInfo;
-          return ttiExt.value.timestamps.timeToInteractive;
+          return safeGet(ttiExt, 'value.timestamps.timeToInteractive');
         },
+        getTiming: auditResults => {
+          const ttiExt = auditResults['time-to-interactive'].extendedInfo;
+          return safeGet(ttiExt, 'value.timings.timeToInteractive');
+        }
       },
       {
         name: 'Time to Interactive (vAlpha non-visual)',
         id: 'tti-non-visual',
         getTs: auditResults => {
           const ttiExt = auditResults['time-to-interactive'].extendedInfo;
-          return ttiExt.value.timestamps.timeToInteractiveB;
+          return safeGet(ttiExt, 'value.timestamps.timeToInteractiveB');
         },
+        getTiming: auditResults => {
+          const ttiExt = auditResults['time-to-interactive'].extendedInfo;
+          return safeGet(ttiExt, 'value.timings.timeToInteractiveB');
+        }
       },
       {
         name: 'Time to Interactive (vAlpha non-visual, 5s)',
         id: 'tti-non-visual-5s',
         getTs: auditResults => {
           const ttiExt = auditResults['time-to-interactive'].extendedInfo;
-          return ttiExt.value.timestamps.timeToInteractiveC;
+          return safeGet(ttiExt, 'value.timestamps.timeToInteractiveC');
+        },
+        getTiming: auditResults => {
+          const ttiExt = auditResults['time-to-interactive'].extendedInfo;
+          return safeGet(ttiExt, 'value.timings.timeToInteractiveC');
+        }
+      },
+      {
+        name: 'End of Trace',
+        id: 'eot',
+        getTs: auditResults => {
+          const ttiExt = auditResults['time-to-interactive'].extendedInfo;
+          return safeGet(ttiExt, 'value.timestamps.endOfTrace');
         },
+        getTiming: auditResults => {
+          const ttiExt = auditResults['time-to-interactive'].extendedInfo;
+          return safeGet(ttiExt, 'value.timings.endOfTrace');
+        }
       },
+      {
+        name: 'On Load',
+        id: 'onload',
+        getTs: auditResults => {
+          const ttiExt = auditResults['time-to-interactive'].extendedInfo;
+          return safeGet(ttiExt, 'value.timestamps.onLoad');
+        },
+        getTiming: auditResults => {
+          const ttiExt = auditResults['time-to-interactive'].extendedInfo;
+          return safeGet(ttiExt, 'value.timings.onLoad');
+        }
+      }
     ];
   }
 

lighthouse-core/test/fixtures/dbw_tester-perf-results.json

@@ -113,6 +113,7 @@
       "extendedInfo": {
         "value": {
           "timings": {
+            "onLoad": 2956.185,
             "fMP": 2946.14,
             "visuallyReady": 2955.548,
             "timeToInteractive": 2955.548,
@@ -121,6 +122,7 @@
             "endOfTrace": 8471.488999843597
           },
           "timestamps": {
+            "onLoad": 1082005348861.9999,
             "fMP": 1082005338816.9999,
             "visuallyReady": 1082005348224.9999,
             "timeToInteractive": 1082005348224.9999,

lighthouse-core/test/lib/traces/pwmetrics-events-test.js

@@ -23,11 +23,10 @@ const assert = require('assert');
 const dbwTrace = require('../../fixtures/traces/dbw_tester.json');
 const dbwResults = require('../../fixtures/dbw_tester-perf-results.json');
 
-
 /* eslint-env mocha */
 describe('metrics events class', () => {
   it('exposes metric definitions', () => {
-    assert.equal(Metrics.metricsDefinitions.length, 10, '10 metrics not exposed');
+    assert.equal(Metrics.metricsDefinitions.length, 12, '12 metrics not exposed');
   });
 
   it('generates fake trace events', () => {

plots/README.md

@@ -0,0 +1,27 @@
+# Lighthouse Metrics Analysis
+
+For context and roadmap, please see issue:
+https://github.com/GoogleChrome/lighthouse/issues/1924
+
+## Workflow
+
+### Setup
+
+You need to build lighthouse first.
+
+### Commands
+
+```
+# View all commands
+$ cd plots
+$ npm run
+
+# Run lighthouse to collect metrics data
+$ npm run measure
+
+# Analyze the data to generate a summary file (i.e. out/generatedResults.js)
+$ npm run analyze
+
+# View visualization
+# Open index.html in browser
+```