Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix(driver): wait for CPU idle #2473

Merged
merged 6 commits into from
Jun 28, 2017
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
23 changes: 23 additions & 0 deletions lighthouse-cli/test/fixtures/tricky-ttci.html
Original file line number Diff line number Diff line change
@@ -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>
26 changes: 26 additions & 0 deletions lighthouse-cli/test/smokehouse/tricky-ttci/expectations.js
Original file line number Diff line number Diff line change
@@ -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': {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

can we assert the rawValue is over 9000 ?
😀

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

love it, gotta check those power levels

score: '<75',
rawValue: '>9000',
},
'consistently-interactive': {
score: '<75',
rawValue: '>9000',
},
}
},
];
16 changes: 16 additions & 0 deletions lighthouse-cli/test/smokehouse/tricky-ttci/run-tests.sh
Original file line number Diff line number Diff line change
@@ -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"
4 changes: 2 additions & 2 deletions lighthouse-core/config/default.js
Original file line number Diff line number Diff line change
Expand Up @@ -13,8 +13,8 @@ module.exports = {
passName: 'defaultPass',
recordTrace: true,
pauseAfterLoadMs: 5250,
networkQuietThresholdMs: 5000,
pauseAfterNetworkQuietMs: 2500,
networkQuietThresholdMs: 5250,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is the idea here to realign networkQuietThresholdMs and the new cpuQuietThresholdMs with the pauseAfterLoadMs delay instead of the lower pause thresholds previously being used?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the historical background to pauseAfterNetworkQuiet was that we needed a way to account for CPU work after scripts have finished downloading, so it became the number for "what's the longest after network quiet we might reasonably expect a long task to occur"

now that this role has been subsumed by a bona fide CPU idle check, we don't need it anymore, however, we still want a little bit of slack in our cutoff thus 5250 instead of straight 5000

pauseAfterLoad is probably still worth keeping around for now as there are cases like the ember + fastboot where "quiet" can be reached too quickly without really reaching the load state, and it's good to see the full timeline as we try to improve the other heuristics

cpuQuietThresholdMs: 5250,
useThrottling: true,
gatherers: [
'url',
Expand Down
133 changes: 119 additions & 14 deletions lighthouse-core/gather/driver.js
Original file line number Diff line number Diff line change
Expand Up @@ -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));

Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this method description need an update. Can you flesh it out a bit so we won't have to look back up the PR when trying to read the code?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done

* @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.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might be worth expanding comment to Network and CPU listeners or adding a similar line above ...const waitForCPUIdle for consistency.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

oops, meant to do that thanks!

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');
Expand All @@ -497,6 +561,7 @@ class Driver {
log.warn('Driver', 'Timed out waiting for page load. Moving on...');
waitForLoadEvent.cancel();
waitForNetworkIdle.cancel();
waitForCPUIdle.cancel();
};
});

Expand Down Expand Up @@ -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 */

Expand All @@ -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());
}

Expand Down Expand Up @@ -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;
2 changes: 1 addition & 1 deletion package.json
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down