core(simulator): convert node timings to trace

lighthouse-core/gather/computed/metrics/lantern-metric.js

@@ -73,6 +73,7 @@ class LanternMetricArtifact extends ComputedArtifact {
    */
   async computeMetricWithGraphs(data, artifacts, extras) {
     const {trace, devtoolsLog, settings} = data;
+    const metricName = this.name.replace('Lantern', '');
     const graph = await artifacts.requestPageDependencyGraph({trace, devtoolsLog});
     const traceOfTab = await artifacts.requestTraceOfTab(trace);
     /** @type {Simulator} */
@@ -82,9 +83,14 @@ class LanternMetricArtifact extends ComputedArtifact {
     const optimisticGraph = this.getOptimisticGraph(graph, traceOfTab);
     const pessimisticGraph = this.getPessimisticGraph(graph, traceOfTab);
 
-    const optimisticSimulation = simulator.simulate(optimisticGraph);
-    const optimisticFlexSimulation = simulator.simulate(optimisticGraph, {flexibleOrdering: true});
-    const pessimisticSimulation = simulator.simulate(pessimisticGraph);
+    let simulateOptions = {label: `optimistic${metricName}`};
+    const optimisticSimulation = simulator.simulate(optimisticGraph, simulateOptions);
+
+    simulateOptions = {label: `optimisticFlex${metricName}`, flexibleOrdering: true};
+    const optimisticFlexSimulation = simulator.simulate(optimisticGraph, simulateOptions);
+
+    simulateOptions = {label: `pessimistic${metricName}`};
+    const pessimisticSimulation = simulator.simulate(pessimisticGraph, simulateOptions);
 
     const optimisticEstimate = this.getEstimateFromSimulation(
       optimisticSimulation.timeInMs < optimisticFlexSimulation.timeInMs ?

lighthouse-core/lib/asset-saver.js

@@ -9,6 +9,8 @@ const fs = require('fs');
 const path = require('path');
 const log = require('lighthouse-logger');
 const stream = require('stream');
+const Simulator = require('./dependency-graph/simulator/simulator');
+const lanternTraceSaver = require('./lantern-trace-saver');
 const Metrics = require('./traces/pwmetrics-events');
 const TraceParser = require('./traces/trace-parser');
 const rimraf = require('rimraf');
@@ -255,6 +257,22 @@ function saveTrace(traceData, traceFilename) {
   });
 }
 
+/**
+ * @param {string} pathWithBasename
+ * @return {Promise<void>}
+ */
+async function saveLanternDebugTraces(pathWithBasename) {
+  if (!process.env.LANTERN_DEBUG) return;
+
+  for (const [label, nodeTimings] of Simulator.ALL_NODE_TIMINGS) {
+    if (lanternTraceSaver.simulationNamesToIgnore.includes(label)) continue;
+
+    const traceFilename = `${pathWithBasename}-${label}${traceSuffix}`;
+    await saveTrace(lanternTraceSaver.convertNodeTimingsToTrace(nodeTimings), traceFilename);
+    log.log('saveAssets', `${label} lantern trace file streamed to disk: ${traceFilename}`);
+  }
+}
+
 /**
  * Writes trace(s) and associated asset(s) to disk.
  * @param {LH.Artifacts} artifacts
@@ -284,6 +302,7 @@ async function saveAssets(artifacts, audits, pathWithBasename) {
   });
 
   await Promise.all(saveAll);
+  await saveLanternDebugTraces(pathWithBasename);
 }
 
 /**

lighthouse-core/lib/dependency-graph/simulator/simulator.js

@@ -26,6 +26,9 @@ const NodeState = {
   Complete: 3,
 };
 
+/** @type {Map<string, LH.Gatherer.Simulation.Result['nodeTimings']>} */
+const ALL_SIMULATION_NODE_TIMINGS = new Map();
+
 class Simulator {
   /**
    * @param {LH.Gatherer.Simulation.Options} [options]
@@ -369,15 +372,19 @@ class Simulator {
    * connection).
    *
    * @param {Node} graph
-   * @param {{flexibleOrdering?: boolean}=} options
+   * @param {{flexibleOrdering?: boolean, label?: string}=} options
    * @return {LH.Gatherer.Simulation.Result}
    */
   simulate(graph, options) {
     if (Node.hasCycle(graph)) {
       throw new Error('Cannot simulate graph with cycle');
     }
 
-    options = Object.assign({flexibleOrdering: false}, options);
+    options = Object.assign({
+      label: undefined,
+      flexibleOrdering: false,
+    }, options);
+
     // initialize the necessary data containers
     this._flexibleOrdering = !!options.flexibleOrdering;
     this._initializeConnectionPool(graph);
@@ -429,11 +436,19 @@ class Simulator {
       }
     }
 
+    const nodeTimings = this._computeFinalNodeTimings();
+    ALL_SIMULATION_NODE_TIMINGS.set(options.label || 'unlabeled', nodeTimings);
+
     return {
       timeInMs: totalElapsedTime,
-      nodeTimings: this._computeFinalNodeTimings(),
+      nodeTimings,
     };
   }
+
+  /** @return {Map<string, LH.Gatherer.Simulation.Result['nodeTimings']>} */
+  static get ALL_NODE_TIMINGS() {
+    return ALL_SIMULATION_NODE_TIMINGS;
+  }
 }
 
 module.exports = Simulator;

lighthouse-core/lib/lantern-trace-saver.js

@@ -0,0 +1,206 @@
+/**
+ * @license Copyright 2018 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';
+
+/**
+ * @param {LH.Gatherer.Simulation.Result['nodeTimings']} nodeTimings
+ * @return {LH.Trace}
+ */
+function convertNodeTimingsToTrace(nodeTimings) {
+  /** @type {LH.TraceEvent[]} */
+  const traceEvents = [];
+  const baseTs = 1e9;
+  const baseEvent = {pid: 1, tid: 1, cat: 'devtools.timeline'};
+  const frame = 'A00001';
+  /** @param {number} ms */
+  const toMicroseconds = ms => baseTs + ms * 1000;
+
+  traceEvents.push(createFakeTracingStartedEvent());
+  traceEvents.push({...createFakeTracingStartedEvent(), name: 'TracingStartedInBrowser'});
+
+  // Create a fake requestId counter
+  let requestId = 1;
+  let lastEventEndTime = 0;
+  for (const [node, timing] of nodeTimings.entries()) {
+    lastEventEndTime = Math.max(lastEventEndTime, timing.endTime);
+    if (node.type === 'cpu') {
+      // Represent all CPU work that was bundled in a task as an EvaluateScript event
+      const cpuNode = /** @type {LH.Gatherer.Simulation.GraphCPUNode} */ (node);
+      traceEvents.push(...createFakeTaskEvents(cpuNode, timing));
+    } else {
+      const networkNode = /** @type {LH.Gatherer.Simulation.GraphNetworkNode} */ (node);
+      // Ignore data URIs as they don't really add much value
+      if (/^data/.test(networkNode.record.url)) continue;
+      traceEvents.push(...createFakeNetworkEvents(networkNode.record, timing));
+    }
+  }
+
+  // Create a fake task event ~1s after the trace ends for a sane default bounds in DT
+  traceEvents.push(
+    ...createFakeTaskEvents(
+      // @ts-ignore
+      {childEvents: [], event: {}},
+      {
+        startTime: lastEventEndTime + 1000,
+        endTime: lastEventEndTime + 1001,
+      }
+    )
+  );
+
+  return {traceEvents};
+
+  /**
+   * @return {LH.TraceEvent}
+   */
+  function createFakeTracingStartedEvent() {
+    const argsData = {
+      frameTreeNodeId: 1,
+      sessionId: '1.1',
+      page: frame,
+      persistentIds: true,
+      frames: [{frame, url: 'about:blank', name: '', processId: 1}],
+    };
+
+    return {
+      ...baseEvent,
+      ts: baseTs - 1e5,
+      ph: 'I',
+      s: 't',
+      cat: 'disabled-by-default-devtools.timeline',
+      name: 'TracingStartedInPage',
+      args: {data: argsData},
+      dur: 0,
+    };
+  }
+
+  /**
+   * @param {LH.Gatherer.Simulation.GraphCPUNode} cpuNode
+   * @param {{startTime: number, endTime: number}} timing
+   * @return {LH.TraceEvent[]}
+   */
+  function createFakeTaskEvents(cpuNode, timing) {
+    const argsData = {
+      url: '',
+      frame,
+      lineNumber: 0,
+      columnNumber: 0,
+    };
+
+    const eventTs = toMicroseconds(timing.startTime);
+
+    /** @type {LH.TraceEvent[]} */
+    const events = [
+      {
+        ...baseEvent,
+        ph: 'X',
+        name: 'Task',
+        ts: eventTs,
+        dur: (timing.endTime - timing.startTime) * 1000,
+        args: {data: argsData},
+      },
+    ];
+
+    const nestedBaseTs = cpuNode.event.ts || 0;
+    const multiplier = (timing.endTime - timing.startTime) * 1000 / cpuNode.event.dur;
+    // https://github.com/ChromeDevTools/devtools-frontend/blob/5429ac8a61ad4fa/front_end/timeline_model/TimelineModel.js#L1129-L1130
+    const netReqEvents = new Set(['ResourceSendRequest', 'ResourceFinish',
+      'ResourceReceiveResponse', 'ResourceReceivedData']);
+    for (const event of cpuNode.childEvents) {
+      if (netReqEvents.has(event.name)) continue;
+      const ts = eventTs + (event.ts - nestedBaseTs) * multiplier;
+      const newEvent = {...event, ...{pid: baseEvent.pid, tid: baseEvent.tid}, ts};
+      if (event.dur) newEvent.dur = event.dur * multiplier;
+      events.push(newEvent);
+    }
+
+    return events;
+  }
+
+  /**
+   * @param {LH.WebInspector.NetworkRequest} record
+   * @param {LH.Gatherer.Simulation.NodeTiming} timing
+   * @return {LH.TraceEvent[]}
+   */
+  function createFakeNetworkEvents(record, timing) {
+    requestId++;
+
+    // 0ms requests get super-messed up rendering
+    // Use 0.3ms instead so they're still hoverable, https://github.com/GoogleChrome/lighthouse/pull/5350#discussion_r194563201
+    let {startTime, endTime} = timing; // eslint-disable-line prefer-const
+    if (startTime === endTime) endTime += 0.3;
+
+    const requestData = {requestId: requestId.toString(), frame};
+    /** @type {Omit<LH.TraceEvent, 'name'|'ts'|'args'>} */
+    const baseRequestEvent = {...baseEvent, ph: 'I', s: 't', dur: 0};
+
+    const sendRequestData = {
+      ...requestData,
+      requestMethod: record.requestMethod,
+      url: record.url,
+      priority: record.priority(),
+    };
+
+    const receiveResponseData = {
+      ...requestData,
+      statusCode: record.statusCode,
+      mimeType: record._mimeType,
+      encodedDataLength: record._transferSize,
+      fromCache: record._fromDiskCache,
+      fromServiceWorker: record._fetchedViaServiceWorker,
+    };
+
+    const resourceFinishData = {
+      ...requestData,
+      decodedBodyLength: record._resourceSize,
+      didFail: !!record.failed,
+      finishTime: endTime,
+    };
+
+    /** @type {LH.TraceEvent[]} */
+    const events = [
+      {
+        ...baseRequestEvent,
+        name: 'ResourceSendRequest',
+        ts: toMicroseconds(startTime),
+        args: {data: sendRequestData},
+      },
+      {
+        ...baseRequestEvent,
+        name: 'ResourceFinish',
+        ts: toMicroseconds(endTime),
+        args: {data: resourceFinishData},
+      },
+    ];
+
+    if (!record.failed) {
+      events.push({
+        ...baseRequestEvent,
+        name: 'ResourceReceiveResponse',
+        ts: toMicroseconds((startTime + endTime) / 2),
+        args: {data: receiveResponseData},
+      });
+    }
+
+    return events;
+  }
+}
+
+module.exports = {
+  simulationNamesToIgnore: [
+    'unlabeled',
+    // These node timings should be nearly identical to the ones produced for Interactive
+    'optimisticFirstCPUIdle',
+    'optimisticFlexFirstCPUIdle',
+    'pessimisticFirstCPUIdle',
+    'optimisticSpeedIndex',
+    'optimisticFlexSpeedIndex',
+    'pessimisticSpeedIndex',
+    'optimisticEstimatedInputLatency',
+    'optimisticFlexEstimatedInputLatency',
+    'pessimisticEstimatedInputLatency',
+  ],
+  convertNodeTimingsToTrace,
+};

typings/externs.d.ts

@@ -160,6 +160,7 @@ declare global {
       ts: number;
       dur: number;
       ph: 'B'|'b'|'D'|'E'|'e'|'F'|'I'|'M'|'N'|'n'|'O'|'R'|'S'|'T'|'X';
+      s?: 't';
     }
 
     export interface DevToolsJsonTarget {