diff --git a/lighthouse-core/gather/computed/metrics/lantern-metric.js b/lighthouse-core/gather/computed/metrics/lantern-metric.js index 7585f68175cf..19f49611febc 100644 --- a/lighthouse-core/gather/computed/metrics/lantern-metric.js +++ b/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 ? diff --git a/lighthouse-core/lib/asset-saver.js b/lighthouse-core/lib/asset-saver.js index fd8c17c5a632..0b0ec8a183b6 100644 --- a/lighthouse-core/lib/asset-saver.js +++ b/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} + */ +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); } /** diff --git a/lighthouse-core/lib/dependency-graph/simulator/simulator.js b/lighthouse-core/lib/dependency-graph/simulator/simulator.js index 0c89a76240d9..1931f63b27e8 100644 --- a/lighthouse-core/lib/dependency-graph/simulator/simulator.js +++ b/lighthouse-core/lib/dependency-graph/simulator/simulator.js @@ -26,6 +26,9 @@ const NodeState = { Complete: 3, }; +/** @type {Map} */ +const ALL_SIMULATION_NODE_TIMINGS = new Map(); + class Simulator { /** * @param {LH.Gatherer.Simulation.Options} [options] @@ -369,7 +372,7 @@ class Simulator { * connection). * * @param {Node} graph - * @param {{flexibleOrdering?: boolean}=} options + * @param {{flexibleOrdering?: boolean, label?: string}=} options * @return {LH.Gatherer.Simulation.Result} */ simulate(graph, options) { @@ -377,7 +380,11 @@ class Simulator { 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} */ + static get ALL_NODE_TIMINGS() { + return ALL_SIMULATION_NODE_TIMINGS; + } } module.exports = Simulator; diff --git a/lighthouse-core/lib/lantern-trace-saver.js b/lighthouse-core/lib/lantern-trace-saver.js new file mode 100644 index 000000000000..1c3239e11a12 --- /dev/null +++ b/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} */ + 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, +}; diff --git a/typings/externs.d.ts b/typings/externs.d.ts index 57a29c4b5dc9..b6678ae3ec15 100644 --- a/typings/externs.d.ts +++ b/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 {