misc(logger): declaratively mark functions for timings

clients/devtools-entry.js

@@ -7,7 +7,7 @@
 
 const lighthouse = require('../lighthouse-core/index.js');
 const RawProtocol = require('../lighthouse-core/gather/connections/raw.js');
-const log = require('lighthouse-logger');
+const log = require('../lighthouse-core/lib/log');
 
 /** @typedef {import('../lighthouse-core/gather/connections/connection.js')} Connection */
 

clients/extension/scripts/extension-entry.js

@@ -11,7 +11,7 @@ const defaultConfig = require('../../../lighthouse-core/config/default-config.js
 const i18n = require('../../../lighthouse-core/lib/i18n/i18n.js');
 
 const ExtensionProtocol = require('../../../lighthouse-core/gather/connections/extension');
-const log = require('lighthouse-logger');
+const log = require('../../../lighthouse-core/lib/log');
 
 /** @typedef {import('../../../lighthouse-core/gather/connections/connection.js')} Connection */
 

jest.config.js

@@ -11,6 +11,7 @@ module.exports = {
   collectCoverageFrom: [
     '**/lighthouse-core/**/*.js',
     '**/lighthouse-cli/**/*.js',
+    '**/lighthouse-logger/**/*.js',
     '!**/test/',
     '!**/scripts/',
   ],
@@ -19,5 +20,6 @@ module.exports = {
   testMatch: [
     '**/lighthouse-core/**/*-test.js',
     '**/lighthouse-cli/**/*-test.js',
+    '**/lighthouse-logger/**/*-test.js',
   ],
 };

lighthouse-cli/bin.js

@@ -27,7 +27,7 @@ const getFlags = require('./cli-flags.js').getFlags;
 const runLighthouse = require('./run').runLighthouse;
 const generateConfig = require('../lighthouse-core/index.js').generateConfig;
 
-const log = require('lighthouse-logger');
+const log = require('../lighthouse-core/lib/log');
 const pkg = require('../package.json');
 const Sentry = require('../lighthouse-core/lib/sentry');
 

lighthouse-cli/printer.js

@@ -6,7 +6,7 @@
 'use strict';
 
 const fs = require('fs');
-const log = require('lighthouse-logger');
+const log = require('../lighthouse-core/lib/log');
 
 /**
  * An enumeration of acceptable output modes:

lighthouse-cli/run.js

@@ -14,7 +14,7 @@ const ChromeLauncher = require('chrome-launcher');
 
 const yargsParser = require('yargs-parser');
 const lighthouse = require('../lighthouse-core');
-const log = require('lighthouse-logger');
+const log = require('../lighthouse-core/lib/log');
 const getFilenamePrefix = require('../lighthouse-core/lib/file-namer').getFilenamePrefix;
 const assetSaver = require('../lighthouse-core/lib/asset-saver');
 

lighthouse-cli/sentry-prompt.js

@@ -8,7 +8,7 @@
 const Configstore = require('configstore');
 const inquirer = require('inquirer');
 
-const log = require('lighthouse-logger');
+const log = require('../lighthouse-core/lib/log');
 
 const MAXIMUM_WAIT_TIME = 20 * 1000;
 

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

@@ -10,7 +10,7 @@ const {promisify} = require('util');
 const execAsync = promisify(require('child_process').exec);
 
 const {server, serverForOffline} = require('../fixtures/static-server');
-const log = require('lighthouse-logger');
+const log = require('../lib/log');
 
 const purpleify = str => `${log.purple}${str}${log.reset}`;
 const smokehouseDir = 'lighthouse-cli/test/smokehouse/';

lighthouse-cli/test/smokehouse/smokehouse.js

@@ -12,7 +12,7 @@ const fs = require('fs');
 const path = require('path');
 const spawnSync = require('child_process').spawnSync;
 const yargs = require('yargs');
-const log = require('lighthouse-logger');
+const log = require('../lib/log');
 
 const PROTOCOL_TIMEOUT_EXIT_CODE = 67;
 const PAGE_HUNG_EXIT_CODE = 68;

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

@@ -17,7 +17,7 @@
  */
 
 const makeComputedArtifact = require('./computed-artifact.js');
-const log = require('lighthouse-logger');
+const log = require('../lib/log.js');
 const TracingProcessor = require('../lib/traces/tracing-processor.js');
 const LHError = require('../lib/lh-error.js');
 const Sentry = require('../lib/sentry.js');

lighthouse-core/config/config.js

@@ -12,7 +12,7 @@ const constants = require('./constants.js');
 const i18n = require('./../lib/i18n/i18n.js');
 
 const isDeepEqual = require('lodash.isequal');
-const log = require('lighthouse-logger');
+const log = require('../lib/log');
 const path = require('path');
 const Audit = require('../audits/audit.js');
 const Runner = require('../runner.js');
@@ -756,8 +756,6 @@ 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;
@@ -789,7 +787,6 @@ class Config {
 
     const mergedAuditDefns = mergeOptionsOfItems(auditDefns);
     mergedAuditDefns.forEach(audit => assertValidAudit(audit.implementation, audit.path));
-    log.timeEnd(status);
     return mergedAuditDefns;
   }
 
@@ -831,8 +828,6 @@ 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 => {
@@ -866,9 +861,19 @@ class Config {
 
       return Object.assign(pass, {gatherers: mergedDefns});
     });
-    log.timeEnd(status);
     return fullPasses;
   }
 }
 
+log.timeDecorateClass(Config, {
+  requireAudits: {
+    msg: 'Requiring audits',
+    id: 'lh:config:requireAudits',
+  },
+  requireGatherers: {
+    msg: 'Requiring gatherers',
+    id: 'lh:config:requireGatherers',
+  },
+});
+
 module.exports = Config;

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

