From ddff3d6628da2fc36c9713ac183b7a5e040dfbf6 Mon Sep 17 00:00:00 2001 From: Patrick Hulce Date: Thu, 6 Jun 2019 18:29:21 -0500 Subject: [PATCH] core(tracehouse): merge tracing-processor with trace-of-tab --- docs/architecture.md | 2 +- .../metrics/cumulative-long-queuing-delay.js | 2 +- .../metrics/estimated-input-latency.js | 2 +- .../computed/metrics/first-cpu-idle.js | 2 +- .../computed/metrics/interactive.js | 2 +- .../computed/metrics/max-potential-fid.js | 2 +- lighthouse-core/computed/metrics/metric.js | 2 +- .../computed/page-dependency-graph.js | 2 +- lighthouse-core/computed/trace-of-tab.js | 31 +- lighthouse-core/lib/minify-trace.js | 5 +- .../lib/tracehouse/trace-processor.js | 324 +++++++++- .../lib/tracehouse/tracing-processor.js | 285 --------- .../computed/metrics/first-cpu-idle-test.js | 2 +- .../test/computed/trace-of-tab-test.js | 32 + .../lib/tracehouse/main-thread-tasks-test.js | 6 +- .../lib/tracehouse/trace-processor-test.js | 565 +++++++++++++----- .../lib/tracehouse/tracing-processor-test.js | 244 -------- 17 files changed, 781 insertions(+), 729 deletions(-) delete mode 100644 lighthouse-core/lib/tracehouse/tracing-processor.js delete mode 100644 lighthouse-core/test/lib/tracehouse/tracing-processor-test.js diff --git a/docs/architecture.md b/docs/architecture.md index a3ed283dfb1d..cf67e925ddc0 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -39,7 +39,7 @@ driver.sendCommand('Security.enable'); ## Understanding a Trace -`lighthouse-core/lib/tracehouse/trace-of-tab.js` and `lighthouse-core/lib/tracehouse/tracing-processor.js` provide the core transformation of a trace into more meaningful objects. Each raw trace event has a monotonically increasing timestamp in microseconds, a thread ID, a process ID, a duration in microseconds (potentially), and other applicable metadata properties such as the event type, the task name, the frame, etc. [Learn more about trace events](https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview). +`lighthouse-core/lib/tracehouse/trace-processor.js` provides the core transformation of a trace into more meaningful objects. Each raw trace event has a monotonically increasing timestamp in microseconds, a thread ID, a process ID, a duration in microseconds (potentially), and other applicable metadata properties such as the event type, the task name, the frame, etc. [Learn more about trace events](https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview). ### Example Trace Event ```js diff --git a/lighthouse-core/computed/metrics/cumulative-long-queuing-delay.js b/lighthouse-core/computed/metrics/cumulative-long-queuing-delay.js index da168907235f..18aa99d1561a 100644 --- a/lighthouse-core/computed/metrics/cumulative-long-queuing-delay.js +++ b/lighthouse-core/computed/metrics/cumulative-long-queuing-delay.js @@ -8,7 +8,7 @@ const makeComputedArtifact = require('../computed-artifact.js'); const ComputedMetric = require('./metric.js'); const LHError = require('../../lib/lh-error.js'); -const TracingProcessor = require('../../lib/tracehouse/tracing-processor.js'); +const TracingProcessor = require('../../lib/tracehouse/trace-processor.js'); const LanternCumulativeLongQueuingDelay = require('./lantern-cumulative-long-queuing-delay.js'); const TimetoInteractive = require('./interactive.js'); diff --git a/lighthouse-core/computed/metrics/estimated-input-latency.js b/lighthouse-core/computed/metrics/estimated-input-latency.js index a027667d9ee0..ef4bab2d6a6f 100644 --- a/lighthouse-core/computed/metrics/estimated-input-latency.js +++ b/lighthouse-core/computed/metrics/estimated-input-latency.js @@ -8,7 +8,7 @@ const makeComputedArtifact = require('../computed-artifact.js'); const ComputedMetric = require('./metric.js'); const LHError = require('../../lib/lh-error.js'); -const TracingProcessor = require('../../lib/tracehouse/tracing-processor.js'); +const TracingProcessor = require('../../lib/tracehouse/trace-processor.js'); const LanternEstimatedInputLatency = require('./lantern-estimated-input-latency.js'); const ROLLING_WINDOW_SIZE = 5000; diff --git a/lighthouse-core/computed/metrics/first-cpu-idle.js b/lighthouse-core/computed/metrics/first-cpu-idle.js index 202821e16568..ff85b08665b5 100644 --- a/lighthouse-core/computed/metrics/first-cpu-idle.js +++ b/lighthouse-core/computed/metrics/first-cpu-idle.js @@ -7,7 +7,7 @@ const makeComputedArtifact = require('../computed-artifact.js'); const ComputedMetric = require('./metric.js'); -const TracingProcessor = require('../../lib/tracehouse/tracing-processor.js'); +const TracingProcessor = require('../../lib/tracehouse/trace-processor.js'); const LHError = require('../../lib/lh-error.js'); const LanternFirstCPUIdle = require('./lantern-first-cpu-idle.js'); diff --git a/lighthouse-core/computed/metrics/interactive.js b/lighthouse-core/computed/metrics/interactive.js index cc7fbd05fcd5..c61ec510126c 100644 --- a/lighthouse-core/computed/metrics/interactive.js +++ b/lighthouse-core/computed/metrics/interactive.js @@ -10,7 +10,7 @@ const ComputedMetric = require('./metric.js'); const LanternInteractive = require('./lantern-interactive.js'); const NetworkRecorder = require('../../lib/network-recorder.js'); -const TracingProcessor = require('../../lib/tracehouse/tracing-processor.js'); +const TracingProcessor = require('../../lib/tracehouse/trace-processor.js'); const LHError = require('../../lib/lh-error.js'); const REQUIRED_QUIET_WINDOW = 5000; diff --git a/lighthouse-core/computed/metrics/max-potential-fid.js b/lighthouse-core/computed/metrics/max-potential-fid.js index 6fed0414e5c1..76db19c9ece0 100644 --- a/lighthouse-core/computed/metrics/max-potential-fid.js +++ b/lighthouse-core/computed/metrics/max-potential-fid.js @@ -9,7 +9,7 @@ const makeComputedArtifact = require('../computed-artifact.js'); const MetricArtifact = require('./metric.js'); const LanternMaxPotentialFID = require('./lantern-max-potential-fid.js'); const LHError = require('../../lib/lh-error.js'); -const TracingProcessor = require('../../lib/tracehouse/tracing-processor.js'); +const TracingProcessor = require('../../lib/tracehouse/trace-processor.js'); class MaxPotentialFID extends MetricArtifact { /** diff --git a/lighthouse-core/computed/metrics/metric.js b/lighthouse-core/computed/metrics/metric.js index 1b2457ff083e..64a4a8938aee 100644 --- a/lighthouse-core/computed/metrics/metric.js +++ b/lighthouse-core/computed/metrics/metric.js @@ -5,7 +5,7 @@ */ 'use strict'; -const TracingProcessor = require('../../lib/tracehouse/tracing-processor.js'); +const TracingProcessor = require('../../lib/tracehouse/trace-processor.js'); const TraceOfTab = require('../trace-of-tab.js'); const NetworkRecords = require('../network-records.js'); diff --git a/lighthouse-core/computed/page-dependency-graph.js b/lighthouse-core/computed/page-dependency-graph.js index 2f728eaf2ef5..df711b783acb 100644 --- a/lighthouse-core/computed/page-dependency-graph.js +++ b/lighthouse-core/computed/page-dependency-graph.js @@ -9,7 +9,7 @@ const makeComputedArtifact = require('./computed-artifact.js'); const NetworkNode = require('../lib/dependency-graph/network-node.js'); const CPUNode = require('../lib/dependency-graph/cpu-node.js'); const NetworkAnalyzer = require('../lib/dependency-graph/simulator/network-analyzer.js'); -const TracingProcessor = require('../lib/tracehouse/tracing-processor.js'); +const TracingProcessor = require('../lib/tracehouse/trace-processor.js'); const NetworkRequest = require('../lib/network-request.js'); const TraceOfTab = require('./trace-of-tab.js'); const NetworkRecords = require('./network-records.js'); diff --git a/lighthouse-core/computed/trace-of-tab.js b/lighthouse-core/computed/trace-of-tab.js index 7aa3ee252867..b8f572c89dd8 100644 --- a/lighthouse-core/computed/trace-of-tab.js +++ b/lighthouse-core/computed/trace-of-tab.js @@ -6,7 +6,34 @@ 'use strict'; const makeComputedArtifact = require('./computed-artifact.js'); -const TraceOfTab_ = require('../lib/tracehouse/trace-of-tab.js'); +const LHError = require('../lib/lh-error.js'); +const TraceProcessor = require('../lib/tracehouse/trace-processor.js'); + +// TraceProcessor throws generic errors, but we'd like our special localized and code-specific LHError +// objects to be thrown instead. +class LHTraceProcessor extends TraceProcessor { + /** + * @return {Error} + */ + static createNoNavstartError() { + return new LHError(LHError.errors.NO_NAVSTART); + } + + /** + * @return {Error} + */ + static createNoFirstContentfulPaintError() { + return new LHError(LHError.errors.NO_FCP); + } + + /** + * @return {Error} + */ + static createNoTracingStartedError() { + return new LHError(LHError.errors.NO_TRACING_STARTED); + } +} + class TraceOfTab { /** @@ -16,7 +43,7 @@ class TraceOfTab { * @return {Promise} */ static async compute_(trace) { - return TraceOfTab_.compute(trace); + return LHTraceProcessor.computeTraceOfTab(trace); } } diff --git a/lighthouse-core/lib/minify-trace.js b/lighthouse-core/lib/minify-trace.js index 0ff5bd8f34d5..afda69099d49 100644 --- a/lighthouse-core/lib/minify-trace.js +++ b/lighthouse-core/lib/minify-trace.js @@ -12,11 +12,10 @@ * See the following files for necessary events: * - lighthouse-core/computed/page-dependency-graph.js * - lighthouse-core/lib/dependency-graph/cpu-node.js - * - lighthouse-core/lib/tracehouse/trace-of-tab.js - * - lighthouse-core/lib/tracehouse/tracing-processor.js + * - lighthouse-core/lib/tracehouse/trace-processor.js */ -const TracingProcessor = require('./tracehouse/tracing-processor.js'); +const TracingProcessor = require('./tracehouse/trace-processor.js'); const toplevelTaskNames = new Set([ 'RunTask', // m71+ diff --git a/lighthouse-core/lib/tracehouse/trace-processor.js b/lighthouse-core/lib/tracehouse/trace-processor.js index 65cbc08de3de..2bc4c6feeca6 100644 --- a/lighthouse-core/lib/tracehouse/trace-processor.js +++ b/lighthouse-core/lib/tracehouse/trace-processor.js @@ -17,19 +17,49 @@ */ const log = require('lighthouse-logger'); -const TracingProcessor = require('./tracing-processor.js'); -const LHError = require('../lh-error.js'); -const Sentry = require('../sentry.js'); const ACCEPTABLE_NAVIGATION_URL_REGEX = /^(chrome|https?):/; -class TraceOfTab { +// The ideal input response latency, the time between the input task and the +// first frame of the response. +const BASE_RESPONSE_LATENCY = 16; +// m71+ We added RunTask to `disabled-by-default-lighthouse` +const SCHEDULABLE_TASK_TITLE_LH = 'RunTask'; +// m69-70 DoWork is different and we now need RunTask, see https://bugs.chromium.org/p/chromium/issues/detail?id=871204#c11 +const SCHEDULABLE_TASK_TITLE_ALT1 = 'ThreadControllerImpl::RunTask'; +// In m66-68 refactored to this task title, https://crrev.com/c/883346 +const SCHEDULABLE_TASK_TITLE_ALT2 = 'ThreadControllerImpl::DoWork'; +// m65 and earlier +const SCHEDULABLE_TASK_TITLE_ALT3 = 'TaskQueueManager::ProcessTaskFromWorkQueue'; + +class TraceProcessor { + /** + * @return {Error} + */ + static createNoNavstartError() { + return new Error('No navigationStart event found'); + } + + /** + * @return {Error} + */ + static createNoFirstContentfulPaintError() { + return new Error('No firstContentfulPaint event found'); + } + + /** + * @return {Error} + */ + static createNoTracingStartedError() { + return new Error('No tracingStartedInBrowser event found'); + } + /** * Returns true if the event is a navigation start event of a document whose URL seems valid. * * @param {LH.TraceEvent} event */ - static isNavigationStartOfInterest(event) { + static _isNavigationStartOfInterest(event) { return event.name === 'navigationStart' && (!event.args.data || !event.args.data.documentLoaderURL || ACCEPTABLE_NAVIGATION_URL_REGEX.test(event.args.data.documentLoaderURL)); @@ -39,7 +69,7 @@ class TraceOfTab { * @param {LH.TraceEvent[]} traceEvents * @param {(e: LH.TraceEvent) => boolean} filter */ - static filteredStableSort(traceEvents, filter) { + static _filteredStableSort(traceEvents, filter) { // create an array of the indices that we want to keep const indices = []; for (let srcIndex = 0; srcIndex < traceEvents.length; srcIndex++) { @@ -63,6 +93,259 @@ class TraceOfTab { return sorted; } + /** + * There should *always* be at least one top level event, having 0 typically means something is + * drastically wrong with the trace and we should just give up early and loudly. + * + * @param {LH.TraceEvent[]} events + */ + static assertHasToplevelEvents(events) { + const hasToplevelTask = events.some(this.isScheduleableTask); + if (!hasToplevelTask) { + throw new Error('Could not find any top level events'); + } + } + + + /** + * Calculate duration at specified percentiles for given population of + * durations. + * If one of the durations overlaps the end of the window, the full + * duration should be in the duration array, but the length not included + * within the window should be given as `clippedLength`. For instance, if a + * 50ms duration occurs 10ms before the end of the window, `50` should be in + * the `durations` array, and `clippedLength` should be set to 40. + * @see https://docs.google.com/document/d/1b9slyaB9yho91YTOkAQfpCdULFkZM9LqsipcX3t7He8/preview + * @param {!Array} durations Array of durations, sorted in ascending order. + * @param {number} totalTime Total time (in ms) of interval containing durations. + * @param {!Array} percentiles Array of percentiles of interest, in ascending order. + * @param {number=} clippedLength Optional length clipped from a duration overlapping end of window. Default of 0. + * @return {!Array<{percentile: number, time: number}>} + * @private + */ + static _riskPercentiles(durations, totalTime, percentiles, clippedLength = 0) { + let busyTime = 0; + for (let i = 0; i < durations.length; i++) { + busyTime += durations[i]; + } + busyTime -= clippedLength; + + // Start with idle time already complete. + let completedTime = totalTime - busyTime; + let duration = 0; + let cdfTime = completedTime; + const results = []; + + let durationIndex = -1; + let remainingCount = durations.length + 1; + if (clippedLength > 0) { + // If there was a clipped duration, one less in count since one hasn't started yet. + remainingCount--; + } + + // Find percentiles of interest, in order. + for (const percentile of percentiles) { + // Loop over durations, calculating a CDF value for each until it is above + // the target percentile. + const percentileTime = percentile * totalTime; + while (cdfTime < percentileTime && durationIndex < durations.length - 1) { + completedTime += duration; + remainingCount -= (duration < 0 ? -1 : 1); + + if (clippedLength > 0 && clippedLength < durations[durationIndex + 1]) { + duration = -clippedLength; + clippedLength = 0; + } else { + durationIndex++; + duration = durations[durationIndex]; + } + + // Calculate value of CDF (multiplied by totalTime) for the end of this duration. + cdfTime = completedTime + Math.abs(duration) * remainingCount; + } + + // Negative results are within idle time (0ms wait by definition), so clamp at zero. + results.push({ + percentile, + time: Math.max(0, (percentileTime - completedTime) / remainingCount) + + BASE_RESPONSE_LATENCY, + }); + } + + return results; + } + + /** + * Calculates the maximum queueing time (in ms) of high priority tasks for + * selected percentiles within a window of the main thread. + * @see https://docs.google.com/document/d/1b9slyaB9yho91YTOkAQfpCdULFkZM9LqsipcX3t7He8/preview + * @param {Array} events + * @param {number} startTime Start time (in ms relative to navstart) of range of interest. + * @param {number} endTime End time (in ms relative to navstart) of range of interest. + * @param {!Array=} percentiles Optional array of percentiles to compute. Defaults to [0.5, 0.75, 0.9, 0.99, 1]. + * @return {!Array<{percentile: number, time: number}>} + */ + static getRiskToResponsiveness( + events, + startTime, + endTime, + percentiles = [0.5, 0.75, 0.9, 0.99, 1] + ) { + const totalTime = endTime - startTime; + percentiles.sort((a, b) => a - b); + + const ret = this.getMainThreadTopLevelEventDurations(events, startTime, endTime); + return this._riskPercentiles(ret.durations, totalTime, percentiles, + ret.clippedLength); + } + + /** + * Provides durations in ms of all main thread top-level events + * @param {Array} topLevelEvents + * @param {number} startTime Optional start time (in ms relative to navstart) of range of interest. Defaults to navstart. + * @param {number} endTime Optional end time (in ms relative to navstart) of range of interest. Defaults to trace end. + * @return {{durations: Array, clippedLength: number}} + */ + static getMainThreadTopLevelEventDurations(topLevelEvents, startTime = 0, endTime = Infinity) { + // Find durations of all slices in range of interest. + /** @type {Array} */ + const durations = []; + let clippedLength = 0; + + for (const event of topLevelEvents) { + if (event.end < startTime || event.start > endTime) { + continue; + } + + let duration = event.duration; + let eventStart = event.start; + if (eventStart < startTime) { + // Any part of task before window can be discarded. + eventStart = startTime; + duration = event.end - startTime; + } + + if (event.end > endTime) { + // Any part of task after window must be clipped but accounted for. + clippedLength = duration - (endTime - eventStart); + } + + durations.push(duration); + } + durations.sort((a, b) => a - b); + + return { + durations, + clippedLength, + }; + } + + /** + * Provides the top level events on the main thread with timestamps in ms relative to navigation + * start. + * @param {LH.Artifacts.TraceOfTab} tabTrace + * @param {number=} startTime Optional start time (in ms relative to navstart) of range of interest. Defaults to navstart. + * @param {number=} endTime Optional end time (in ms relative to navstart) of range of interest. Defaults to trace end. + * @return {Array} + */ + static getMainThreadTopLevelEvents(tabTrace, startTime = 0, endTime = Infinity) { + const topLevelEvents = []; + // note: mainThreadEvents is already sorted by event start + for (const event of tabTrace.mainThreadEvents) { + if (!this.isScheduleableTask(event) || !event.dur) continue; + + const start = (event.ts - tabTrace.navigationStartEvt.ts) / 1000; + const end = (event.ts + event.dur - tabTrace.navigationStartEvt.ts) / 1000; + if (start > endTime || end < startTime) continue; + + topLevelEvents.push({ + start, + end, + duration: event.dur / 1000, + }); + } + + return topLevelEvents; + } + + /** + * @param {LH.TraceEvent[]} events + * @return {{pid: number, tid: number, frameId: string}} + */ + static findMainFrameIds(events) { + // Prefer the newer TracingStartedInBrowser event first, if it exists + const startedInBrowserEvt = events.find(e => e.name === 'TracingStartedInBrowser'); + if (startedInBrowserEvt && startedInBrowserEvt.args.data && + startedInBrowserEvt.args.data.frames) { + const mainFrame = startedInBrowserEvt.args.data.frames.find(frame => !frame.parent); + const frameId = mainFrame && mainFrame.frame; + const pid = mainFrame && mainFrame.processId; + + const threadNameEvt = events.find(e => e.pid === pid && e.ph === 'M' && + e.cat === '__metadata' && e.name === 'thread_name' && e.args.name === 'CrRendererMain'); + const tid = threadNameEvt && threadNameEvt.tid; + + if (pid && tid && frameId) { + return { + pid, + tid, + frameId, + }; + } + } + + // Support legacy browser versions that do not emit TracingStartedInBrowser event. + // The first TracingStartedInPage in the trace is definitely our renderer thread of interest + // Beware: the tracingStartedInPage event can appear slightly after a navigationStart + const startedInPageEvt = events.find(e => e.name === 'TracingStartedInPage'); + if (startedInPageEvt && startedInPageEvt.args && startedInPageEvt.args.data) { + const frameId = startedInPageEvt.args.data.page; + if (frameId) { + return { + pid: startedInPageEvt.pid, + tid: startedInPageEvt.tid, + frameId, + }; + } + } + + // Support the case where everything else fails, see https://github.com/GoogleChrome/lighthouse/issues/7118. + // If we can't find either TracingStarted event, then we'll fallback to the first navStart that + // looks like it was loading the main frame with a real URL. Because the schema for this event + // has changed across Chrome versions, we'll be extra defensive about finding this case. + const navStartEvt = events.find(e => Boolean(e.name === 'navigationStart' && e.args && + e.args.data && e.args.data.isLoadingMainFrame && e.args.data.documentLoaderURL)); + // Find the first resource that was requested and make sure it agrees on the id. + const firstResourceSendEvt = events.find(e => e.name === 'ResourceSendRequest'); + // We know that these properties exist if we found the events, but TSC doesn't. + if (navStartEvt && navStartEvt.args && navStartEvt.args.data && + firstResourceSendEvt && + firstResourceSendEvt.pid === navStartEvt.pid && + firstResourceSendEvt.tid === navStartEvt.tid) { + const frameId = navStartEvt.args.frame; + if (frameId) { + return { + pid: navStartEvt.pid, + tid: navStartEvt.tid, + frameId, + }; + } + } + + throw this.createNoTracingStartedError(); + } + + /** + * @param {LH.TraceEvent} evt + * @return {boolean} + */ + static isScheduleableTask(evt) { + return evt.name === SCHEDULABLE_TASK_TITLE_LH || + evt.name === SCHEDULABLE_TASK_TITLE_ALT1 || + evt.name === SCHEDULABLE_TASK_TITLE_ALT2 || + evt.name === SCHEDULABLE_TASK_TITLE_ALT3; + } + /** * Finds key trace events, identifies main process/thread, and returns timings of trace events @@ -70,10 +353,10 @@ class TraceOfTab { * @param {LH.Trace} trace * @return {LH.Artifacts.TraceOfTab} */ - static compute(trace) { + static computeTraceOfTab(trace) { // Parse the trace for our key events and sort them by timestamp. Note: sort // *must* be stable to keep events correctly nested. - const keyEvents = TraceOfTab.filteredStableSort(trace.traceEvents, e => { + const keyEvents = this._filteredStableSort(trace.traceEvents, e => { return e.cat.includes('blink.user_timing') || e.cat.includes('loading') || e.cat.includes('devtools.timeline') || @@ -81,14 +364,14 @@ class TraceOfTab { }); // Find the inspected frame - const mainFrameIds = TracingProcessor.findMainFrameIds(keyEvents); + const mainFrameIds = this.findMainFrameIds(keyEvents); // Filter to just events matching the frame ID for sanity const frameEvents = keyEvents.filter(e => e.args.frame === mainFrameIds.frameId); // Our navStart will be the last frame navigation in the trace - const navigationStart = frameEvents.filter(TraceOfTab.isNavigationStartOfInterest).pop(); - if (!navigationStart) throw new LHError(LHError.errors.NO_NAVSTART); + const navigationStart = frameEvents.filter(this._isNavigationStartOfInterest).pop(); + if (!navigationStart) throw this.createNoNavstartError(); // Find our first paint of this frame const firstPaint = frameEvents.find(e => e.name === 'firstPaint' && e.ts > navigationStart.ts); @@ -97,7 +380,7 @@ class TraceOfTab { const firstContentfulPaint = frameEvents.find( e => e.name === 'firstContentfulPaint' && e.ts > navigationStart.ts ); - if (!firstContentfulPaint) throw new LHError(LHError.errors.NO_FCP); + if (!firstContentfulPaint) throw this.createNoFirstContentfulPaintError(); // fMP will follow at/after the FP let firstMeaningfulPaint = frameEvents.find( @@ -110,9 +393,6 @@ class TraceOfTab { // In this case, we'll use the last firstMeaningfulPaintCandidate we can find. // However, if no candidates were found (a bogus trace, likely), we fail. if (!firstMeaningfulPaint) { - // Track this with Sentry since it's likely a bug we should investigate. - Sentry.captureMessage('No firstMeaningfulPaint found, using fallback', {level: 'warning'}); - const fmpCand = 'firstMeaningfulPaintCandidate'; fmpFellBack = true; log.verbose('trace-of-tab', `No firstMeaningfulPaint found, falling back to last ${fmpCand}`); @@ -130,8 +410,8 @@ class TraceOfTab { // subset all trace events to just our tab's process (incl threads other than main) // stable-sort events to keep them correctly nested. - const processEvents = TraceOfTab - .filteredStableSort(trace.traceEvents, e => e.pid === mainFrameIds.pid); + const processEvents = TraceProcessor + ._filteredStableSort(trace.traceEvents, e => e.pid === mainFrameIds.pid); const mainThreadEvents = processEvents .filter(e => e.tid === mainFrameIds.tid); @@ -188,4 +468,12 @@ class TraceOfTab { } } -module.exports = TraceOfTab; +module.exports = TraceProcessor; + + +/** + * @typedef ToplevelEvent + * @prop {number} start + * @prop {number} end + * @prop {number} duration + */ diff --git a/lighthouse-core/lib/tracehouse/tracing-processor.js b/lighthouse-core/lib/tracehouse/tracing-processor.js deleted file mode 100644 index e3a11991c05f..000000000000 --- a/lighthouse-core/lib/tracehouse/tracing-processor.js +++ /dev/null @@ -1,285 +0,0 @@ -/** - * @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'; - -// The ideal input response latency, the time between the input task and the -// first frame of the response. -const BASE_RESPONSE_LATENCY = 16; -// m71+ We added RunTask to `disabled-by-default-lighthouse` -const SCHEDULABLE_TASK_TITLE_LH = 'RunTask'; -// m69-70 DoWork is different and we now need RunTask, see https://bugs.chromium.org/p/chromium/issues/detail?id=871204#c11 -const SCHEDULABLE_TASK_TITLE_ALT1 = 'ThreadControllerImpl::RunTask'; -// In m66-68 refactored to this task title, https://crrev.com/c/883346 -const SCHEDULABLE_TASK_TITLE_ALT2 = 'ThreadControllerImpl::DoWork'; -// m65 and earlier -const SCHEDULABLE_TASK_TITLE_ALT3 = 'TaskQueueManager::ProcessTaskFromWorkQueue'; - - -const LHError = require('../lh-error.js'); - -class TraceProcessor { - /** - * There should *always* be at least one top level event, having 0 typically means something is - * drastically wrong with the trace and we should just give up early and loudly. - * - * @param {LH.TraceEvent[]} events - */ - static assertHasToplevelEvents(events) { - const hasToplevelTask = events.some(TraceProcessor.isScheduleableTask); - if (!hasToplevelTask) { - throw new Error('Could not find any top level events'); - } - } - - - /** - * Calculate duration at specified percentiles for given population of - * durations. - * If one of the durations overlaps the end of the window, the full - * duration should be in the duration array, but the length not included - * within the window should be given as `clippedLength`. For instance, if a - * 50ms duration occurs 10ms before the end of the window, `50` should be in - * the `durations` array, and `clippedLength` should be set to 40. - * @see https://docs.google.com/document/d/1b9slyaB9yho91YTOkAQfpCdULFkZM9LqsipcX3t7He8/preview - * @param {!Array} durations Array of durations, sorted in ascending order. - * @param {number} totalTime Total time (in ms) of interval containing durations. - * @param {!Array} percentiles Array of percentiles of interest, in ascending order. - * @param {number=} clippedLength Optional length clipped from a duration overlapping end of window. Default of 0. - * @return {!Array<{percentile: number, time: number}>} - * @private - */ - static _riskPercentiles(durations, totalTime, percentiles, clippedLength = 0) { - let busyTime = 0; - for (let i = 0; i < durations.length; i++) { - busyTime += durations[i]; - } - busyTime -= clippedLength; - - // Start with idle time already complete. - let completedTime = totalTime - busyTime; - let duration = 0; - let cdfTime = completedTime; - const results = []; - - let durationIndex = -1; - let remainingCount = durations.length + 1; - if (clippedLength > 0) { - // If there was a clipped duration, one less in count since one hasn't started yet. - remainingCount--; - } - - // Find percentiles of interest, in order. - for (const percentile of percentiles) { - // Loop over durations, calculating a CDF value for each until it is above - // the target percentile. - const percentileTime = percentile * totalTime; - while (cdfTime < percentileTime && durationIndex < durations.length - 1) { - completedTime += duration; - remainingCount -= (duration < 0 ? -1 : 1); - - if (clippedLength > 0 && clippedLength < durations[durationIndex + 1]) { - duration = -clippedLength; - clippedLength = 0; - } else { - durationIndex++; - duration = durations[durationIndex]; - } - - // Calculate value of CDF (multiplied by totalTime) for the end of this duration. - cdfTime = completedTime + Math.abs(duration) * remainingCount; - } - - // Negative results are within idle time (0ms wait by definition), so clamp at zero. - results.push({ - percentile, - time: Math.max(0, (percentileTime - completedTime) / remainingCount) + - BASE_RESPONSE_LATENCY, - }); - } - - return results; - } - - /** - * Calculates the maximum queueing time (in ms) of high priority tasks for - * selected percentiles within a window of the main thread. - * @see https://docs.google.com/document/d/1b9slyaB9yho91YTOkAQfpCdULFkZM9LqsipcX3t7He8/preview - * @param {Array} events - * @param {number} startTime Start time (in ms relative to navstart) of range of interest. - * @param {number} endTime End time (in ms relative to navstart) of range of interest. - * @param {!Array=} percentiles Optional array of percentiles to compute. Defaults to [0.5, 0.75, 0.9, 0.99, 1]. - * @return {!Array<{percentile: number, time: number}>} - */ - static getRiskToResponsiveness( - events, - startTime, - endTime, - percentiles = [0.5, 0.75, 0.9, 0.99, 1] - ) { - const totalTime = endTime - startTime; - percentiles.sort((a, b) => a - b); - - const ret = TraceProcessor.getMainThreadTopLevelEventDurations(events, startTime, endTime); - return TraceProcessor._riskPercentiles(ret.durations, totalTime, percentiles, - ret.clippedLength); - } - - /** - * Provides durations in ms of all main thread top-level events - * @param {Array} topLevelEvents - * @param {number} startTime Optional start time (in ms relative to navstart) of range of interest. Defaults to navstart. - * @param {number} endTime Optional end time (in ms relative to navstart) of range of interest. Defaults to trace end. - * @return {{durations: Array, clippedLength: number}} - */ - static getMainThreadTopLevelEventDurations(topLevelEvents, startTime = 0, endTime = Infinity) { - // Find durations of all slices in range of interest. - /** @type {Array} */ - const durations = []; - let clippedLength = 0; - - for (const event of topLevelEvents) { - if (event.end < startTime || event.start > endTime) { - continue; - } - - let duration = event.duration; - let eventStart = event.start; - if (eventStart < startTime) { - // Any part of task before window can be discarded. - eventStart = startTime; - duration = event.end - startTime; - } - - if (event.end > endTime) { - // Any part of task after window must be clipped but accounted for. - clippedLength = duration - (endTime - eventStart); - } - - durations.push(duration); - } - durations.sort((a, b) => a - b); - - return { - durations, - clippedLength, - }; - } - - /** - * Provides the top level events on the main thread with timestamps in ms relative to navigation - * start. - * @param {LH.Artifacts.TraceOfTab} tabTrace - * @param {number=} startTime Optional start time (in ms relative to navstart) of range of interest. Defaults to navstart. - * @param {number=} endTime Optional end time (in ms relative to navstart) of range of interest. Defaults to trace end. - * @return {Array} - */ - static getMainThreadTopLevelEvents(tabTrace, startTime = 0, endTime = Infinity) { - const topLevelEvents = []; - // note: mainThreadEvents is already sorted by event start - for (const event of tabTrace.mainThreadEvents) { - if (!TraceProcessor.isScheduleableTask(event) || !event.dur) continue; - - const start = (event.ts - tabTrace.navigationStartEvt.ts) / 1000; - const end = (event.ts + event.dur - tabTrace.navigationStartEvt.ts) / 1000; - if (start > endTime || end < startTime) continue; - - topLevelEvents.push({ - start, - end, - duration: event.dur / 1000, - }); - } - - return topLevelEvents; - } - - /** - * @param {LH.TraceEvent[]} events - * @return {{pid: number, tid: number, frameId: string}} - */ - static findMainFrameIds(events) { - // Prefer the newer TracingStartedInBrowser event first, if it exists - const startedInBrowserEvt = events.find(e => e.name === 'TracingStartedInBrowser'); - if (startedInBrowserEvt && startedInBrowserEvt.args.data && - startedInBrowserEvt.args.data.frames) { - const mainFrame = startedInBrowserEvt.args.data.frames.find(frame => !frame.parent); - const frameId = mainFrame && mainFrame.frame; - const pid = mainFrame && mainFrame.processId; - - const threadNameEvt = events.find(e => e.pid === pid && e.ph === 'M' && - e.cat === '__metadata' && e.name === 'thread_name' && e.args.name === 'CrRendererMain'); - const tid = threadNameEvt && threadNameEvt.tid; - - if (pid && tid && frameId) { - return { - pid, - tid, - frameId, - }; - } - } - - // Support legacy browser versions that do not emit TracingStartedInBrowser event. - // The first TracingStartedInPage in the trace is definitely our renderer thread of interest - // Beware: the tracingStartedInPage event can appear slightly after a navigationStart - const startedInPageEvt = events.find(e => e.name === 'TracingStartedInPage'); - if (startedInPageEvt && startedInPageEvt.args && startedInPageEvt.args.data) { - const frameId = startedInPageEvt.args.data.page; - if (frameId) { - return { - pid: startedInPageEvt.pid, - tid: startedInPageEvt.tid, - frameId, - }; - } - } - - // Support the case where everything else fails, see https://github.com/GoogleChrome/lighthouse/issues/7118. - // If we can't find either TracingStarted event, then we'll fallback to the first navStart that - // looks like it was loading the main frame with a real URL. Because the schema for this event - // has changed across Chrome versions, we'll be extra defensive about finding this case. - const navStartEvt = events.find(e => Boolean(e.name === 'navigationStart' && e.args && - e.args.data && e.args.data.isLoadingMainFrame && e.args.data.documentLoaderURL)); - // Find the first resource that was requested and make sure it agrees on the id. - const firstResourceSendEvt = events.find(e => e.name === 'ResourceSendRequest'); - // We know that these properties exist if we found the events, but TSC doesn't. - if (navStartEvt && navStartEvt.args && navStartEvt.args.data && - firstResourceSendEvt && - firstResourceSendEvt.pid === navStartEvt.pid && - firstResourceSendEvt.tid === navStartEvt.tid) { - const frameId = navStartEvt.args.frame; - if (frameId) { - return { - pid: navStartEvt.pid, - tid: navStartEvt.tid, - frameId, - }; - } - } - - throw new LHError(LHError.errors.NO_TRACING_STARTED); - } - - /** - * @param {LH.TraceEvent} evt - * @return {boolean} - */ - static isScheduleableTask(evt) { - return evt.name === SCHEDULABLE_TASK_TITLE_LH || - evt.name === SCHEDULABLE_TASK_TITLE_ALT1 || - evt.name === SCHEDULABLE_TASK_TITLE_ALT2 || - evt.name === SCHEDULABLE_TASK_TITLE_ALT3; - } -} - -/** - * @typedef ToplevelEvent - * @prop {number} start - * @prop {number} end - * @prop {number} duration - */ - -module.exports = TraceProcessor; diff --git a/lighthouse-core/test/computed/metrics/first-cpu-idle-test.js b/lighthouse-core/test/computed/metrics/first-cpu-idle-test.js index cfb21da04bff..6233f46a4090 100644 --- a/lighthouse-core/test/computed/metrics/first-cpu-idle-test.js +++ b/lighthouse-core/test/computed/metrics/first-cpu-idle-test.js @@ -6,7 +6,7 @@ 'use strict'; const FirstCPUIdle = require('../../../computed/metrics/first-cpu-idle.js'); -const TracingProcessor = require('../../../lib/tracehouse/tracing-processor.js'); +const TracingProcessor = require('../../../lib/tracehouse/trace-processor.js'); const tooShortTrace = require('../../fixtures/traces/progressive-app.json'); const acceptableTrace = require('../../fixtures/traces/progressive-app-m60.json'); diff --git a/lighthouse-core/test/computed/trace-of-tab-test.js b/lighthouse-core/test/computed/trace-of-tab-test.js index 4c14d71cab83..3b337276c6b1 100644 --- a/lighthouse-core/test/computed/trace-of-tab-test.js +++ b/lighthouse-core/test/computed/trace-of-tab-test.js @@ -9,6 +9,8 @@ const TraceOfTab = require('../../computed/trace-of-tab.js'); const pwaTrace = require('../fixtures/traces/progressive-app-m60.json'); +const noFCPtrace = require('../fixtures/traces/airhorner_no_fcp.json'); +const noNavStartTrace = require('../fixtures/traces/no_navstart_event.json'); describe('TraceOfTabComputed', () => { it('computes the artifact', async () => { @@ -122,4 +124,34 @@ describe('TraceOfTabComputed', () => { }, }); }); + + it('fails with NO_NAVSTART', async () => { + const context = {computedCache: new Map()}; + await expect(TraceOfTab.request(noNavStartTrace, context)) + .rejects.toMatchObject({code: 'NO_NAVSTART'}); + }); + + it('fails with NO_FCP', async () => { + const context = {computedCache: new Map()}; + await expect(TraceOfTab.request(noFCPtrace, context)) + .rejects.toMatchObject({code: 'NO_FCP'}); + }); + + it('fails with NO_TRACING_STARTED', async () => { + const context = {computedCache: new Map()}; + const noTracingStartedTrace = { + traceEvents: pwaTrace.traceEvents.filter(event => { + if (event.name === 'TracingStartedInBrowser' || + event.name === 'TracingStartedInPage' || + event.name === 'ResourceSendRequest') { + return false; + } + + return true; + }), + }; + + await expect(TraceOfTab.request(noTracingStartedTrace, context)) + .rejects.toMatchObject({code: 'NO_TRACING_STARTED'}); + }); }); diff --git a/lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js b/lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js index fbfdc5234c06..d73120baa78b 100644 --- a/lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js +++ b/lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js @@ -8,10 +8,10 @@ /* eslint-env jest */ const MainThreadTasks = require('../../../lib/tracehouse/main-thread-tasks.js'); -const TraceOfTab = require('../../../lib/tracehouse/trace-of-tab.js'); +const TraceProcessor = require('../../../lib/tracehouse/trace-processor.js'); const taskGroups = require('../../../lib/tracehouse/task-groups.js').taskGroups; const pwaTrace = require('../../fixtures/traces/progressive-app.json'); -const TracingProcessor = require('../../../lib/tracehouse/tracing-processor.js'); +const TracingProcessor = require('../../../lib/tracehouse/trace-processor.js'); const assert = require('assert'); describe('Main Thread Tasks', () => { @@ -31,7 +31,7 @@ describe('Main Thread Tasks', () => { }); function run(trace) { - const {mainThreadEvents, timestamps} = TraceOfTab.compute(trace); + const {mainThreadEvents, timestamps} = TraceProcessor.computeTraceOfTab(trace); return MainThreadTasks.getMainThreadTasks(mainThreadEvents, timestamps.traceEnd); } diff --git a/lighthouse-core/test/lib/tracehouse/trace-processor-test.js b/lighthouse-core/test/lib/tracehouse/trace-processor-test.js index a8fee73408fd..66e1204d0c1c 100644 --- a/lighthouse-core/test/lib/tracehouse/trace-processor-test.js +++ b/lighthouse-core/test/lib/tracehouse/trace-processor-test.js @@ -5,10 +5,11 @@ */ 'use strict'; -const TraceOfTab = require('../../../lib/tracehouse/trace-of-tab.js'); +const TraceProcessor = require('../../../lib/tracehouse/trace-processor.js'); const assert = require('assert'); const fs = require('fs'); +const pwaTrace = require('../../fixtures/traces/progressive-app.json'); const badNavStartTrace = require('../../fixtures/traces/bad-nav-start-ts.json'); const lateTracingStartedTrace = require('../../fixtures/traces/tracingstarted-after-navstart.json'); const noTracingStartedTrace = require('../../fixtures/traces/no-tracingstarted-m74.json'); @@ -19,191 +20,425 @@ const noNavStartTrace = require('../../fixtures/traces/no_navstart_event.json'); const backgroundTabTrace = require('../../fixtures/traces/backgrounded-tab-missing-paints.json'); /* eslint-env jest */ -describe('Trace of Tab computed artifact:', () => { - it('gathers the events from the tab\'s process', () => { - const trace = TraceOfTab.compute(lateTracingStartedTrace); - const firstEvt = trace.processEvents[0]; - trace.processEvents.forEach(evt => { - assert.equal(evt.pid, firstEvt.pid, 'A traceEvent is found from another process'); +describe('TraceProcessor', () => { + describe('_riskPercentiles', () => { + const defaultPercentiles = [0, 0.25, 0.5, 0.75, 0.9, 0.99, 1]; + + /** + * Create a riskPercentiles result object by matching the values in percentiles + * and times. + * @param {!Array} percentiles + * @param {!Array} times + * @return {!Array<{percentile: number, time: number}>} + */ + function createRiskPercentiles(percentiles, times) { + return percentiles.map((percentile, index) => { + return { + percentile, + time: times[index], + }; + }); + } + + it('correctly calculates percentiles of no tasks', () => { + const results = TraceProcessor._riskPercentiles([], 100, defaultPercentiles); + const expected = createRiskPercentiles(defaultPercentiles, [16, 16, 16, 16, 16, 16, 16]); + assert.deepEqual(results, expected); }); - assert.ok(firstEvt.pid === trace.mainFrameIds.pid); - assert.ok(firstEvt.pid === trace.navigationStartEvt.pid); - assert.ok(firstEvt.pid === trace.firstContentfulPaintEvt.pid); - assert.ok(firstEvt.pid === trace.firstMeaningfulPaintEvt.pid); - }); + it('correctly calculates percentiles of a single task with idle time', () => { + const results = TraceProcessor._riskPercentiles([50], 100, defaultPercentiles); + const expected = createRiskPercentiles(defaultPercentiles, [16, 16, 16, 41, 56, 65, 66]); + assert.deepEqual(results, expected); + }); + + it('correctly calculates percentiles of a single task with no idle time', () => { + const results = TraceProcessor._riskPercentiles([50], 50, defaultPercentiles); + const expected = createRiskPercentiles(defaultPercentiles, + [16, 28.5, 41, 53.5, 61, 65.5, 66]); + assert.deepEqual(results, expected); + }); + + it('correctly calculates percentiles of several equal-length tasks', () => { + const results = TraceProcessor._riskPercentiles([50, 50, 50, 50], 400, defaultPercentiles); + const expected = createRiskPercentiles(defaultPercentiles, [16, 16, 16, 41, 56, 65, 66]); + assert.deepEqual(results, expected); + }); + + it('correctly calculates percentiles of tasks including zero-length durations', () => { + const results = TraceProcessor._riskPercentiles([0, 0, 0, 10, 20, 20, 30, 30, 120], 320, + defaultPercentiles); + const expected = createRiskPercentiles(defaultPercentiles, [16, 16, 28, 56, 104, 132.8, 136]); + assert.deepEqual(results, expected); + }); + + // Three tasks of one second each, all within a five-second window. + // Mean Queueing Time of 300ms. + it('correctly calculates percentiles of three one-second tasks in a five-second window', () => { + const results = TraceProcessor._riskPercentiles([1000, 1000, 1000], 5000, + defaultPercentiles, 0); + // Round to hundredths to simplify floating point comparison. + results.forEach(result => { + result.time = Number(result.time.toFixed(2)); + }); + + const expected = createRiskPercentiles(defaultPercentiles, + [16, 16, 182.67, 599.33, 849.33, 999.33, 1016]); + assert.deepEqual(results, expected); + }); + + it('correctly calculates percentiles of tasks with a clipped task', () => { + const results = TraceProcessor._riskPercentiles([10, 20, 50, 60, 90, 100], 300, + defaultPercentiles, 30); + // Round to hundredths to simplify floating point comparison. + results.forEach(result => { + result.time = Number(result.time.toFixed(2)); + }); + + const expected = createRiskPercentiles(defaultPercentiles, + [16, 32.25, 53.5, 74.33, 96, 113, 116]); + assert.deepEqual(results, expected); + }); + + // One 20 second long task over three five-second windows. + it('correctly calculates percentiles of single task over multiple windows', () => { + // Starts 3 seconds into the first window. Mean Queueing Time = 7600ms. + const TASK_LENGTH = 20000; + const results1 = TraceProcessor._riskPercentiles([TASK_LENGTH], 5000, + defaultPercentiles, TASK_LENGTH - 2000); + const expected1 = createRiskPercentiles(defaultPercentiles, + [16, 16, 16, 18766, 19516, 19966, 20016]); + assert.deepEqual(results1, expected1); - it('computes timings of each event', () => { - const trace = TraceOfTab.compute(lateTracingStartedTrace); - assert.equal(Math.round(trace.timings.navigationStart), 0); - assert.equal(Math.round(trace.timings.firstPaint), 80); - assert.equal(Math.round(trace.timings.firstContentfulPaint), 80); - assert.equal(Math.round(trace.timings.firstMeaningfulPaint), 530); - assert.equal(Math.round(trace.timings.traceEnd), 649); + // Starts 2 seconds before and ends 13 seconds after. Mean Queueing Time = 15500ms. + const results2 = TraceProcessor._riskPercentiles([TASK_LENGTH - 2000], 5000, + defaultPercentiles, TASK_LENGTH - 7000); + const expected2 = createRiskPercentiles(defaultPercentiles, + [16, 14266, 15516, 16766, 17516, 17966, 18016]); + assert.deepEqual(results2, expected2); + + // Starts 17 seconds before and ends 3 seconds into the window. Mean Queueing Time = 900ms. + const results3 = TraceProcessor._riskPercentiles([TASK_LENGTH - 17000], 5000, + defaultPercentiles, 0); + const expected3 = createRiskPercentiles(defaultPercentiles, + [16, 16, 516, 1766, 2516, 2966, 3016]); + assert.deepEqual(results3, expected3); + }); + + it('correctly calculates with a task shorter than the clipped length of another', () => { + const results = TraceProcessor._riskPercentiles([40, 100], 100, + defaultPercentiles, 50); + const expected = createRiskPercentiles(defaultPercentiles, + [16, 31, 56, 91, 106, 115, 116]); + assert.deepEqual(results, expected); + }); + + it('correctly calculates with a task clipped completely', () => { + const results = TraceProcessor._riskPercentiles([40, 100], 100, + defaultPercentiles, 100); + const expected = createRiskPercentiles(defaultPercentiles, + [16, 16, 16, 31, 46, 55, 56]); + assert.deepEqual(results, expected); + }); + + it('does not divide by zero when duration sum is less than whole', () => { + // Durations chosen such that, due to floating point error: + // const idleTime = totalTime - (duration1 + duration2); + // (idleTime + duration1 + duration2) < totalTime + const duration1 = 67 / 107; + const duration2 = 67 / 53; + const totalTime = 10; + const results = TraceProcessor._riskPercentiles([duration1, duration2], totalTime, [1], 0); + const expected = createRiskPercentiles([1], [16 + duration2]); + assert.deepEqual(results, expected); + }); }); - it('computes timestamps of each event', () => { - const trace = TraceOfTab.compute(lateTracingStartedTrace); - assert.equal(Math.round(trace.timestamps.navigationStart), 29343540951); - assert.equal(Math.round(trace.timestamps.firstPaint), 29343620997); - assert.equal(Math.round(trace.timestamps.firstContentfulPaint), 29343621005); - assert.equal(Math.round(trace.timestamps.firstMeaningfulPaint), 29344070867); - assert.equal(Math.round(trace.timestamps.traceEnd), 29344190223); + describe('getMainThreadTopLevelEvents', () => { + it('gets durations of top-level tasks', () => { + const trace = {traceEvents: pwaTrace}; + const tabTrace = TraceProcessor.computeTraceOfTab(trace); + const ret = TraceProcessor.getMainThreadTopLevelEvents(tabTrace); + + assert.equal(ret.length, 645); + }); + + it('filters events based on start and end times', () => { + const baseTime = 20000 * 1000; + const name = 'TaskQueueManager::ProcessTaskFromWorkQueue'; + const tabTrace = { + navigationStartEvt: {ts: baseTime}, + mainThreadEvents: [ + // 15ms to 25ms + {ts: baseTime + 15 * 1000, dur: 10 * 1000, name}, + // 40ms to 60ms + {ts: baseTime + 40 * 1000, dur: 20 * 1000, name}, + // 1000ms to 2000ms + {ts: baseTime + 1000 * 1000, dur: 1000 * 1000, name}, + // 4000ms to 4020ms + {ts: baseTime + 4000 * 1000, dur: 20 * 1000, name}, + ], + }; + + const ret = TraceProcessor.getMainThreadTopLevelEvents( + tabTrace, + 50, + 1500 + ); + assert.equal(ret.length, 2); + assert.equal(ret[0].start, 40); + assert.equal(ret[0].end, 60); + assert.equal(ret[0].duration, 20); + assert.equal(ret[1].start, 1000); + assert.equal(ret[1].end, 2000); + assert.equal(ret[1].duration, 1000); + }); }); - describe('finds correct FMP', () => { - it('if there was a tracingStartedInPage after the frame\'s navStart', () => { - const trace = TraceOfTab.compute(lateTracingStartedTrace); - assert.equal(trace.mainFrameIds.frameId, '0x163736997740'); - assert.equal(trace.navigationStartEvt.ts, 29343540951); - assert.equal(trace.firstContentfulPaintEvt.ts, 29343621005); - assert.equal(trace.firstMeaningfulPaintEvt.ts, 29344070867); - assert.ok(!trace.fmpFellBack); - }); - - it('if there was a tracingStartedInPage after the frame\'s navStart #2', () => { - const trace = TraceOfTab.compute(badNavStartTrace); - assert.equal(trace.mainFrameIds.frameId, '0x89915541e48'); - assert.equal(trace.navigationStartEvt.ts, 8885424467); - assert.equal(trace.firstContentfulPaintEvt.ts, 8886056886); - assert.equal(trace.firstMeaningfulPaintEvt.ts, 8886056891); - assert.ok(!trace.fmpFellBack); - }); - - it('if it appears slightly before the fCP', () => { - const trace = TraceOfTab.compute(preactTrace); - assert.equal(trace.mainFrameIds.frameId, '0x25edaa521e58'); - assert.equal(trace.navigationStartEvt.ts, 1805796384607); - assert.equal(trace.firstContentfulPaintEvt.ts, 1805797263653); - assert.equal(trace.firstMeaningfulPaintEvt.ts, 1805797262960); - assert.ok(!trace.fmpFellBack); - }); - - it('from candidates if no defined FMP exists', () => { - const trace = TraceOfTab.compute(noFMPtrace); - assert.equal(trace.mainFrameIds.frameId, '0x150343381dd0'); - assert.equal(trace.navigationStartEvt.ts, 2146735807738); - assert.equal(trace.firstContentfulPaintEvt.ts, 2146737302468); - assert.equal(trace.firstMeaningfulPaintEvt.ts, 2146740268666); - assert.ok(trace.fmpFellBack); + describe('getMainThreadTopLevelEventDurations', () => { + it('gets durations of top-level tasks', async () => { + const trace = {traceEvents: pwaTrace}; + const tabTrace = TraceProcessor.computeTraceOfTab(trace); + const events = TraceProcessor.getMainThreadTopLevelEvents(tabTrace); + const ret = TraceProcessor.getMainThreadTopLevelEventDurations(events); + const durations = ret.durations; + + function getDurationFromIndex(index) { + return Number(durations[index].toFixed(2)); + } + + assert.equal(durations.filter(dur => isNaN(dur)).length, 0, 'NaN found'); + assert.equal(durations.length, 645); + + const sum = durations.reduce((a, b) => a + b); + assert.equal(Math.round(sum), 386); + + assert.equal(getDurationFromIndex(50), 0.01); + assert.equal(getDurationFromIndex(300), 0.04); + assert.equal(getDurationFromIndex(400), 0.07); + assert.equal(getDurationFromIndex(durations.length - 3), 26.01); + assert.equal(getDurationFromIndex(durations.length - 2), 36.9); + assert.equal(getDurationFromIndex(durations.length - 1), 38.53); }); }); - it('handles traces missing a paints (captured in background tab)', () => { - const trace = TraceOfTab.compute(backgroundTabTrace); - assert.equal(trace.mainFrameIds.frameId, '0x53965941e30'); - assert.notEqual(trace.navigationStartEvt.ts, 1966813346529, 'picked wrong frame'); - assert.notEqual(trace.navigationStartEvt.ts, 1966813520313, 'picked wrong frame'); - assert.equal( - trace.navigationStartEvt.ts, - 1966813258737, - 'didnt select navStart event with same timestamp as usertiming measure' - ); - assert.equal(trace.firstMeaningfulPaintEvt, undefined, 'bad fmp'); + describe('getRiskToResponsiveness', () => { + let oldFn; + // monkeypatch _riskPercentiles to test just getRiskToResponsiveness + beforeEach(() => { + oldFn = TraceProcessor._riskPercentiles; + TraceProcessor._riskPercentiles = (durations, totalTime, percentiles, clippedLength) => { + return { + durations, totalTime, percentiles, clippedLength, + }; + }; + }); + + it('compute correct defaults', async () => { + const trace = {traceEvents: pwaTrace}; + const tabTrace = TraceProcessor.computeTraceOfTab(trace); + const events = TraceProcessor.getMainThreadTopLevelEvents(tabTrace); + const ret = TraceProcessor.getRiskToResponsiveness(events, 0, tabTrace.timings.traceEnd); + assert.equal(ret.durations.length, 645); + assert.equal(Math.round(ret.totalTime), 2143); + assert.equal(ret.clippedLength, 0); + assert.deepEqual(ret.percentiles, [0.5, 0.75, 0.9, 0.99, 1]); + }); + + afterEach(() => { + TraceProcessor._riskPercentiles = oldFn; + }); }); - it('handles traces with TracingStartedInBrowser events', () => { - const tracingStartedInBrowserTrace = { - 'traceEvents': [{ - 'pid': 69850, - 'tid': 69850, - 'ts': 2193564729582, - 'ph': 'I', - 'cat': 'disabled-by-default-devtools.timeline', - 'name': 'TracingStartedInBrowser', - 'args': {'data': { - 'frameTreeNodeId': 1, - 'frames': [{ + describe('computeTraceOfTab', () => { + it('gathers the events from the tab\'s process', () => { + const trace = TraceProcessor.computeTraceOfTab(lateTracingStartedTrace); + + const firstEvt = trace.processEvents[0]; + trace.processEvents.forEach(evt => { + assert.equal(evt.pid, firstEvt.pid, 'A traceEvent is found from another process'); + }); + + assert.ok(firstEvt.pid === trace.mainFrameIds.pid); + assert.ok(firstEvt.pid === trace.navigationStartEvt.pid); + assert.ok(firstEvt.pid === trace.firstContentfulPaintEvt.pid); + assert.ok(firstEvt.pid === trace.firstMeaningfulPaintEvt.pid); + }); + + it('computes timings of each event', () => { + const trace = TraceProcessor.computeTraceOfTab(lateTracingStartedTrace); + assert.equal(Math.round(trace.timings.navigationStart), 0); + assert.equal(Math.round(trace.timings.firstPaint), 80); + assert.equal(Math.round(trace.timings.firstContentfulPaint), 80); + assert.equal(Math.round(trace.timings.firstMeaningfulPaint), 530); + assert.equal(Math.round(trace.timings.traceEnd), 649); + }); + + it('computes timestamps of each event', () => { + const trace = TraceProcessor.computeTraceOfTab(lateTracingStartedTrace); + assert.equal(Math.round(trace.timestamps.navigationStart), 29343540951); + assert.equal(Math.round(trace.timestamps.firstPaint), 29343620997); + assert.equal(Math.round(trace.timestamps.firstContentfulPaint), 29343621005); + assert.equal(Math.round(trace.timestamps.firstMeaningfulPaint), 29344070867); + assert.equal(Math.round(trace.timestamps.traceEnd), 29344190223); + }); + + describe('finds correct FMP', () => { + it('if there was a tracingStartedInPage after the frame\'s navStart', () => { + const trace = TraceProcessor.computeTraceOfTab(lateTracingStartedTrace); + assert.equal(trace.mainFrameIds.frameId, '0x163736997740'); + assert.equal(trace.navigationStartEvt.ts, 29343540951); + assert.equal(trace.firstContentfulPaintEvt.ts, 29343621005); + assert.equal(trace.firstMeaningfulPaintEvt.ts, 29344070867); + assert.ok(!trace.fmpFellBack); + }); + + it('if there was a tracingStartedInPage after the frame\'s navStart #2', () => { + const trace = TraceProcessor.computeTraceOfTab(badNavStartTrace); + assert.equal(trace.mainFrameIds.frameId, '0x89915541e48'); + assert.equal(trace.navigationStartEvt.ts, 8885424467); + assert.equal(trace.firstContentfulPaintEvt.ts, 8886056886); + assert.equal(trace.firstMeaningfulPaintEvt.ts, 8886056891); + assert.ok(!trace.fmpFellBack); + }); + + it('if it appears slightly before the fCP', () => { + const trace = TraceProcessor.computeTraceOfTab(preactTrace); + assert.equal(trace.mainFrameIds.frameId, '0x25edaa521e58'); + assert.equal(trace.navigationStartEvt.ts, 1805796384607); + assert.equal(trace.firstContentfulPaintEvt.ts, 1805797263653); + assert.equal(trace.firstMeaningfulPaintEvt.ts, 1805797262960); + assert.ok(!trace.fmpFellBack); + }); + + it('from candidates if no defined FMP exists', () => { + const trace = TraceProcessor.computeTraceOfTab(noFMPtrace); + assert.equal(trace.mainFrameIds.frameId, '0x150343381dd0'); + assert.equal(trace.navigationStartEvt.ts, 2146735807738); + assert.equal(trace.firstContentfulPaintEvt.ts, 2146737302468); + assert.equal(trace.firstMeaningfulPaintEvt.ts, 2146740268666); + assert.ok(trace.fmpFellBack); + }); + }); + + it('handles traces missing a paints (captured in background tab)', () => { + const trace = TraceProcessor.computeTraceOfTab(backgroundTabTrace); + assert.equal(trace.mainFrameIds.frameId, '0x53965941e30'); + assert.notEqual(trace.navigationStartEvt.ts, 1966813346529, 'picked wrong frame'); + assert.notEqual(trace.navigationStartEvt.ts, 1966813520313, 'picked wrong frame'); + assert.equal( + trace.navigationStartEvt.ts, + 1966813258737, + 'didnt select navStart event with same timestamp as usertiming measure' + ); + assert.equal(trace.firstMeaningfulPaintEvt, undefined, 'bad fmp'); + }); + + it('handles traces with TracingStartedInBrowser events', () => { + const tracingStartedInBrowserTrace = { + 'traceEvents': [{ + 'pid': 69850, + 'tid': 69850, + 'ts': 2193564729582, + 'ph': 'I', + 'cat': 'disabled-by-default-devtools.timeline', + 'name': 'TracingStartedInBrowser', + 'args': {'data': { + 'frameTreeNodeId': 1, + 'frames': [{ + 'frame': 'B192D1F3355A6F961EC8F0B01623C1FB', + 'url': 'http://www.example.com/', + 'name': '', + 'processId': 69920, + }], + }}, + 'tts': 1085165, + 's': 't', + }, { + 'pid': 69920, + 'tid': 1, + 'ts': 2193564790059, + 'ph': 'R', + 'cat': 'blink.user_timing', + 'name': 'navigationStart', + 'args': { 'frame': 'B192D1F3355A6F961EC8F0B01623C1FB', - 'url': 'http://www.example.com/', - 'name': '', - 'processId': 69920, - }], - }}, - 'tts': 1085165, - 's': 't', - }, { - 'pid': 69920, - 'tid': 1, - 'ts': 2193564790059, - 'ph': 'R', - 'cat': 'blink.user_timing', - 'name': 'navigationStart', - 'args': { - 'frame': 'B192D1F3355A6F961EC8F0B01623C1FB', - 'data': { - 'documentLoaderURL': 'http://www.example.com/', - 'isLoadingMainFrame': true, + 'data': { + 'documentLoaderURL': 'http://www.example.com/', + 'isLoadingMainFrame': true, + }, }, - }, - 'tts': 141371, - }, { - 'pid': 69920, - 'tid': 1, - 'ts': 2193564790060, - 'ph': 'R', - 'cat': 'loading,rail,devtools.timeline', - 'name': 'firstContentfulPaint', - 'args': { - 'frame': 'B192D1F3355A6F961EC8F0B01623C1FB', - }, - 'tts': 141372, - }, { - 'pid': 69920, - 'tid': 1, - 'ts': 0, - 'ph': 'M', - 'cat': '__metadata', - 'name': 'thread_name', - 'args': {'name': 'CrRendererMain'}, - }]}; - const trace = TraceOfTab.compute(tracingStartedInBrowserTrace); - assert.equal(trace.mainFrameIds.frameId, 'B192D1F3355A6F961EC8F0B01623C1FB'); - assert.equal(trace.navigationStartEvt.ts, 2193564790059); - }); + 'tts': 141371, + }, { + 'pid': 69920, + 'tid': 1, + 'ts': 2193564790060, + 'ph': 'R', + 'cat': 'loading,rail,devtools.timeline', + 'name': 'firstContentfulPaint', + 'args': { + 'frame': 'B192D1F3355A6F961EC8F0B01623C1FB', + }, + 'tts': 141372, + }, { + 'pid': 69920, + 'tid': 1, + 'ts': 0, + 'ph': 'M', + 'cat': '__metadata', + 'name': 'thread_name', + 'args': {'name': 'CrRendererMain'}, + }]}; + const trace = TraceProcessor.computeTraceOfTab(tracingStartedInBrowserTrace); + assert.equal(trace.mainFrameIds.frameId, 'B192D1F3355A6F961EC8F0B01623C1FB'); + assert.equal(trace.navigationStartEvt.ts, 2193564790059); + }); - it('handles no TracingStarted errors in m74+', () => { - const trace = TraceOfTab.compute(noTracingStartedTrace); - expect(trace.mainFrameIds.frameId).toEqual('0E0B1AF0B1BA04676037345D18A71577'); - expect(trace.firstContentfulPaintEvt.ts).toEqual(2610265036367); - }); + it('handles no TracingStarted errors in m74+', () => { + const trace = TraceProcessor.computeTraceOfTab(noTracingStartedTrace); + expect(trace.mainFrameIds.frameId).toEqual('0E0B1AF0B1BA04676037345D18A71577'); + expect(trace.firstContentfulPaintEvt.ts).toEqual(2610265036367); + }); - it('stably sorts events', () => { - const traceJson = fs.readFileSync(__dirname + - '/../../fixtures/traces/tracingstarted-after-navstart.json', 'utf8'); - const trace = TraceOfTab.compute(JSON.parse(traceJson)); - const mainPid = trace.mainThreadEvents[0].pid; - - const freshProcessEvents = JSON.parse(traceJson).traceEvents - .filter(e => e.pid === mainPid); - - // Group all events with the same timestamp in original trace order. - const tsMap = new Map(); - for (const event of freshProcessEvents) { - const tsGroup = tsMap.get(event.ts) || []; - tsGroup.push(event); - tsMap.set(event.ts, tsGroup); - } + it('stably sorts events', () => { + const traceJson = fs.readFileSync(__dirname + + '/../../fixtures/traces/tracingstarted-after-navstart.json', 'utf8'); + const trace = TraceProcessor.computeTraceOfTab(JSON.parse(traceJson)); + const mainPid = trace.mainThreadEvents[0].pid; - // Assert that groups of same-timestamped events are in the same order in - // processed events. - for (const [ts, tsGroup] of tsMap) { - if (tsGroup.length === 1) { - continue; + const freshProcessEvents = JSON.parse(traceJson).traceEvents + .filter(e => e.pid === mainPid); + + // Group all events with the same timestamp in original trace order. + const tsMap = new Map(); + for (const event of freshProcessEvents) { + const tsGroup = tsMap.get(event.ts) || []; + tsGroup.push(event); + tsMap.set(event.ts, tsGroup); } - // .filter overhead could be slow, but only a handful of tsGroups. - const sortedEvents = trace.processEvents.filter(e => e.ts === ts); - assert.deepStrictEqual(sortedEvents, tsGroup); - } - }); + // Assert that groups of same-timestamped events are in the same order in + // processed events. + for (const [ts, tsGroup] of tsMap) { + if (tsGroup.length === 1) { + continue; + } - it('throws on traces missing a navigationStart', () => { - expect(() =>TraceOfTab.compute(noNavStartTrace)).toThrowError('NO_NAVSTART'); - }); + // .filter overhead could be slow, but only a handful of tsGroups. + const sortedEvents = trace.processEvents.filter(e => e.ts === ts); + assert.deepStrictEqual(sortedEvents, tsGroup); + } + }); + + it('throws on traces missing a navigationStart', () => { + expect(() => TraceProcessor.computeTraceOfTab(noNavStartTrace)) + .toThrowError('navigationStart'); + }); - it('throws on traces missing an FCP', () => { - expect(() =>TraceOfTab.compute(noFCPtrace)).toThrowError('NO_FCP'); + it('throws on traces missing an FCP', () => { + expect(() => TraceProcessor.computeTraceOfTab(noFCPtrace)) + .toThrowError('firstContentfulPaint'); + }); }); }); diff --git a/lighthouse-core/test/lib/tracehouse/tracing-processor-test.js b/lighthouse-core/test/lib/tracehouse/tracing-processor-test.js deleted file mode 100644 index 3241c8298d79..000000000000 --- a/lighthouse-core/test/lib/tracehouse/tracing-processor-test.js +++ /dev/null @@ -1,244 +0,0 @@ -/** - * @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 assert = require('assert'); - -/* eslint-env jest */ -const TracingProcessor = require('../../../lib/tracehouse/tracing-processor.js'); -const pwaTrace = require('../../fixtures/traces/progressive-app.json'); -const defaultPercentiles = [0, 0.25, 0.5, 0.75, 0.9, 0.99, 1]; - -const TraceOfTab = require('../../../lib/tracehouse/trace-of-tab.js'); - -/** - * Create a riskPercentiles result object by matching the values in percentiles - * and times. - * @param {!Array} percentiles - * @param {!Array} times - * @return {!Array<{percentile: number, time: number}>} - */ -function createRiskPercentiles(percentiles, times) { - return percentiles.map((percentile, index) => { - return { - percentile, - time: times[index], - }; - }); -} - -describe('TracingProcessor lib', () => { - describe('riskPercentiles calculation', () => { - it('correctly calculates percentiles of no tasks', () => { - const results = TracingProcessor._riskPercentiles([], 100, defaultPercentiles); - const expected = createRiskPercentiles(defaultPercentiles, [16, 16, 16, 16, 16, 16, 16]); - assert.deepEqual(results, expected); - }); - - it('correctly calculates percentiles of a single task with idle time', () => { - const results = TracingProcessor._riskPercentiles([50], 100, defaultPercentiles); - const expected = createRiskPercentiles(defaultPercentiles, [16, 16, 16, 41, 56, 65, 66]); - assert.deepEqual(results, expected); - }); - - it('correctly calculates percentiles of a single task with no idle time', () => { - const results = TracingProcessor._riskPercentiles([50], 50, defaultPercentiles); - const expected = createRiskPercentiles(defaultPercentiles, - [16, 28.5, 41, 53.5, 61, 65.5, 66]); - assert.deepEqual(results, expected); - }); - - it('correctly calculates percentiles of several equal-length tasks', () => { - const results = TracingProcessor._riskPercentiles([50, 50, 50, 50], 400, defaultPercentiles); - const expected = createRiskPercentiles(defaultPercentiles, [16, 16, 16, 41, 56, 65, 66]); - assert.deepEqual(results, expected); - }); - - it('correctly calculates percentiles of tasks including zero-length durations', () => { - const results = TracingProcessor._riskPercentiles([0, 0, 0, 10, 20, 20, 30, 30, 120], 320, - defaultPercentiles); - const expected = createRiskPercentiles(defaultPercentiles, [16, 16, 28, 56, 104, 132.8, 136]); - assert.deepEqual(results, expected); - }); - - // Three tasks of one second each, all within a five-second window. - // Mean Queueing Time of 300ms. - it('correctly calculates percentiles of three one-second tasks in a five-second window', () => { - const results = TracingProcessor._riskPercentiles([1000, 1000, 1000], 5000, - defaultPercentiles, 0); - // Round to hundredths to simplify floating point comparison. - results.forEach(result => { - result.time = Number(result.time.toFixed(2)); - }); - - const expected = createRiskPercentiles(defaultPercentiles, - [16, 16, 182.67, 599.33, 849.33, 999.33, 1016]); - assert.deepEqual(results, expected); - }); - - it('correctly calculates percentiles of tasks with a clipped task', () => { - const results = TracingProcessor._riskPercentiles([10, 20, 50, 60, 90, 100], 300, - defaultPercentiles, 30); - // Round to hundredths to simplify floating point comparison. - results.forEach(result => { - result.time = Number(result.time.toFixed(2)); - }); - - const expected = createRiskPercentiles(defaultPercentiles, - [16, 32.25, 53.5, 74.33, 96, 113, 116]); - assert.deepEqual(results, expected); - }); - - // One 20 second long task over three five-second windows. - it('correctly calculates percentiles of single task over multiple windows', () => { - // Starts 3 seconds into the first window. Mean Queueing Time = 7600ms. - const TASK_LENGTH = 20000; - const results1 = TracingProcessor._riskPercentiles([TASK_LENGTH], 5000, - defaultPercentiles, TASK_LENGTH - 2000); - const expected1 = createRiskPercentiles(defaultPercentiles, - [16, 16, 16, 18766, 19516, 19966, 20016]); - assert.deepEqual(results1, expected1); - - // Starts 2 seconds before and ends 13 seconds after. Mean Queueing Time = 15500ms. - const results2 = TracingProcessor._riskPercentiles([TASK_LENGTH - 2000], 5000, - defaultPercentiles, TASK_LENGTH - 7000); - const expected2 = createRiskPercentiles(defaultPercentiles, - [16, 14266, 15516, 16766, 17516, 17966, 18016]); - assert.deepEqual(results2, expected2); - - // Starts 17 seconds before and ends 3 seconds into the window. Mean Queueing Time = 900ms. - const results3 = TracingProcessor._riskPercentiles([TASK_LENGTH - 17000], 5000, - defaultPercentiles, 0); - const expected3 = createRiskPercentiles(defaultPercentiles, - [16, 16, 516, 1766, 2516, 2966, 3016]); - assert.deepEqual(results3, expected3); - }); - - it('correctly calculates with a task shorter than the clipped length of another', () => { - const results = TracingProcessor._riskPercentiles([40, 100], 100, - defaultPercentiles, 50); - const expected = createRiskPercentiles(defaultPercentiles, - [16, 31, 56, 91, 106, 115, 116]); - assert.deepEqual(results, expected); - }); - - it('correctly calculates with a task clipped completely', () => { - const results = TracingProcessor._riskPercentiles([40, 100], 100, - defaultPercentiles, 100); - const expected = createRiskPercentiles(defaultPercentiles, - [16, 16, 16, 31, 46, 55, 56]); - assert.deepEqual(results, expected); - }); - - it('does not divide by zero when duration sum is less than whole', () => { - // Durations chosen such that, due to floating point error: - // const idleTime = totalTime - (duration1 + duration2); - // (idleTime + duration1 + duration2) < totalTime - const duration1 = 67 / 107; - const duration2 = 67 / 53; - const totalTime = 10; - const results = TracingProcessor._riskPercentiles([duration1, duration2], totalTime, [1], 0); - const expected = createRiskPercentiles([1], [16 + duration2]); - assert.deepEqual(results, expected); - }); - }); - - describe('getMainThreadTopLevelEvents', () => { - it('gets durations of top-level tasks', () => { - const trace = {traceEvents: pwaTrace}; - const tabTrace = TraceOfTab.compute(trace); - const ret = TracingProcessor.getMainThreadTopLevelEvents(tabTrace); - - assert.equal(ret.length, 645); - }); - - it('filters events based on start and end times', () => { - const baseTime = 20000 * 1000; - const name = 'TaskQueueManager::ProcessTaskFromWorkQueue'; - const tabTrace = { - navigationStartEvt: {ts: baseTime}, - mainThreadEvents: [ - // 15ms to 25ms - {ts: baseTime + 15 * 1000, dur: 10 * 1000, name}, - // 40ms to 60ms - {ts: baseTime + 40 * 1000, dur: 20 * 1000, name}, - // 1000ms to 2000ms - {ts: baseTime + 1000 * 1000, dur: 1000 * 1000, name}, - // 4000ms to 4020ms - {ts: baseTime + 4000 * 1000, dur: 20 * 1000, name}, - ], - }; - - const ret = TracingProcessor.getMainThreadTopLevelEvents( - tabTrace, - 50, - 1500 - ); - assert.equal(ret.length, 2); - assert.equal(ret[0].start, 40); - assert.equal(ret[0].end, 60); - assert.equal(ret[0].duration, 20); - assert.equal(ret[1].start, 1000); - assert.equal(ret[1].end, 2000); - assert.equal(ret[1].duration, 1000); - }); - }); - - describe('getMainThreadTopLevelEventDurations', () => { - it('gets durations of top-level tasks', async () => { - const trace = {traceEvents: pwaTrace}; - const tabTrace = TraceOfTab.compute(trace); - const events = TracingProcessor.getMainThreadTopLevelEvents(tabTrace); - const ret = TracingProcessor.getMainThreadTopLevelEventDurations(events); - const durations = ret.durations; - - function getDurationFromIndex(index) { - return Number(durations[index].toFixed(2)); - } - - assert.equal(durations.filter(dur => isNaN(dur)).length, 0, 'NaN found'); - assert.equal(durations.length, 645); - - const sum = durations.reduce((a, b) => a + b); - assert.equal(Math.round(sum), 386); - - assert.equal(getDurationFromIndex(50), 0.01); - assert.equal(getDurationFromIndex(300), 0.04); - assert.equal(getDurationFromIndex(400), 0.07); - assert.equal(getDurationFromIndex(durations.length - 3), 26.01); - assert.equal(getDurationFromIndex(durations.length - 2), 36.9); - assert.equal(getDurationFromIndex(durations.length - 1), 38.53); - }); - }); - - describe('risk to responsiveness', () => { - let oldFn; - // monkeypatch _riskPercentiles to test just getRiskToResponsiveness - beforeEach(() => { - oldFn = TracingProcessor._riskPercentiles; - TracingProcessor._riskPercentiles = (durations, totalTime, percentiles, clippedLength) => { - return { - durations, totalTime, percentiles, clippedLength, - }; - }; - }); - - it('compute correct defaults', async () => { - const trace = {traceEvents: pwaTrace}; - const tabTrace = TraceOfTab.compute(trace); - const events = TracingProcessor.getMainThreadTopLevelEvents(tabTrace); - const ret = TracingProcessor.getRiskToResponsiveness(events, 0, tabTrace.timings.traceEnd); - assert.equal(ret.durations.length, 645); - assert.equal(Math.round(ret.totalTime), 2143); - assert.equal(ret.clippedLength, 0); - assert.deepEqual(ret.percentiles, [0.5, 0.75, 0.9, 0.99, 1]); - }); - - afterEach(() => { - TracingProcessor._riskPercentiles = oldFn; - }); - }); -});