diff --git a/lighthouse-core/lib/tracehouse/cpu-profile-model.js b/lighthouse-core/lib/tracehouse/cpu-profile-model.js index c93ab2a0687b..9c32d5715cc4 100644 --- a/lighthouse-core/lib/tracehouse/cpu-profile-model.js +++ b/lighthouse-core/lib/tracehouse/cpu-profile-model.js @@ -123,7 +123,7 @@ class CpuProfilerModel { * @param {Array} currentNodeIds * @return {Array} */ - _createStartEndEventsForTransition(timestamp, previousNodeIds, currentNodeIds) { + _synthesizeTraceEventsForTransition(timestamp, previousNodeIds, currentNodeIds) { const startNodes = currentNodeIds .filter(id => !previousNodeIds.includes(id)) .map(id => this._nodesById.get(id)) @@ -155,19 +155,121 @@ class CpuProfilerModel { } /** - * Creates B/E-style trace events from a CpuProfile object created by `collectProfileEvents()` + * Finds all the tasks that started or ended (depending on `type`) within the provided time range. + * Uses a memory index to remember the place in the array the last invocation left off to avoid + * re-traversing the entire array. + * + * @param {Array<{startTime: number, endTime: number}>} knownTasks + * @param {{type: 'startTime'|'endTime', initialIndex: number, earliestPossibleTimestamp: number, latestPossibleTimestamp: number}} options + */ + static _getTasksInRange(knownTasks, options) { + const {type, initialIndex, earliestPossibleTimestamp, latestPossibleTimestamp} = options; + + /** @type {Array<{startTime: number, endTime: number}>} */ + const matchingTasks = []; + for (let i = initialIndex; i < knownTasks.length; i++) { + const task = knownTasks[i]; + // Task is before our range of interest, keep looping. + if (task[type] < earliestPossibleTimestamp) continue; + + // Task is after our range of interest, we're done. + if (task[type] > latestPossibleTimestamp) { + return {tasks: matchingTasks, lastIndex: i}; + } + + // Task is in our range of interest, add it to our list. + matchingTasks.push(task); + } + + return {tasks: matchingTasks, lastIndex: knownTasks.length}; + } + + /** + * Given a particular time range and a set of known true tasks, find the correct timestamp to use + * for a transition between tasks. + * + * Because the sampling profiler only provides a *range* of start/stop function boundaries, this + * method uses knowledge of a known set of tasks to find the most accurate timestamp for a particular + * range. For example, if we know that a function ended between 800ms and 810ms, we can use the + * knowledge that a toplevel task ended at 807ms to use 807ms as the correct endtime for this function. + * + * @param {{earliestPossibleTimestamp: number, latestPossibleTimestamp: number, knownTaskStartTimeIndex: number, knownTaskEndTimeIndex: number, knownTasksByStartTime: Array<{startTime: number, endTime: number}>, knownTasksByEndTime: Array<{startTime: number, endTime: number}>}} data + * @return {{timestamp: number, lastStartTimeIndex: number, lastEndTimeIndex: number}} + */ + static _findEffectiveTimestamp(data) { + const { + earliestPossibleTimestamp, + latestPossibleTimestamp, + knownTasksByStartTime, + knownTaskStartTimeIndex, + knownTasksByEndTime, + knownTaskEndTimeIndex, + } = data; + + const {tasks: knownTasksStarting, lastIndex: lastStartTimeIndex} = this._getTasksInRange( + knownTasksByStartTime, + { + type: 'startTime', + initialIndex: knownTaskStartTimeIndex, + earliestPossibleTimestamp, + latestPossibleTimestamp, + } + ); + + const {tasks: knownTasksEnding, lastIndex: lastEndTimeIndex} = this._getTasksInRange( + knownTasksByEndTime, + { + type: 'endTime', + initialIndex: knownTaskEndTimeIndex, + earliestPossibleTimestamp, + latestPossibleTimestamp, + } + ); + + // First, find all the tasks that span *across* (not fully contained within) our ambiguous range. + const knownTasksStartingNotContained = knownTasksStarting + .filter(t => !knownTasksEnding.includes(t)); + const knownTasksEndingNotContained = knownTasksEnding + .filter(t => !knownTasksStarting.includes(t)); + + let effectiveTimestamp = latestPossibleTimestamp; + if (knownTasksStartingNotContained.length) { + // Tasks that started but did not finish take priority. Use the earliest of their timestamps. + effectiveTimestamp = Math.min(...knownTasksStartingNotContained.map(t => t.startTime)); + } else if (knownTasksEndingNotContained.length) { + // Tasks that ended but did not start take next priority. Use the latest of their timestamps. + effectiveTimestamp = Math.max(...knownTasksEndingNotContained.map(t => t.endTime)); + } + + return {timestamp: effectiveTimestamp, lastStartTimeIndex, lastEndTimeIndex}; + } + + /** + * Creates B/E-style trace events from a CpuProfile object created by `collectProfileEvents()`. + * An optional set of tasks can be passed in to refine the start/end times. * + * With the sampling profiler we know that a function started/ended *sometime between* two points, + * but not exactly when. Using the information from other tasks gives us more information to be + * more precise with timings and allows us to create a valid task tree later on. + * + * @param {Array} [knownTasks] * @return {Array} */ - createStartEndEvents() { + synthesizeTraceEvents(knownTasks = []) { const profile = this._profile; const length = profile.samples.length; if (profile.timeDeltas.length !== length) throw new Error(`Invalid CPU profile length`); + const knownTasksByStartTime = knownTasks.slice().sort((a, b) => a.startTime - b.startTime); + const knownTasksByEndTime = knownTasks.slice().sort((a, b) => a.endTime - b.endTime); + /** @type {Array} */ const events = []; - let timestamp = profile.startTime; + let currentProfilerTimestamp = profile.startTime; + let lastEffectiveTimestamp = currentProfilerTimestamp; + let knownTaskStartTimeIndex = 0; + let knownTaskEndTimeIndex = 0; /** @type {Array} */ let lastActiveNodeIds = []; for (let i = 0; i < profile.samples.length; i++) { @@ -176,16 +278,37 @@ class CpuProfilerModel { const node = this._nodesById.get(nodeId); if (!node) throw new Error(`Missing node ${nodeId}`); - timestamp += timeDelta; + const { + timestamp: effectiveTimestamp, + lastStartTimeIndex, + lastEndTimeIndex, + } = CpuProfilerModel._findEffectiveTimestamp({ + earliestPossibleTimestamp: lastEffectiveTimestamp, + latestPossibleTimestamp: currentProfilerTimestamp + timeDelta, + knownTaskStartTimeIndex, + knownTaskEndTimeIndex, + knownTasksByStartTime, + knownTasksByEndTime, + }); + + currentProfilerTimestamp += timeDelta; + lastEffectiveTimestamp = effectiveTimestamp; + knownTaskStartTimeIndex = lastStartTimeIndex; + knownTaskEndTimeIndex = lastEndTimeIndex; + const activeNodeIds = this._getActiveNodeIds(nodeId); events.push( - ...this._createStartEndEventsForTransition(timestamp, lastActiveNodeIds, activeNodeIds) + ...this._synthesizeTraceEventsForTransition( + effectiveTimestamp, + lastActiveNodeIds, + activeNodeIds + ) ); lastActiveNodeIds = activeNodeIds; } events.push( - ...this._createStartEndEventsForTransition(timestamp, lastActiveNodeIds, []) + ...this._synthesizeTraceEventsForTransition(currentProfilerTimestamp, lastActiveNodeIds, []) ); return events; @@ -195,16 +318,17 @@ class CpuProfilerModel { * Creates B/E-style trace events from a CpuProfile object created by `collectProfileEvents()` * * @param {CpuProfile} profile + * @param {Array} tasks * @return {Array} */ - static createStartEndEvents(profile) { + static synthesizeTraceEvents(profile, tasks) { const model = new CpuProfilerModel(profile); - return model.createStartEndEvents(); + return model.synthesizeTraceEvents(tasks); } /** * Merges the data of all the `ProfileChunk` trace events into a single CpuProfile object for consumption - * by `createStartEndEvents()`. + * by `synthesizeTraceEvents()`. * * @param {Array} traceEvents * @return {Array} @@ -217,7 +341,7 @@ class CpuProfilerModel { if (typeof event.id !== 'string') continue; // `Profile` or `ProfileChunk` can partially define these across multiple events. - // We'll fallback to empty values and worry about validation in the `createStartEndEvents` phase. + // We'll fallback to empty values and worry about validation in the `synthesizeTraceEvents` phase. const cpuProfileArg = (event.args.data && event.args.data.cpuProfile) || {}; const timeDeltas = (event.args.data && event.args.data.timeDeltas) || cpuProfileArg.timeDeltas; diff --git a/lighthouse-core/lib/tracehouse/main-thread-tasks.js b/lighthouse-core/lib/tracehouse/main-thread-tasks.js index f1eb26aeeb47..de52c7c27b4d 100644 --- a/lighthouse-core/lib/tracehouse/main-thread-tasks.js +++ b/lighthouse-core/lib/tracehouse/main-thread-tasks.js @@ -598,6 +598,85 @@ class MainThreadTasks { return tasks; } + + /** + * Prints an artistic rendering of the task tree for easier debugability. + * + * @param {TaskNode[]} tasks + * @param {{printWidth?: number, startTime?: number, endTime?: number, taskLabelFn?: (node: TaskNode) => string}} options + * @return {string} + */ + static printTaskTreeToDebugString(tasks, options = {}) { + const traceEndMs = Math.max(...tasks.map(t => t.endTime), 0); + const { + printWidth = 100, + startTime = 0, + endTime = traceEndMs, + taskLabelFn = node => node.event.name, + } = options; + + /** @param {TaskNode} task */ + function computeTaskDepth(task) { + let depth = 0; + for (; task.parent; task = task.parent) depth++; + return depth; + } + + const traceRange = endTime - startTime; + const characterInMs = traceRange / printWidth; + + /** @type {Map} */ + const taskLegend = new Map(); + + /** @type {Map} */ + const tasksByDepth = new Map(); + for (const task of tasks) { + if (task.startTime > endTime || task.endTime < startTime) continue; + + const depth = computeTaskDepth(task); + const tasksAtDepth = tasksByDepth.get(depth) || []; + tasksAtDepth.push(task); + tasksByDepth.set(depth, tasksAtDepth); + + // Create a user-friendly ID for new tasks using a capital letter. + // 65 is the ASCII code for 'A' and there are 26 letters in the english alphabet. + const id = String.fromCharCode(65 + (taskLegend.size % 26)); + taskLegend.set(task, {id, task}); + } + + const debugStringLines = [ + `Trace Duration: ${traceEndMs.toFixed(0)}ms`, + `Range: [${startTime}, ${endTime}]`, + `█ = ${characterInMs.toFixed(2)}ms`, + '', + ]; + + const increasingDepth = Array.from(tasksByDepth.entries()).sort((a, b) => a[0] - b[0]); + for (const [, tasks] of increasingDepth) { + const taskRow = Array.from({length: printWidth}).map(() => ' '); + + for (const task of tasks) { + const taskStart = Math.max(task.startTime, startTime); + const taskEnd = Math.min(task.endTime, endTime); + + const {id} = taskLegend.get(task) || {id: '?'}; + const startIndex = Math.floor(taskStart / characterInMs); + const endIndex = Math.floor(taskEnd / characterInMs); + const idIndex = Math.floor((startIndex + endIndex) / 2); + for (let i = startIndex; i <= endIndex; i++) taskRow[i] = '█'; + for (let i = 0; i < id.length; i++) taskRow[idIndex] = id; + } + + debugStringLines.push(taskRow.join('')); + } + + debugStringLines.push(''); + for (const {id, task} of taskLegend.values()) { + debugStringLines.push(`${id} = ${taskLabelFn(task)}`); + } + + return debugStringLines.join('\n'); + } } module.exports = MainThreadTasks; diff --git a/lighthouse-core/test/lib/tracehouse/cpu-profile-model-test.js b/lighthouse-core/test/lib/tracehouse/cpu-profile-model-test.js index e6c1f3090bfc..b0fd821a4213 100644 --- a/lighthouse-core/test/lib/tracehouse/cpu-profile-model-test.js +++ b/lighthouse-core/test/lib/tracehouse/cpu-profile-model-test.js @@ -44,10 +44,106 @@ describe('CPU Profiler Model', () => { }; }); - describe('#createStartEndEvents', () => { + describe('#_findEffectiveTimestamp', () => { + it('should default to the latest possible timestamp when no task data available', () => { + const result = CpuProfilerModel._findEffectiveTimestamp({ + earliestPossibleTimestamp: 0, + latestPossibleTimestamp: 1000, + knownTasksByStartTime: [], + knownTaskStartTimeIndex: 0, + knownTasksByEndTime: [], + knownTaskEndTimeIndex: 0, + }); + + expect(result).toEqual({timestamp: 1000, lastStartTimeIndex: 0, lastEndTimeIndex: 0}); + }); + + it('should use the latest possible timestamp when tasks fully include range', () => { + const tasks = [{startTime: 500, endTime: 2500}]; + const result = CpuProfilerModel._findEffectiveTimestamp({ + earliestPossibleTimestamp: 1000, + latestPossibleTimestamp: 2000, + knownTasksByStartTime: tasks, + knownTaskStartTimeIndex: 0, + knownTasksByEndTime: tasks, + knownTaskEndTimeIndex: 0, + }); + + expect(result).toEqual({timestamp: 2000, lastStartTimeIndex: 1, lastEndTimeIndex: 0}); + }); + + it('should use the latest possible timestamp when tasks are fully contained in range', () => { + const tasks = [{startTime: 250, endTime: 750}]; + const result = CpuProfilerModel._findEffectiveTimestamp({ + earliestPossibleTimestamp: 0, + latestPossibleTimestamp: 1000, + knownTasksByStartTime: tasks, + knownTaskStartTimeIndex: 0, + knownTasksByEndTime: tasks, + knownTaskEndTimeIndex: 0, + }); + + expect(result).toEqual({timestamp: 1000, lastStartTimeIndex: 1, lastEndTimeIndex: 1}); + }); + + it('should use earliest of the start task timestamps when tasks started in range', () => { + const tasks = [{startTime: 250, endTime: 2000}]; + const result = CpuProfilerModel._findEffectiveTimestamp({ + earliestPossibleTimestamp: 0, + latestPossibleTimestamp: 1000, + knownTasksByStartTime: tasks, + knownTaskStartTimeIndex: 0, + knownTasksByEndTime: tasks, + knownTaskEndTimeIndex: 0, + }); + + expect(result).toEqual({timestamp: 250, lastStartTimeIndex: 1, lastEndTimeIndex: 0}); + }); + + it('should use latest of the end task timestamps when tasks ended in range', () => { + const tasks = [{startTime: 250, endTime: 1500}]; + const result = CpuProfilerModel._findEffectiveTimestamp({ + earliestPossibleTimestamp: 1000, + latestPossibleTimestamp: 2000, + knownTasksByStartTime: tasks, + knownTaskStartTimeIndex: 0, + knownTasksByEndTime: tasks, + knownTaskEndTimeIndex: 0, + }); + + expect(result).toEqual({timestamp: 1500, lastStartTimeIndex: 1, lastEndTimeIndex: 1}); + }); + + it('should handle multiple tasks', () => { + const tasks = [ + {startTime: 250, endTime: 1500}, + {startTime: 500, endTime: 1400}, + {startTime: 1100, endTime: 1200}, + {startTime: 1700, endTime: 1800}, + {startTime: 1900, endTime: 2200}, + {startTime: 1925, endTime: 1975}, + ]; + + // TODO: eventually, this should split the start and end effective timestamps. + // For now it assumes both are the same timestamp which forces this to choose the latest option. + // Eventually the endTimestamp should be 1500 and the startTimestamp should be 1900. + const result = CpuProfilerModel._findEffectiveTimestamp({ + earliestPossibleTimestamp: 1000, + latestPossibleTimestamp: 2000, + knownTasksByStartTime: tasks, + knownTaskStartTimeIndex: 0, + knownTasksByEndTime: tasks.slice().sort((a, b) => a.endTime - b.endTime), + knownTaskEndTimeIndex: 0, + }); + + expect(result).toEqual({timestamp: 1900, lastStartTimeIndex: 6, lastEndTimeIndex: 5}); + }); + }); + + describe('#synthesizeTraceEvents', () => { it('should create events in order', () => { - const ts = x => 9e6 + x; - const events = CpuProfilerModel.createStartEndEvents(profile); + const ts = x => profile.startTime + x; + const events = CpuProfilerModel.synthesizeTraceEvents(profile); expect(events).toMatchObject([ {ph: 'B', ts: ts(10e3), args: {data: {callFrame: {functionName: '(root)'}}}}, @@ -65,9 +161,43 @@ describe('CPU Profiler Model', () => { ]); }); + it('should create events while aware of other tasks', () => { + const ts = x => profile.startTime + x; + + // With the sampling profiler we know that Baz and Foo ended *sometime between* 17e3 and 18e3. + // We want to make sure when additional task information is present, we refine the end time. + const tasks = [ + // The RunTask at the toplevel, should move start time of Foo to 8.0e3 and end time to 17.5e3 + {startTime: ts(8.0e3), endTime: ts(17.5e3)}, + // The EvaluateScript at the 2nd level, should not affect anything. + {startTime: ts(9.0e3), endTime: ts(17.4e3)}, + // A small task inside Baz, should move the start time of Baz to 12.5e3. + {startTime: ts(12.5e3), endTime: ts(13.4e3)}, + // A small task inside Foo, should move the end time of Bar to 15.7e3, start time of Baz to 16.8e3. + {startTime: ts(15.7e3), endTime: ts(16.8e3)}, + ]; + + const events = CpuProfilerModel.synthesizeTraceEvents(profile, tasks); + + expect(events).toMatchObject([ + {ph: 'B', ts: ts(8.0e3), args: {data: {callFrame: {functionName: '(root)'}}}}, + {ph: 'B', ts: ts(8.0e3), args: {data: {callFrame: {functionName: '(program)'}}}}, + {ph: 'B', ts: ts(8.0e3), args: {data: {callFrame: {functionName: 'Foo'}}}}, + {ph: 'B', ts: ts(12.0e3), args: {data: {callFrame: {functionName: 'Bar'}}}}, + {ph: 'B', ts: ts(12.5e3), args: {data: {callFrame: {functionName: 'Baz'}}}}, + {ph: 'E', ts: ts(13.4e3), args: {data: {callFrame: {functionName: 'Baz'}}}}, + {ph: 'E', ts: ts(15.7e3), args: {data: {callFrame: {functionName: 'Bar'}}}}, + {ph: 'B', ts: ts(16.8e3), args: {data: {callFrame: {functionName: 'Baz'}}}}, + {ph: 'E', ts: ts(17.5e3), args: {data: {callFrame: {functionName: 'Baz'}}}}, + {ph: 'E', ts: ts(17.5e3), args: {data: {callFrame: {functionName: 'Foo'}}}}, + {ph: 'E', ts: ts(19.0e3), args: {data: {callFrame: {functionName: '(program)'}}}}, + {ph: 'E', ts: ts(19.0e3), args: {data: {callFrame: {functionName: '(root)'}}}}, + ]); + }); + it('should create main-thread-task parseable events', () => { - const ts = x => 9e6 + x; - const events = CpuProfilerModel.createStartEndEvents(profile); + const ts = x => profile.startTime + x; + const events = CpuProfilerModel.synthesizeTraceEvents(profile); const tasks = MainThreadTasks.getMainThreadTasks(events, [], ts(19e3)); expect(tasks).toHaveLength(6); @@ -83,24 +213,52 @@ describe('CPU Profiler Model', () => { const fooTask = tasks[0].children[0].children[0]; expect(fooTask).toMatchObject({ + startTime: 0, + endTime: 8, event: {args: {data: {callFrame: {functionName: 'Foo'}}}}, children: [ { + startTime: 2, + endTime: 6, event: {args: {data: {callFrame: {functionName: 'Bar'}}}}, children: [{event: {args: {data: {callFrame: {functionName: 'Baz'}}}}}], }, { + startTime: 7, + endTime: 8, event: {args: {data: {callFrame: {functionName: 'Baz'}}}}, children: [], }, ], }); + + const visualization = MainThreadTasks.printTaskTreeToDebugString(tasks, { + printWidth: 80, + }).replace(/ +\n/g, '\n'); + expect(visualization).toMatchInlineSnapshot(` + "Trace Duration: 9ms + Range: [0, 9] + █ = 0.11ms + + ████████████████████████████████████████A████████████████████████████████████████ + ████████████████████████████████████████B████████████████████████████████████████ + ███████████████████████████████████C████████████████████████████████████ + ██████████████████D██████████████████ ████F█████ + ████E█████ + + A = FunctionCall-SynthesizedByProfilerModel + B = FunctionCall-SynthesizedByProfilerModel + C = FunctionCall-SynthesizedByProfilerModel + D = FunctionCall-SynthesizedByProfilerModel + E = FunctionCall-SynthesizedByProfilerModel + F = FunctionCall-SynthesizedByProfilerModel" + `); }); it('should work on a real trace', () => { const {processEvents} = TraceProcessor.computeTraceOfTab(profilerTrace); const profiles = CpuProfileModel.collectProfileEvents(processEvents); - const events = CpuProfileModel.createStartEndEvents(profiles[0]); + const events = CpuProfileModel.synthesizeTraceEvents(profiles[0]); expect(events).toHaveLength(230); const lastTs = events[events.length - 1].length; const tasks = MainThreadTasks.getMainThreadTasks(events, [], lastTs); 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 568c148f94e3..43747882bfdb 100644 --- a/lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js +++ b/lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js @@ -805,14 +805,41 @@ describe('Main Thread Tasks', () => { for (const invalidEvents of invalidEventSets) { it('should throw on invalid task input', () => { + const traceEvents = [...boilerplateTrace, ...invalidEvents]; + traceEvents.forEach(evt => Object.assign(evt, {cat: 'devtools.timeline'})); + expect(() => run({traceEvents})).toThrow(); + }); + } + + describe('printTaskTreeToDebugString', () => { + it('should print a nice-looking task tree', () => { const traceEvents = [ ...boilerplateTrace, - ...invalidEvents, + {ph: 'X', name: 'TaskA', pid, tid, ts: baseTs, dur: 100e3, args}, + {ph: 'B', name: 'TaskB', pid, tid, ts: baseTs + 5e3, args}, + {ph: 'X', name: 'TaskC', pid, tid, ts: baseTs + 10e3, dur: 30e3, args}, + {ph: 'E', name: 'TaskB', pid, tid, ts: baseTs + 55e3, args}, + {ph: 'X', name: 'TaskD', pid, tid, ts: baseTs + 60e3, dur: 30e3, args}, ]; traceEvents.forEach(evt => Object.assign(evt, {cat: 'devtools.timeline'})); - expect(() => run({traceEvents})).toThrow(); + const tasks = run({traceEvents}); + const taskTreeAsString = MainThreadTasks.printTaskTreeToDebugString(tasks, {printWidth: 50}); + expect(taskTreeAsString).toMatchInlineSnapshot(` + "Trace Duration: 100ms + Range: [0, 100] + █ = 2.00ms + + █████████████████████████A█████████████████████████ + ████████████B█████████████ ███████D████████ + ███████C████████ + + A = TaskA + B = TaskB + C = TaskC + D = TaskD" + `); }); - } + }); });