core(perf): add timing instrumentation to measure runtime perf (#3745)

lighthouse-cli/test/cli/run-test.js

@@ -41,6 +41,7 @@ describe('CLI run', function() {
  Object.keys(results.audits).length,
  Object.keys(lhr.audits).length);
  assert.deepStrictEqual(results.timing, lhr.timing);
+ assert.ok(results.timing.total !== 0);
 
  fs.unlinkSync(filename);
  });

lighthouse-core/config/config.js

@@ -312,6 +312,8 @@ class Config {
  * @param {LH.Flags=} flags
  */
  constructor(configJSON, flags) {
+ const status = {msg: 'Create config', id: 'lh:init:config'};
+ log.time(status, 'verbose');
  let configPath = flags && flags.configPath;
 
  if (!configJSON) {
@@ -364,6 +366,7 @@ class Config {
  // TODO(bckenny): until tsc adds @implements support, assert that Config is a ConfigJson.
  /** @type {LH.Config.Json} */
  const configJson = this; // eslint-disable-line no-unused-vars
+ log.timeEnd(status);
  }
 
  /**
@@ -748,6 +751,8 @@ class Config {
  * @return {Config['audits']}
  */
  static requireAudits(audits, configPath) {
+ const status = {msg: 'Requiring audits', id: 'lh:config:requireAudits'};
+ log.time(status, 'verbose');
  const expandedAudits = Config.expandAuditShorthand(audits);
  if (!expandedAudits) {
  return null;
@@ -779,6 +784,7 @@ class Config {
 
  const mergedAuditDefns = mergeOptionsOfItems(auditDefns);
  mergedAuditDefns.forEach(audit => assertValidAudit(audit.implementation, audit.path));
+ log.timeEnd(status);
  return mergedAuditDefns;
  }
 
@@ -820,6 +826,8 @@ class Config {
  if (!passes) {
  return null;
  }
+ const status = {msg: 'Requiring gatherers', id: 'lh:config:requireGatherers'};
+ log.time(status, 'verbose');
 
  const coreList = Runner.getGathererList();
  const fullPasses = passes.map(pass => {
@@ -853,7 +861,7 @@ class Config {
 
  return Object.assign(pass, {gatherers: mergedDefns});
  });
-
+ log.timeEnd(status);
  return fullPasses;
  }
 }

lighthouse-core/gather/computed/computed-artifact.js

@@ -6,6 +6,7 @@
 'use strict';
 
 const ArbitraryEqualityMap = require('../../lib/arbitrary-equality-map');
+const log = require('lighthouse-logger');
 
 class ComputedArtifact {
  /**
@@ -59,12 +60,15 @@ class ComputedArtifact {
  return computed;
  }
 
+ const status = {msg: `Computing artifact: ${this.name}`, id: `lh:computed:${this.name}`};
+ log.time(status, 'verbose');
  // Need to cast since `this.compute_(...)` returns the concrete return type
  // of the base class's compute_, not the called derived class's.
  const artifactPromise = /** @type {ReturnType<this['compute_']>} */ (
  this.compute_(requiredArtifacts, this._allComputedArtifacts));
  this._cache.set(requiredArtifacts, artifactPromise);
 
+ artifactPromise.then(() => log.timeEnd(status));
  return artifactPromise;
  }
 }

lighthouse-core/gather/driver.js

@@ -136,25 +136,35 @@ class Driver {
  * @return {Promise<LH.Crdp.Browser.GetVersionResponse & {milestone: number}>}
  */
  async getBrowserVersion() {
+ const status = {msg: 'Getting browser version', id: 'lh:gather:getVersion'};
+ log.time(status, 'verbose');
  const version = await this.sendCommand('Browser.getVersion');
  const match = version.product.match(/\/(\d+)/); // eg 'Chrome/71.0.3577.0'
  const milestone = match ? parseInt(match[1]) : 0;
+ log.timeEnd(status);
  return Object.assign(version, {milestone});
  }
 
  /**
  * Computes the ULTRADUMB™ benchmark index to get a rough estimate of device class.
  * @return {Promise<number>}
  */
- getBenchmarkIndex() {
- return this.evaluateAsync(`(${pageFunctions.ultradumbBenchmarkString})()`);
+ async getBenchmarkIndex() {
+ const status = {msg: 'Benchmarking machine', id: 'lh:gather:getBenchmarkIndex'};
+ log.time(status);
+ const indexVal = await this.evaluateAsync(`(${pageFunctions.ultradumbBenchmarkString})()`);
+ log.timeEnd(status);
+ return indexVal;
  }
 
  /**
  * @return {Promise<void>}
  */
- connect() {
- return this._connection.connect();
+ async connect() {
+ const status = {msg: 'Connecting to browser', id: 'lh:init:connect'};
+ log.time(status);
+ await this._connection.connect();
+ log.timeEnd(status);
  }
 
  /**

lighthouse-core/gather/gather-runner.js

@@ -76,8 +76,11 @@ class GatherRunner {
  url = constants.defaultPassConfig.blankPage,
  duration = constants.defaultPassConfig.blankDuration
  ) {
+ const status = {msg: 'Resetting state with about:blank', id: 'lh:gather:loadBlank'};
+ log.time(status);
  await driver.gotoURL(url);
  await new Promise(resolve => setTimeout(resolve, duration));
+ log.timeEnd(status);
  }
 
  /**
@@ -103,7 +106,8 @@ class GatherRunner {
  * @return {Promise<void>}
  */
  static async setupDriver(driver, options) {
- log.log('status', 'Initializing…');
+ const status = {msg: 'Initializing…', id: 'lh:gather:setupDriver'};
+ log.time(status);
  const resetStorage = !options.settings.disableStorageReset;
  await driver.assertNoSameOriginServiceWorkerClients(options.requestedUrl);
  await driver.beginEmulation(options.settings);
@@ -113,21 +117,27 @@ class GatherRunner {
  await driver.dismissJavaScriptDialogs();
  await driver.listenForSecurityStateChanges();
  if (resetStorage) await driver.clearDataForOrigin(options.requestedUrl);
+ log.timeEnd(status);
  }
 
  /**
  * @param {Driver} driver
  * @return {Promise<void>}
  */
- static disposeDriver(driver) {
- log.log('status', 'Disconnecting from browser...');
- return driver.disconnect().catch(err => {
+ static async disposeDriver(driver) {
+ const status = {msg: 'Disconnecting from browser...', id: 'lh:gather:disconnect'};
+
+ log.time(status);
+ try {
+ await driver.disconnect();
+ } catch (err) {
  // Ignore disconnecting error if browser was already closed.
  // See https://github.com/GoogleChrome/lighthouse/issues/1583
  if (!(/close\/.*status: 500$/.test(err.message))) {
  log.error('GatherRunner disconnect', err.message);
  }
- });
+ }
+ log.timeEnd(status);
  }
 
  /**
@@ -182,6 +192,8 @@ class GatherRunner {
  * @return {Promise<void>}
  */
  static async beforePass(passContext, gathererResults) {
+ const bpStatus = {msg: `Running beforePass methods`, id: `lh:gather:beforePass`};
+ log.time(bpStatus, 'verbose');
  const blockedUrls = (passContext.passConfig.blockedUrlPatterns || [])
  .concat(passContext.settings.blockedUrlPatterns || []);
 
@@ -195,10 +207,17 @@ class GatherRunner {
  const gatherer = gathererDefn.instance;
  // Abuse the passContext to pass through gatherer options
  passContext.options = gathererDefn.options || {};
+ const status = {
+ msg: `Retrieving setup: ${gatherer.name}`,
+ id: `lh:gather:beforePass:${gatherer.name}`,
+ };
+ log.time(status, 'verbose');
  const artifactPromise = Promise.resolve().then(_ => gatherer.beforePass(passContext));
  gathererResults[gatherer.name] = [artifactPromise];
  await artifactPromise.catch(() => {});
+ log.timeEnd(status);
  }
+ log.timeEnd(bpStatus);
  }
 
  /**
@@ -217,9 +236,12 @@ class GatherRunner {
  const recordTrace = config.recordTrace;
  const isPerfRun = !settings.disableStorageReset && recordTrace && config.useThrottling;
 
- const gatherernames = gatherers.map(g => g.instance.name).join(', ');
- const status = 'Loading page & waiting for onload';
- log.log('status', status, gatherernames);
+ const status = {
+ msg: 'Loading page & waiting for onload',
+ id: 'lh:gather:loadPage',
+ args: [gatherers.map(g => g.instance.name).join(', ')],
+ };
+ log.time(status);
 
  // Clear disk & memory cache if it's a perf run
  if (isPerfRun) await driver.cleanBrowserCaches();
@@ -230,19 +252,28 @@ class GatherRunner {
 
  // Navigate.
  await GatherRunner.loadPage(driver, passContext);
- log.log('statusEnd', status);
+ log.timeEnd(status);
 
+ const pStatus = {msg: `Running pass methods`, id: `lh:gather:pass`};
+ log.time(pStatus, 'verbose');
  for (const gathererDefn of gatherers) {
  const gatherer = gathererDefn.instance;
  // Abuse the passContext to pass through gatherer options
  passContext.options = gathererDefn.options || {};
+ const status = {
+ msg: `Retrieving in-page: ${gatherer.name}`,
+ id: `lh:gather:pass:${gatherer.name}`,
+ };
+ log.time(status);
  const artifactPromise = Promise.resolve().then(_ => gatherer.pass(passContext));
 
  const gathererResult = gathererResults[gatherer.name] || [];
  gathererResult.push(artifactPromise);
  gathererResults[gatherer.name] = gathererResult;
  await artifactPromise.catch(() => {});
+ log.timeEnd(status);
  }
+ log.timeEnd(pStatus);
  }
 
  /**
@@ -260,16 +291,20 @@ class GatherRunner {
 
  let trace;
  if (config.recordTrace) {
- log.log('status', 'Retrieving trace');
+ const status = {msg: 'Retrieving trace', id: `lh:gather:getTrace`};
+ log.time(status);
  trace = await driver.endTrace();
- log.verbose('statusEnd', 'Retrieving trace');
+ log.timeEnd(status);
  }
 
- const status = 'Retrieving devtoolsLog and network records';
- log.log('status', status);
+ const status = {
+ msg: 'Retrieving devtoolsLog & network records',
+ id: `lh:gather:getDevtoolsLog`,
+ };
+ log.time(status);
  const devtoolsLog = driver.endDevtoolsLog();
  const networkRecords = NetworkRecorder.recordsFromLogs(devtoolsLog);
- log.verbose('statusEnd', status);
+ log.timeEnd(status);
 
  let pageLoadError = GatherRunner.getPageLoadError(passContext.url, networkRecords);
  // If the driver was offline, a page load error is expected, so do not save it.
@@ -290,13 +325,18 @@ class GatherRunner {
  trace,
  };
 
+ const apStatus = {msg: `Running afterPass methods`, id: `lh:gather:afterPass`};
  // Disable throttling so the afterPass analysis isn't throttled
  await driver.setThrottling(passContext.settings, {useThrottling: false});
+ log.time(apStatus, 'verbose');
 
  for (const gathererDefn of gatherers) {
  const gatherer = gathererDefn.instance;
- const status = `Retrieving: ${gatherer.name}`;
- log.log('status', status);
+ const status = {
+ msg: `Retrieving: ${gatherer.name}`,
+ id: `lh:gather:afterPass:${gatherer.name}`,
+ };
+ log.time(status);
 
  // Add gatherer options to the passContext.
  passContext.options = gathererDefn.options || {};
@@ -311,8 +351,9 @@ class GatherRunner {
  gathererResult.push(artifactPromise);
  gathererResults[gatherer.name] = gathererResult;
  await artifactPromise.catch(() => {});
- log.verbose('statusEnd', status);
+ log.timeEnd(status);
  }
+ log.timeEnd(apStatus);
 
  // Resolve on tracing data using passName from config.
  return passData;
@@ -355,6 +396,9 @@ class GatherRunner {
  // Take only unique LighthouseRunWarnings.
  baseArtifacts.LighthouseRunWarnings = Array.from(new Set(baseArtifacts.LighthouseRunWarnings));
 
+ // Take the timing entries we've gathered so far.
+ baseArtifacts.Timing = log.getTimeEntries();
+
  // TODO(bckenny): correct Partial<LH.GathererArtifacts> at this point to drop cast.
  return /** @type {LH.Artifacts} */ ({...baseArtifacts, ...gathererArtifacts});
  }
@@ -374,6 +418,7 @@ class GatherRunner {
  devtoolsLogs: {},
  settings: options.settings,
  URL: {requestedUrl: options.requestedUrl, finalUrl: ''},
+ Timing: [],
  };
  }
 

lighthouse-core/lib/asset-saver.js

@@ -63,6 +63,11 @@ async function loadArtifacts(basePath) {
  artifacts.traces[passName] = Array.isArray(trace) ? {traceEvents: trace} : trace;
  });
 
+ if (Array.isArray(artifacts.Timing)) {
+ // Any Timing entries in saved artifacts will have a different timeOrigin than the auditing phase
+ // The `gather` prop is read later in generate-timing-trace and they're added to a separate track of trace events
+ artifacts.Timing.forEach(entry => (entry.gather = true));
+ }
  return artifacts;
 }
 
@@ -74,6 +79,8 @@ async function loadArtifacts(basePath) {
  * @return {Promise<void>}
  */
 async function saveArtifacts(artifacts, basePath) {
+ const status = {msg: 'Saving artifacts', id: 'lh:assetSaver:saveArtifacts'};
+ log.time(status);
  mkdirp.sync(basePath);
  rimraf.sync(`${basePath}/*${traceSuffix}`);
  rimraf.sync(`${basePath}/${artifactsFilename}`);
@@ -95,6 +102,7 @@ async function saveArtifacts(artifacts, basePath) {
  const restArtifactsString = JSON.stringify(restArtifacts, null, 2);
  fs.writeFileSync(`${basePath}/${artifactsFilename}`, restArtifactsString, 'utf8');
  log.log('Artifacts saved to disk in folder:', basePath);
+ log.timeEnd(status);
 }
 
 /**