Repository: GoogleChrome/lighthouse
Pull request #6619 (2018-11-20 23:34:07)

core(computed-artifacts): fix cache and add perf timing
split off from #6618

- log timing was added at the same time that #6204 updated computed artifacts, so timing info hasn't actually been collected for computed artifacts (timing was still accounted for in the audits that called them, though). This PR adds timing to the new version.
- #6204 messed up and was using strict equality testing for the computed artifact cache, not deep equality. Computed artifacts that take a bare artifact (e.g. `trace-of-tab`) had no issue with this and cached correctly. Any computed artifact that take a more complicated input (e.g. all the metrics) always found keys to be unequal, and so reran their computations every time they were called. This was especially bad in the lantern metrics, which tend to call each other a lot and benefit a good deal from caching.

  This PR defaults `ArbitraryEqualityMap` to using deep equality now (since that's the only way we use it), and the kind of goofball test updated in `computed-artifact-test.js` proved it's worth and will prevent this from regressing again.

Good news: runs should speed up :)


Patch:
diff --git a/lighthouse-core/computed/computed-artifact.js b/lighthouse-core/computed/computed-artifact.js
index 471a027e4..618c8520b 100644
--- a/lighthouse-core/computed/computed-artifact.js
+++ b/lighthouse-core/computed/computed-artifact.js
@@ -6,6 +6,7 @@
 'use strict';
 
 const ArbitraryEqualityMap = require('../lib/arbitrary-equality-map.js');
+const log = require('lighthouse-logger');
 
 /**
  * Decorate computableArtifact with a caching `request()` method which will
@@ -25,18 +26,25 @@ function makeComputedArtifact(computableArtifact) {
    */
   const request = (artifacts, context) => {
     const computedCache = context.computedCache;
-    const cache = computedCache.get(computableArtifact.name) || new ArbitraryEqualityMap();
-    computedCache.set(computableArtifact.name, cache);
+    const computedName = computableArtifact.name;
+
+    const cache = computedCache.get(computedName) || new ArbitraryEqualityMap();
+    computedCache.set(computedName, cache);
 
     const computed = /** @type {ReturnType<C['compute_']>|undefined} */ (cache.get(artifacts));
     if (computed) {
       return computed;
     }
 
+    const status = {msg: `Computing artifact: ${computedName}`, id: `lh:computed:${computedName}`};
+    log.time(status, 'verbose');
+
     const artifactPromise = /** @type {ReturnType<C['compute_']>} */
         (computableArtifact.compute_(artifacts, context));
     cache.set(artifacts, artifactPromise);
 
+    artifactPromise.then(() => log.timeEnd(status)).catch(() => log.timeEnd(status));
+
     return artifactPromise;
   };
 
diff --git a/lighthouse-core/lib/arbitrary-equality-map.js b/lighthouse-core/lib/arbitrary-equality-map.js
index 78a3fd5e8..15bd8caa4 100644
--- a/lighthouse-core/lib/arbitrary-equality-map.js
+++ b/lighthouse-core/lib/arbitrary-equality-map.js
@@ -14,7 +14,7 @@ const isEqual = require('lodash.isequal');
  */
 class ArbitraryEqualityMap {
   constructor() {
-    this._equalsFn = /** @type {function(*,*):boolean} */ ((a, b) => a === b);
+    this._equalsFn = ArbitraryEqualityMap.deepEquals;
     /** @type {Array<{key: *, value: *}>} */
     this._entries = [];
   }
diff --git a/proto/sample_v2_round_trip.json b/proto/sample_v2_round_trip.json
index 551bb7fb9..a3339bc09 100644
--- a/proto/sample_v2_round_trip.json
+++ b/proto/sample_v2_round_trip.json
@@ -3330,6 +3330,12 @@
                 "name": "lh:audit:is-on-https", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:NetworkRecords", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
@@ -3366,24 +3372,60 @@
                 "name": "lh:audit:first-contentful-paint", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:FirstContentfulPaint", 
+                "startTime": 0.0
+            }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:TraceOfTab", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
                 "name": "lh:audit:first-meaningful-paint", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:FirstMeaningfulPaint", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
                 "name": "lh:audit:load-fast-enough-for-pwa", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:Interactive", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
                 "name": "lh:audit:speed-index", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:SpeedIndex", 
+                "startTime": 0.0
+            }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:Speedline", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
@@ -3396,12 +3438,24 @@
                 "name": "lh:audit:final-screenshot", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:Screenshots", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
                 "name": "lh:audit:estimated-input-latency", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:EstimatedInputLatency", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
@@ -3414,12 +3468,24 @@
                 "name": "lh:audit:time-to-first-byte", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:MainResource", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
                 "name": "lh:audit:first-cpu-idle", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:FirstCPUIdle", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
@@ -3438,18 +3504,66 @@
                 "name": "lh:audit:critical-request-chains", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:CriticalRequestChains", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
                 "name": "lh:audit:redirects", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:LanternInteractive", 