@@ -0,0 +1,95 @@
+/**
+ * @license Copyright 2016 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';
+
+const ArbitraryEqualityMap = require('../../lib/arbitrary-equality-map');
+const log = require('../../lib/log');
+
+class ComputedArtifact {
+  /**
+   * @param {*} allComputedArtifacts
+   */
+  constructor(allComputedArtifacts) {
+    const cache = new ArbitraryEqualityMap();
+    cache.setEqualityFn(ArbitraryEqualityMap.deepEquals);
+
+    /** @type {Map<FirstParamType<this['compute_']>, Promise<ReturnType<this['compute_']>>>} */
+    // @ts-ignore cache is close enough to a Map for our purposes (but e.g. no [Symbol.toStringTag])
+    this._cache = cache;
+
+    /** @type {*} */
+    this._allComputedArtifacts = allComputedArtifacts;
+  }
+
+  /**
+   * @return {string}
+   */
+  get name() {
+    throw new Error('name getter not implemented for computed artifact ' + this.constructor.name);
+  }
+
+  /* eslint-disable no-unused-vars */
+
+  /**
+   * Override with more specific `artifact` and return type to implement a
+   * computed artifact.
+   * @param {*} artifact Input to computation.
+   * @param {*} allComputedArtifacts Access to all computed artifacts.
+   * @return {Promise<*>}
+   * @throws {Error}
+   */
+  async compute_(artifact, allComputedArtifacts) {
+    throw new Error('compute_() not implemented for computed artifact ' + this.name);
+  }
+
+  /* eslint-enable no-unused-vars */
+
+  /**
+   * Request a computed artifact, caching the result on the input artifact.
+   * Types of `requiredArtifacts` and the return value are derived from the
+   * `compute_` method on classes derived from ComputedArtifact.
+   * @param {FirstParamType<this['compute_']>} requiredArtifacts
+   * @return {Promise<ReturnType<this['compute_']>>}
+   */
+  async request(requiredArtifacts) {
+    const computed = this._cache.get(requiredArtifacts);
+    if (computed) {
+      return computed;
+    }
+
+    // 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.makeRequest(requiredArtifacts));
+    this._cache.set(requiredArtifacts, artifactPromise);
+    return artifactPromise;
+  }
+
+  /**
+   * Request a computed artifact, caching the result on the input artifact.
+   * Types of `requiredArtifacts` and the return value are derived from the
+   * `compute_` method on classes derived from ComputedArtifact.
+   * @param {FirstParamType<this['compute_']>} requiredArtifacts
+   * @return {Promise<ReturnType<this['compute_']>>}
+   */
+  makeRequest(requiredArtifacts) {
+    return this.compute_(requiredArtifacts, this._allComputedArtifacts);
+  }
+}
+
+log.timeDecorateClass(ComputedArtifact.prototype, {
+  makeRequest: {
+    msg: function() {
+      return `Computing artifact: ${this.name}`;
+    },
+    id: function() {
+      return `lh:computed:${this.name}`;
+    },
+    timeStartLogLevel: 'verbose',
+  },
+});
+
+module.exports = ComputedArtifact;

lighthouse-core/gather/connections/connection.js

@@ -6,7 +6,7 @@
 'use strict';
 
 const EventEmitter = require('events').EventEmitter;
-const log = require('lighthouse-logger');
+const log = require('../../lib/log');
 const LHError = require('../../lib/lh-error');
 
 // TODO(bckenny): CommandCallback properties should be tied by command type after

lighthouse-core/gather/connections/cri.js

@@ -8,7 +8,7 @@
 const Connection = require('./connection.js');
 const WebSocket = require('ws');
 const http = require('http');
-const log = require('lighthouse-logger');
+const log = require('../../lib/log');
 
 const DEFAULT_HOSTNAME = 'localhost';
 const CONNECT_TIMEOUT = 10000;

lighthouse-core/gather/connections/extension.js

@@ -8,7 +8,7 @@
 'use strict';
 
 const Connection = require('./connection.js');
-const log = require('lighthouse-logger');
+const log = require('../../lib/log');
 
 /* globals chrome */
 

lighthouse-core/gather/driver.js

@@ -13,8 +13,7 @@ const NetworkRequest = require('../lib/network-request');
 const EventEmitter = require('events').EventEmitter;
 const URL = require('../lib/url-shim');
 const constants = require('../config/constants');
-
-const log = require('lighthouse-logger');
+const log = require('../lib/log');
 const DevtoolsLog = require('./devtools-log');
 
 const pageFunctions = require('../lib/page-functions.js');
@@ -136,35 +135,25 @@ 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});
+    return {...version, milestone};
   }
 
   /**
    * Computes the ULTRADUMB™ benchmark index to get a rough estimate of device class.
    * @return {Promise<number>}
    */
   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 this.evaluateAsync(`(${pageFunctions.ultradumbBenchmarkString})()`);
   }
 
   /**
    * @return {Promise<void>}
    */
   async connect() {
-    const status = {msg: 'Connecting to browser', id: 'lh:init:connect'};
-    log.time(status);
-    await this._connection.connect();
-    log.timeEnd(status);
+    return this._connection.connect();
   }
 
   /**
@@ -1318,4 +1307,19 @@ class Driver {
   }
 }
 
+log.timeDecorateClass(Driver.prototype, {
+  getBenchmarkIndex: {
+    msg: 'Benchmarking machine',
+    id: 'lh:gather:getBenchmarkIndex',
+  },
+  getBrowserVersion: {
+    msg: 'Getting browser version',
+    id: 'lh:gather:getVersion',
+  },
+  connect: {
+    msg: 'Connecting to browser',
+    id: 'lh:init:connect',
+  },
+});
+
 module.exports = Driver;