From de23f3734209f429bd83856998040f78583fb196 Mon Sep 17 00:00:00 2001 From: Patrick Hulce Date: Thu, 8 Oct 2020 11:46:57 -0500 Subject: [PATCH] more tests and renames --- .../lib/tracehouse/cpu-profile-model.js | 59 +++--- .../lib/tracehouse/main-thread-tasks.js | 6 +- .../lib/tracehouse/cpu-profile-model-test.js | 176 +++++++++++++++--- 3 files changed, 182 insertions(+), 59 deletions(-) diff --git a/lighthouse-core/lib/tracehouse/cpu-profile-model.js b/lighthouse-core/lib/tracehouse/cpu-profile-model.js index cc9787585f67..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)) @@ -160,14 +160,14 @@ class CpuProfilerModel { * re-traversing the entire array. * * @param {Array<{startTime: number, endTime: number}>} knownTasks - * @param {{type: 'startTime'|'endTime', lastKnownTaskIndex: number, earliestPossibleTimestamp: number, latestPossibleTimestamp: number}} options + * @param {{type: 'startTime'|'endTime', initialIndex: number, earliestPossibleTimestamp: number, latestPossibleTimestamp: number}} options */ - _getTasksInRange(knownTasks, options) { - const {type, lastKnownTaskIndex, earliestPossibleTimestamp, latestPossibleTimestamp} = options; + static _getTasksInRange(knownTasks, options) { + const {type, initialIndex, earliestPossibleTimestamp, latestPossibleTimestamp} = options; /** @type {Array<{startTime: number, endTime: number}>} */ const matchingTasks = []; - for (let i = lastKnownTaskIndex; i < knownTasks.length; i++) { + 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; @@ -193,24 +193,24 @@ class CpuProfilerModel { * 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, lastKnownTaskStartTimeIndex: number, lastKnownTaskEndTimeIndex: number, knownTasksByStartTime: Array<{startTime: number, endTime: number}>, knownTasksByEndTime: Array<{startTime: number, endTime: number}>}} data + * @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}} */ - _findEffectiveTimestamp(data) { + static _findEffectiveTimestamp(data) { const { earliestPossibleTimestamp, latestPossibleTimestamp, knownTasksByStartTime, - lastKnownTaskStartTimeIndex, + knownTaskStartTimeIndex, knownTasksByEndTime, - lastKnownTaskEndTimeIndex, + knownTaskEndTimeIndex, } = data; const {tasks: knownTasksStarting, lastIndex: lastStartTimeIndex} = this._getTasksInRange( knownTasksByStartTime, { type: 'startTime', - lastKnownTaskIndex: lastKnownTaskStartTimeIndex, + initialIndex: knownTaskStartTimeIndex, earliestPossibleTimestamp, latestPossibleTimestamp, } @@ -220,7 +220,7 @@ class CpuProfilerModel { knownTasksByEndTime, { type: 'endTime', - lastKnownTaskIndex: lastKnownTaskEndTimeIndex, + initialIndex: knownTaskEndTimeIndex, earliestPossibleTimestamp, latestPossibleTimestamp, } @@ -255,7 +255,7 @@ class CpuProfilerModel { * @param {Array} [knownTasks] * @return {Array} */ - createStartEndEvents(knownTasks = []) { + synthesizeTraceEvents(knownTasks = []) { const profile = this._profile; const length = profile.samples.length; if (profile.timeDeltas.length !== length) throw new Error(`Invalid CPU profile length`); @@ -266,10 +266,10 @@ class CpuProfilerModel { /** @type {Array} */ const events = []; - let profilerTimestamp = profile.startTime; - let lastEffectiveTimestamp = profilerTimestamp; - let lastKnownTaskStartTimeIndex = 0; - let lastKnownTaskEndTimeIndex = 0; + 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++) { @@ -278,28 +278,27 @@ class CpuProfilerModel { const node = this._nodesById.get(nodeId); if (!node) throw new Error(`Missing node ${nodeId}`); - const { timestamp: effectiveTimestamp, lastStartTimeIndex, lastEndTimeIndex, - } = this._findEffectiveTimestamp({ + } = CpuProfilerModel._findEffectiveTimestamp({ earliestPossibleTimestamp: lastEffectiveTimestamp, - latestPossibleTimestamp: profilerTimestamp + timeDelta, - lastKnownTaskStartTimeIndex, - lastKnownTaskEndTimeIndex, + latestPossibleTimestamp: currentProfilerTimestamp + timeDelta, + knownTaskStartTimeIndex, + knownTaskEndTimeIndex, knownTasksByStartTime, knownTasksByEndTime, }); - profilerTimestamp += timeDelta; + currentProfilerTimestamp += timeDelta; lastEffectiveTimestamp = effectiveTimestamp; - lastKnownTaskStartTimeIndex = lastStartTimeIndex; - lastKnownTaskEndTimeIndex = lastEndTimeIndex; + knownTaskStartTimeIndex = lastStartTimeIndex; + knownTaskEndTimeIndex = lastEndTimeIndex; const activeNodeIds = this._getActiveNodeIds(nodeId); events.push( - ...this._createStartEndEventsForTransition( + ...this._synthesizeTraceEventsForTransition( effectiveTimestamp, lastActiveNodeIds, activeNodeIds @@ -309,7 +308,7 @@ class CpuProfilerModel { } events.push( - ...this._createStartEndEventsForTransition(profilerTimestamp, lastActiveNodeIds, []) + ...this._synthesizeTraceEventsForTransition(currentProfilerTimestamp, lastActiveNodeIds, []) ); return events; @@ -322,14 +321,14 @@ class CpuProfilerModel { * @param {Array} tasks * @return {Array} */ - static createStartEndEvents(profile, tasks) { + static synthesizeTraceEvents(profile, tasks) { const model = new CpuProfilerModel(profile); - return model.createStartEndEvents(tasks); + 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} @@ -342,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 3566ce0a5a41..de52c7c27b4d 100644 --- a/lighthouse-core/lib/tracehouse/main-thread-tasks.js +++ b/lighthouse-core/lib/tracehouse/main-thread-tasks.js @@ -603,13 +603,13 @@ class MainThreadTasks { * 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 + * @param {{printWidth?: number, startTime?: number, endTime?: number, taskLabelFn?: (node: TaskNode) => string}} options * @return {string} */ - static printTaskTreeToDebugString(tasks, options) { + static printTaskTreeToDebugString(tasks, options = {}) { const traceEndMs = Math.max(...tasks.map(t => t.endTime), 0); const { - printWidth, + printWidth = 100, startTime = 0, endTime = traceEndMs, taskLabelFn = node => node.event.name, 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 ab3a18e3056d..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)'}}}}, @@ -71,37 +167,37 @@ describe('CPU Profiler Model', () => { // 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 80e2 and end time to 175e2 - {startTime: ts(80e2), endTime: ts(175e2)}, + // 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(90e2), endTime: ts(174e2)}, - // A small task inside Baz, should move the start time of Baz to 125e2. - {startTime: ts(125e2), endTime: ts(134e2)}, - // A small task inside Foo, should move the end time of Bar to 157e2, start time of Baz to 168e2. - {startTime: ts(157e2), endTime: ts(168e2)}, + {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.createStartEndEvents(profile, tasks); + const events = CpuProfilerModel.synthesizeTraceEvents(profile, tasks); expect(events).toMatchObject([ - {ph: 'B', ts: ts(80e2), args: {data: {callFrame: {functionName: '(root)'}}}}, - {ph: 'B', ts: ts(80e2), args: {data: {callFrame: {functionName: '(program)'}}}}, - {ph: 'B', ts: ts(80e2), args: {data: {callFrame: {functionName: 'Foo'}}}}, - {ph: 'B', ts: ts(120e2), args: {data: {callFrame: {functionName: 'Bar'}}}}, - {ph: 'B', ts: ts(125e2), args: {data: {callFrame: {functionName: 'Baz'}}}}, - {ph: 'E', ts: ts(134e2), args: {data: {callFrame: {functionName: 'Baz'}}}}, - {ph: 'E', ts: ts(157e2), args: {data: {callFrame: {functionName: 'Bar'}}}}, - {ph: 'B', ts: ts(168e2), args: {data: {callFrame: {functionName: 'Baz'}}}}, - {ph: 'E', ts: ts(175e2), args: {data: {callFrame: {functionName: 'Baz'}}}}, - {ph: 'E', ts: ts(175e2), args: {data: {callFrame: {functionName: 'Foo'}}}}, - {ph: 'E', ts: ts(190e2), args: {data: {callFrame: {functionName: '(program)'}}}}, - {ph: 'E', ts: ts(190e2), args: {data: {callFrame: {functionName: '(root)'}}}}, + {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); @@ -117,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);