+                "startTime": 0.0
+            }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:LanternFirstMeaningfulPaint", 
+                "startTime": 0.0
+            }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:LanternFirstContentfulPaint", 
+                "startTime": 0.0
+            }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:PageDependencyGraph", 
+                "startTime": 0.0
+            }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:LoadSimulator", 
+                "startTime": 0.0
+            }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:NetworkAnalysis", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
                 "name": "lh:audit:webapp-install-banner", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:ManifestValues", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
@@ -3486,6 +3600,12 @@
                 "name": "lh:audit:mainthread-work-breakdown", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:MainThreadTasks", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
@@ -3498,6 +3618,12 @@
                 "name": "lh:audit:uses-rel-preload", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:LoadSimulator", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 
@@ -3846,6 +3972,18 @@
                 "name": "lh:audit:render-blocking-resources", 
                 "startTime": 0.0
             }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:FirstContentfulPaint", 
+                "startTime": 0.0
+            }, 
+            {
+                "duration": 100.0, 
+                "entryType": "measure", 
+                "name": "lh:computed:LanternFirstContentfulPaint", 
+                "startTime": 0.0
+            }, 
             {
                 "duration": 100.0, 
                 "entryType": "measure", 


Test patch:
diff --git a/lighthouse-core/test/computed/computed-artifact-test.js b/lighthouse-core/test/computed/computed-artifact-test.js
index 2c7d3a866..d59fdd4e4 100644
--- a/lighthouse-core/test/computed/computed-artifact-test.js
+++ b/lighthouse-core/test/computed/computed-artifact-test.js
@@ -12,19 +12,19 @@ const assert = require('assert');
 const makeComputedArtifact = require('../../computed/computed-artifact.js');
 
 describe('ComputedArtifact base class', () => {
-  it.skip('caches computed artifacts by strict equality', async () => {
+  it('caches computed artifacts by strict equality', async () => {
     let computeCounter = 0;
-
-    const TestComputedArtifact = makeComputedArtifact(class TestComputedArtifact {
+    class RawTestComputedArtifact {
       static async compute_() {
         return computeCounter++;
       }
-    });
+    }
 
     const context = {
       computedCache: new Map(),
     };
 
+    const TestComputedArtifact = makeComputedArtifact(RawTestComputedArtifact);
     let result = await TestComputedArtifact.request({x: 1}, context);
     assert.equal(result, 0);
 
diff --git a/lighthouse-core/test/results/sample_v2.json b/lighthouse-core/test/results/sample_v2.json
index 053f381a5..3c7570076 100644
--- a/lighthouse-core/test/results/sample_v2.json
+++ b/lighthouse-core/test/results/sample_v2.json
@@ -3474,6 +3474,12 @@
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:NetworkRecords",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:redirects-http",
@@ -3510,24 +3516,60 @@
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:FirstContentfulPaint",
+        "duration": 100,
+        "entryType": "measure"
+      },
+      {
+        "startTime": 0,
+        "name": "lh:computed:TraceOfTab",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:first-meaningful-paint",
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:FirstMeaningfulPaint",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:load-fast-enough-for-pwa",
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:Interactive",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:speed-index",
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:SpeedIndex",
+        "duration": 100,
+        "entryType": "measure"
+      },
+      {
+        "startTime": 0,
+        "name": "lh:computed:Speedline",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:screenshot-thumbnails",
@@ -3540,12 +3582,24 @@
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:Screenshots",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:estimated-input-latency",
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:EstimatedInputLatency",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:errors-in-console",
@@ -3558,12 +3612,24 @@
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:MainResource",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:first-cpu-idle",
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:FirstCPUIdle",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:interactive",
@@ -3582,18 +3648,66 @@
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:CriticalRequestChains",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:redirects",
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:LanternInteractive",
+        "duration": 100,
+        "entryType": "measure"
+      },
+      {
+        "startTime": 0,
+        "name": "lh:computed:LanternFirstMeaningfulPaint",
+        "duration": 100,
+        "entryType": "measure"
+      },
+      {
+        "startTime": 0,
+        "name": "lh:computed:LanternFirstContentfulPaint",
+        "duration": 100,
+        "entryType": "measure"
+      },
+      {
+        "startTime": 0,
+        "name": "lh:computed:PageDependencyGraph",
+        "duration": 100,
+        "entryType": "measure"
+      },
+      {
+        "startTime": 0,
+        "name": "lh:computed:LoadSimulator",
+        "duration": 100,
+        "entryType": "measure"
+      },
+      {
+        "startTime": 0,
+        "name": "lh:computed:NetworkAnalysis",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:webapp-install-banner",
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:ManifestValues",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:splash-screen",
@@ -3630,6 +3744,12 @@
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:MainThreadTasks",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:bootup-time",
@@ -3642,6 +3762,12 @@
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:LoadSimulator",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:uses-rel-preconnect",
@@ -3990,6 +4116,18 @@
         "duration": 100,
         "entryType": "measure"
       },
+      {
+        "startTime": 0,
+        "name": "lh:computed:FirstContentfulPaint",
+        "duration": 100,
+        "entryType": "measure"
+      },
+      {
+        "startTime": 0,
+        "name": "lh:computed:LanternFirstContentfulPaint",
+        "duration": 100,
+        "entryType": "measure"
+      },
       {
         "startTime": 0,
         "name": "lh:audit:unminified-css",