fix(driver): wait for CPU idle via clientside perfObserver (#2473)

GoogleChrome · Jun 28, 2017 · 56eaa50 · 56eaa50
1 parent 673c3ba
commit 56eaa50
Show file tree

Hide file tree

Showing 6 changed files with 187 additions and 17 deletions.
diff --git a/lighthouse-cli/test/fixtures/tricky-ttci.html b/lighthouse-cli/test/fixtures/tricky-ttci.html
@@ -0,0 +1,23 @@
+<html>
+<meta name="viewport" content="width=device-width, initial-scale=1, minimum-scale=1">
+<body>
+  Just try and figure out my TTCI (hint: it should be ~10s)
+
+  <script>
+    /**
+     * Stalls the main thread for timeInMs
+     */
+    function stall(timeInMs) {
+      const start = performance.now();
+      while (performance.now() - start < timeInMs) {
+        for (let i = 0; i < 1000000; i++) ;
+      }
+    }
+
+    setTimeout(() => stall(250), 1000); // stall for 250ms, 1 second out
+    setTimeout(() => stall(500), 2000); // stall for 500ms, 2 seconds out
+    setTimeout(() => stall(5000), 5000); // stall for 5000ms, 5 seconds out
+  </script>
+  <script src="bogus.js?delay=2000"></script>
+</body>
+</html>
diff --git a/lighthouse-cli/test/smokehouse/tricky-ttci/expectations.js b/lighthouse-cli/test/smokehouse/tricky-ttci/expectations.js
@@ -0,0 +1,26 @@
+/**
+ * @license Copyright 2017 Google Inc. All Rights Reserved.
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. You may obtain a copy of the License at http://www.apache.org/licenses/LICENSE-2.0
+ * Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License.
+ */
+'use strict';
+
+/**
+ * Expected Lighthouse audit values for --perf tests
+ */
+module.exports = [
+  {
+    initialUrl: 'http://localhost:10200/tricky-ttci.html',
+    url: 'http://localhost:10200/tricky-ttci.html',
+    audits: {
+      'first-interactive': {
+        score: '<75',
+        rawValue: '>9000',
+      },
+      'consistently-interactive': {
+        score: '<75',
+        rawValue: '>9000',
+      },
+    }
+  },
+];
diff --git a/lighthouse-cli/test/smokehouse/tricky-ttci/run-tests.sh b/lighthouse-cli/test/smokehouse/tricky-ttci/run-tests.sh
@@ -0,0 +1,16 @@
+#!/usr/bin/env bash
+
+node lighthouse-cli/test/fixtures/static-server.js &
+
+sleep 0.5s
+
+config="lighthouse-core/config/perf.json"
+expectations="lighthouse-cli/test/smokehouse/tricky-ttci/expectations.js"
+
+yarn smokehouse -- --config-path=$config --expectations-path=$expectations
+exit_code=$?
+
+# kill test servers
+kill $(jobs -p)
+
+exit "$exit_code"
diff --git a/lighthouse-core/config/default.js b/lighthouse-core/config/default.js
@@ -13,8 +13,8 @@ module.exports = {
     passName: 'defaultPass',
     recordTrace: true,
     pauseAfterLoadMs: 5250,
-    networkQuietThresholdMs: 5000,
-    pauseAfterNetworkQuietMs: 2500,
+    networkQuietThresholdMs: 5250,
+    cpuQuietThresholdMs: 5250,
     useThrottling: true,
     gatherers: [
       'url',

diff --git a/lighthouse-core/gather/driver.js b/lighthouse-core/gather/driver.js
@@ -18,8 +18,8 @@ const DevtoolsLog = require('./devtools-log');
 const DEFAULT_PAUSE_AFTER_LOAD = 0;
 // Controls how long to wait between network requests before determining the network is quiet
 const DEFAULT_NETWORK_QUIET_THRESHOLD = 5000;
-// Controls how long to wait after network quiet before continuing
-const DEFAULT_PAUSE_AFTER_NETWORK_QUIET = 0;
+// Controls how long to wait between longtasks before determining the CPU is idle, off by default
+const DEFAULT_CPU_QUIET_THRESHOLD = 0;
 
 const _uniq = arr => Array.from(new Set(arr));
 
@@ -424,6 +424,66 @@ class Driver {
     };
   }
 
+  /**
+   * Installs a PerformanceObserver in the page to monitor for longtasks and resolves when there have
+   * been no long tasks for at least waitForCPUQuiet ms. The promise will not resolve until the
+   * `markAsResolvable` function on the return object has been called. This is to prevent promise resolution
+   * before some important point in time such as network quiet or document load.
+   * @param {number} waitForCPUQuiet
+   * @return {{promise: !Promise, cancel: function(), markAsResolvable: function()}}
+   */
+  _waitForCPUIdle(waitForCPUQuiet) {
+    if (!waitForCPUQuiet) {
+      return {
+        markAsResolvable: () => undefined,
+        promise: Promise.resolve(),
+        cancel: () => undefined,
+      };
+    }
+
+    let lastTimeout;
+    let isResolvable = false;
+    function checkForQuiet(driver, resolve) {
+      const tryLater = timeToWait => {
+        lastTimeout = setTimeout(() => checkForQuiet(driver, resolve), timeToWait);
+      };
+
+      if (!isResolvable) {
+        return tryLater(1000);
+      }
+
+      return driver.evaluateAsync(`(${checkTimeSinceLastLongTask.toString()})()`)
+        .then(timeSinceLongTask => {
+          if (typeof timeSinceLongTask === 'number' && timeSinceLongTask >= waitForCPUQuiet) {
+            log.verbose('Driver', `CPU has been idle for ${timeSinceLongTask} ms`);
+            resolve();
+          } else {
+            log.verbose('Driver', `CPU has been idle for ${timeSinceLongTask} ms`);
+            tryLater(waitForCPUQuiet - timeSinceLongTask);
+          }
+        });
+    }
+
+    log.verbose('Driver', `Installing longtask listener for CPU idle.`);
+    this.evaluateScriptOnLoad(`(${installPerformanceObserver.toString()})()`);
+    let cancel;
+    const promise = new Promise((resolve, reject) => {
+      checkForQuiet(this, resolve);
+      cancel = () => {
+        if (lastTimeout) clearTimeout(lastTimeout);
+        reject(new Error('Wait for CPU idle cancelled'));
+      };
+    });
+
+    return {
+      markAsResolvable: () => {
+        isResolvable = true;
+      },
+      promise,
+      cancel,
+    };
+  }
+
   /**
    * Return a promise that resolves `pauseAfterLoadMs` after the load event
    * fires and a method to cancel internal listeners and timeout.
@@ -454,33 +514,37 @@ class Driver {
 
   /**
    * Returns a promise that resolves when:
-   * - it's been networkQuietThresholdMs milliseconds after both onload and the network
-   * has gone idle, or
+   * - All of the following conditions have been met:
+   *    - pauseAfterLoadMs milliseconds have passed since the load event.
+   *    - networkQuietThresholdMs milliseconds have passed since the last network request that exceeded
+   *      2 inflight requests (network-2-quiet has been reached).
+   *    - cpuQuietThresholdMs have passed since the last long task after network-2-quiet.
    * - maxWaitForLoadedMs milliseconds have passed.
    * See https://github.com/GoogleChrome/lighthouse/issues/627 for more.
    * @param {number} pauseAfterLoadMs
    * @param {number} networkQuietThresholdMs
-   * @param {number} pauseAfterNetworkQuietMs
+   * @param {number} cpuQuietThresholdMs
    * @param {number} maxWaitForLoadedMs
    * @return {!Promise}
    * @private
    */
-  _waitForFullyLoaded(pauseAfterLoadMs, networkQuietThresholdMs, pauseAfterNetworkQuietMs,
+  _waitForFullyLoaded(pauseAfterLoadMs, networkQuietThresholdMs, cpuQuietThresholdMs,
       maxWaitForLoadedMs) {
     let maxTimeoutHandle;
 
     // Listener for onload. Resolves pauseAfterLoadMs ms after load.
     const waitForLoadEvent = this._waitForLoadEvent(pauseAfterLoadMs);
-    // Network listener. Resolves pauseAfterNetworkQuietMs after when the network has been idle for
-    // networkQuietThresholdMs.
-    const waitForNetworkIdle = this._waitForNetworkIdle(networkQuietThresholdMs,
-        pauseAfterNetworkQuietMs);
+    // Network listener. Resolves when the network has been idle for networkQuietThresholdMs.
+    const waitForNetworkIdle = this._waitForNetworkIdle(networkQuietThresholdMs);
+    // CPU listener. Resolves when the CPU has been idle for cpuQuietThresholdMs after network idle.
+    const waitForCPUIdle = this._waitForCPUIdle(cpuQuietThresholdMs);
 
     // Wait for both load promises. Resolves on cleanup function the clears load
     // timeout timer.
     const loadPromise = Promise.all([
       waitForLoadEvent.promise,
-      waitForNetworkIdle.promise
+      waitForNetworkIdle.promise.then(waitForCPUIdle.markAsResolvable),
+      waitForCPUIdle.promise,
     ]).then(() => {
       return function() {
         log.verbose('Driver', 'loadEventFired and network considered idle');
@@ -497,6 +561,7 @@ class Driver {
         log.warn('Driver', 'Timed out waiting for page load. Moving on...');
         waitForLoadEvent.cancel();
         waitForNetworkIdle.cancel();
+        waitForCPUIdle.cancel();
       };
     });
 
@@ -564,13 +629,13 @@ class Driver {
 
     let pauseAfterLoadMs = options.config && options.config.pauseAfterLoadMs;
     let networkQuietThresholdMs = options.config && options.config.networkQuietThresholdMs;
-    let pauseAfterNetworkQuietMs = options.config && options.config.pauseAfterNetworkQuietMs;
+    let cpuQuietThresholdMs = options.config && options.config.cpuQuietThresholdMs;
     let maxWaitMs = options.flags && options.flags.maxWaitForLoad;
 
     /* eslint-disable max-len */
     if (typeof pauseAfterLoadMs !== 'number') pauseAfterLoadMs = DEFAULT_PAUSE_AFTER_LOAD;
     if (typeof networkQuietThresholdMs !== 'number') networkQuietThresholdMs = DEFAULT_NETWORK_QUIET_THRESHOLD;
-    if (typeof pauseAfterNetworkQuietMs !== 'number') pauseAfterNetworkQuietMs = DEFAULT_PAUSE_AFTER_NETWORK_QUIET;
+    if (typeof cpuQuietThresholdMs !== 'number') cpuQuietThresholdMs = DEFAULT_CPU_QUIET_THRESHOLD;
     if (typeof maxWaitMs !== 'number') maxWaitMs = Driver.MAX_WAIT_FOR_FULLY_LOADED;
     /* eslint-enable max-len */
 
@@ -579,7 +644,7 @@ class Driver {
       .then(_ => this.sendCommand('Emulation.setScriptExecutionDisabled', {value: disableJS}))
       .then(_ => this.sendCommand('Page.navigate', {url}))
       .then(_ => waitForLoad && this._waitForFullyLoaded(pauseAfterLoadMs,
-          networkQuietThresholdMs, pauseAfterNetworkQuietMs, maxWaitMs))
+          networkQuietThresholdMs, cpuQuietThresholdMs, maxWaitMs))
       .then(_ => this._endNetworkStatusMonitoring());
   }
 
@@ -1011,4 +1076,44 @@ function wrapRuntimeEvalErrorInBrowser(err) {
   };
 }
 
+/**
+ * Used by _waitForCPUIdle and executed in the context of the page, updates the ____lastLongTask
+ * property on window to the end time of the last long task.
+ * instanbul ignore next
+ */
+function installPerformanceObserver() {
+  window.____lastLongTask = window.performance.now();
+  const observer = new window.PerformanceObserver(entryList => {
+    const entries = entryList.getEntries();
+    for (const entry of entries) {
+      if (entry.entryType === 'longtask') {
+        const taskEnd = entry.startTime + entry.duration;
+        window.____lastLongTask = Math.max(window.____lastLongTask, taskEnd);
+      }
+    }
+  });
+  observer.observe({entryTypes: ['longtask']});
+}
+
+
+/**
+ * Used by _waitForCPUIdle and executed in the context of the page, returns time since last long task.
+ * instanbul ignore next
+ */
+function checkTimeSinceLastLongTask() {
+  // Wait for a delta before returning so that we're sure the PerformanceObserver
+  // has had time to register the last longtask
+  return new Promise(resolve => {
+    const timeoutRequested = window.performance.now() + 50;
+
+    setTimeout(() => {
+      // Double check that a long task hasn't happened since setTimeout
+      const timeoutFired = window.performance.now();
+      const timeSinceLongTask = timeoutFired - timeoutRequested < 50 ?
+          timeoutFired - window.____lastLongTask : 0;
+      resolve(timeSinceLongTask);
+    }, 50);
+  });
+}
+
 module.exports = Driver;
diff --git a/package.json b/package.json
@@ -27,7 +27,7 @@
     "build-viewer": "cd ./lighthouse-viewer && yarn build",
     "clean": "rimraf *.report.html *.report.dom.html *.report.json *.screenshots.html *.devtoolslog.json *.trace.json || true",
     "lint": "[ \"$CI\" = true ] && eslint --quiet -f codeframe . || eslint .",
-    "smoke": "bash lighthouse-cli/test/smokehouse/offline-local/run-tests.sh && bash lighthouse-cli/test/smokehouse/perf/run-tests.sh && bash lighthouse-cli/test/smokehouse/dobetterweb/run-tests.sh && bash lighthouse-cli/test/smokehouse/byte-efficiency/run-tests.sh",
+    "smoke": "bash lighthouse-cli/test/smokehouse/offline-local/run-tests.sh && bash lighthouse-cli/test/smokehouse/perf/run-tests.sh && bash lighthouse-cli/test/smokehouse/dobetterweb/run-tests.sh && bash lighthouse-cli/test/smokehouse/byte-efficiency/run-tests.sh && bash lighthouse-cli/test/smokehouse/tricky-ttci/run-tests.sh",
     "coverage": "istanbul cover -x \"**/third_party/**\" _mocha -- $(find */test -name '*-test.js') --timeout 10000 --reporter progress --report lcovonly",
     "start": "gulp && node ./lighthouse-cli/index.js",
     "test": "yarn lint --silent && gulp && yarn unit && yarn closure && yarn test-cli-formatting && yarn test-launcher-formatting",