diff --git a/lighthouse-core/lib/timing-trace-saver.js b/lighthouse-core/lib/timing-trace-saver.js index 078d4e2e3906..106f69506aab 100644 --- a/lighthouse-core/lib/timing-trace-saver.js +++ b/lighthouse-core/lib/timing-trace-saver.js @@ -5,70 +5,50 @@ */ 'use strict'; -/** - * Technically, it's fine for usertiming measures to overlap, however non-async events make - * for a much clearer UI in traceviewer. We do this check to make sure we aren't passing off - * async-like measures as non-async. - * prevEntries are expected to be sorted by startTime - * @param {LH.Artifacts.MeasureEntry} entry user timing entry - * @param {LH.Artifacts.MeasureEntry[]} prevEntries user timing entries - */ -function checkEventOverlap(entry, prevEntries) { - for (const prevEntry of prevEntries) { - const prevEnd = prevEntry.startTime + prevEntry.duration; - const thisEnd = entry.startTime + entry.duration; - const isOverlap = prevEnd > entry.startTime && prevEnd < thisEnd; - if (isOverlap) { - // eslint-disable-next-line no-console - console.error(`Two measures overlap! ${prevEntry.name} & ${entry.name}`); - } - } -} - /** * Generates a chromium trace file from user timing measures + * `threadId` can be provided to separate a series of trace events into another thread, useful + * if timings do not share the same timeOrigin, but should both be "left-aligned". * Adapted from https://github.com/tdresser/performance-observer-tracing * @param {LH.Artifacts.MeasureEntry[]} entries user timing entries - * @param {string=} trackName + * @param {number=} threadId */ -function generateTraceEvents(entries, trackName = 'measures') { +function generateTraceEvents(entries, threadId = 0) { if (!Array.isArray(entries)) return []; /** @type {LH.TraceEvent[]} */ const currentTrace = []; - let id = 0; - entries.sort((a, b) => a.startTime - b.startTime); entries.forEach((entry, i) => { - checkEventOverlap(entry, entries.slice(0, i)); - /** @type {LH.TraceEvent} */ - const traceEvent = { - name: entry.name, - cat: entry.entryType, + const startEvt = { + // 1) Remove 'lh:' for readability + // 2) Colons in user_timing names get special handling in traceviewer we don't want. https://goo.gl/m23Vz7 + // Replace with a 'Modifier letter colon' ;) + name: entry.name.replace('lh:', '').replace(/:/g, '\ua789'), + cat: 'blink.user_timing', ts: entry.startTime * 1000, - dur: entry.duration * 1000, args: {}, + dur: 0, pid: 0, - tid: trackName === 'measures' ? 50 : 75, - ph: 'X', - id: '0x' + (id++).toString(16), + tid: threadId, + ph: 'b', + id: '0x' + (i++).toString(16), }; - if (entry.entryType !== 'measure') throw new Error('Unexpected entryType!'); - if (entry.duration === 0) { - traceEvent.ph = 'n'; - traceEvent.s = 't'; - } + const endEvt = JSON.parse(JSON.stringify(startEvt)); + endEvt.ph = 'e'; + endEvt.ts = startEvt.ts + (entry.duration * 1000); - currentTrace.push(traceEvent); + currentTrace.push(startEvt); + currentTrace.push(endEvt); }); // Add labels /** @type {LH.TraceEvent} */ const metaEvtBase = { pid: 0, - tid: trackName === 'measures' ? 50 : 75, + tid: threadId, ts: 0, dur: 0, ph: 'M', @@ -77,8 +57,20 @@ function generateTraceEvents(entries, trackName = 'measures') { args: {labels: 'Default'}, }; currentTrace.push(Object.assign({}, metaEvtBase, {args: {labels: 'Lighthouse Timing'}})); - currentTrace.push(Object.assign({}, metaEvtBase, {name: 'thread_name', args: {name: trackName}})); + // Only inject TracingStartedInBrowser once + if (threadId === 0) { + currentTrace.push(Object.assign({}, metaEvtBase, { + 'cat': 'disabled-by-default-devtools.timeline', + 'name': 'TracingStartedInBrowser', + 'ph': 'I', + 'args': {'data': { + 'frameTreeNodeId': 1, + 'persistentIds': true, + 'frames': [], + }}, + })); + } return currentTrace; } @@ -92,13 +84,12 @@ function createTraceString(lhr) { const entries = lhr.timing.entries.filter(entry => !gatherEntries.includes(entry)); const auditEvents = generateTraceEvents(entries); - const gatherEvents = generateTraceEvents(gatherEntries, 'gather'); + const gatherEvents = generateTraceEvents(gatherEntries, 10); const events = [...auditEvents, ...gatherEvents]; - const jsonStr = ` - { "traceEvents": [ - ${events.map(evt => JSON.stringify(evt)).join(',\n')} - ]}`; + const jsonStr = `{"traceEvents":[ +${events.map(evt => JSON.stringify(evt)).join(',\n')} +]}`; return jsonStr; } diff --git a/lighthouse-core/scripts/generate-timing-trace.js b/lighthouse-core/scripts/generate-timing-trace.js index 055311404d4c..a4ad0c23030f 100644 --- a/lighthouse-core/scripts/generate-timing-trace.js +++ b/lighthouse-core/scripts/generate-timing-trace.js @@ -11,7 +11,7 @@ const {createTraceString} = require('../lib/timing-trace-saver'); /** * @fileoverview This script takes the timing entries saved during a Lighthouse run and generates - * a trace file that's readable in chrome://tracing. + * a trace file that's readable in DevTools perf panel or chrome://tracing. * * input = LHR.json * output = LHR.timing.trace.json @@ -50,7 +50,7 @@ function saveTraceFromCLI() { // eslint-disable-next-line no-console console.log(` > Timing trace file saved to: ${traceFilePath} - > Open this file in chrome://tracing + > Open this file in DevTools perf panel (For --audit-mode runs, use chrome://tracing instead) `); } diff --git a/lighthouse-core/test/lib/__snapshots__/timing-trace-saver-test.js.snap b/lighthouse-core/test/lib/__snapshots__/timing-trace-saver-test.js.snap new file mode 100644 index 000000000000..65eca3948a79 --- /dev/null +++ b/lighthouse-core/test/lib/__snapshots__/timing-trace-saver-test.js.snap @@ -0,0 +1,137 @@ +// Jest Snapshot v1, https://goo.gl/fbAQLP + +exports[`createTraceString creates a real trace 1`] = ` +Array [ + Object { + "args": Object {}, + "cat": "blink.user_timing", + "dur": 0, + "id": "0x0", + "name": "init꞉config", + "ph": "b", + "pid": 0, + "tid": 0, + "ts": 650000, + }, + Object { + "args": Object {}, + "cat": "blink.user_timing", + "dur": 0, + "id": "0x0", + "name": "init꞉config", + "ph": "e", + "pid": 0, + "tid": 0, + "ts": 860000, + }, + Object { + "args": Object {}, + "cat": "blink.user_timing", + "dur": 0, + "id": "0x1", + "name": "runner꞉run", + "ph": "b", + "pid": 0, + "tid": 0, + "ts": 870000, + }, + Object { + "args": Object {}, + "cat": "blink.user_timing", + "dur": 0, + "id": "0x1", + "name": "runner꞉run", + "ph": "e", + "pid": 0, + "tid": 0, + "ts": 990000, + }, + Object { + "args": Object {}, + "cat": "blink.user_timing", + "dur": 0, + "id": "0x2", + "name": "runner꞉auditing", + "ph": "b", + "pid": 0, + "tid": 0, + "ts": 990000, + }, + Object { + "args": Object {}, + "cat": "blink.user_timing", + "dur": 0, + "id": "0x2", + "name": "runner꞉auditing", + "ph": "e", + "pid": 0, + "tid": 0, + "ts": 1740000, + }, + Object { + "args": Object {}, + "cat": "blink.user_timing", + "dur": 0, + "id": "0x3", + "name": "audit꞉is-on-https", + "ph": "b", + "pid": 0, + "tid": 0, + "ts": 1010000, + }, + Object { + "args": Object {}, + "cat": "blink.user_timing", + "dur": 0, + "id": "0x3", + "name": "audit꞉is-on-https", + "ph": "e", + "pid": 0, + "tid": 0, + "ts": 1020000, + }, + Object { + "args": Object { + "data": Object { + "frameTreeNodeId": 1, + "frames": Array [], + "persistentIds": true, + }, + }, + "cat": "disabled-by-default-devtools.timeline", + "dur": 0, + "name": "TracingStartedInBrowser", + "ph": "I", + "pid": 0, + "tid": 0, + "ts": 0, + }, +] +`; + +exports[`generateTraceEvents generates a pair of trace events 1`] = ` +Array [ + Object { + "args": Object {}, + "cat": "blink.user_timing", + "dur": 0, + "id": "0x0", + "name": "init꞉config", + "ph": "b", + "pid": 0, + "tid": 0, + "ts": 650000, + }, + Object { + "args": Object {}, + "cat": "blink.user_timing", + "dur": 0, + "id": "0x0", + "name": "init꞉config", + "ph": "e", + "pid": 0, + "tid": 0, + "ts": 860000, + }, +] +`; diff --git a/lighthouse-core/test/lib/timing-trace-saver-test.js b/lighthouse-core/test/lib/timing-trace-saver-test.js index be3749e9df4b..fa128c5a46d5 100644 --- a/lighthouse-core/test/lib/timing-trace-saver-test.js +++ b/lighthouse-core/test/lib/timing-trace-saver-test.js @@ -9,7 +9,6 @@ /* eslint-disable no-console */ -const assert = require('assert'); const {generateTraceEvents, createTraceString} = require('../../lib/timing-trace-saver'); const mockEntries = [{ @@ -37,92 +36,11 @@ const mockEntries = [{ entryType: 'measure', }, ]; -const expectedTrace = { - traceEvents: [{ - name: 'lh:init:config', - cat: 'measure', - ts: 650000, - dur: 210000, - args: {}, - pid: 0, - tid: 50, - ph: 'X', - id: '0x0', - }, - { - name: 'lh:runner:run', - cat: 'measure', - ts: 870000, - dur: 120000, - args: {}, - pid: 0, - tid: 50, - ph: 'X', - id: '0x1', - }, - { - name: 'lh:runner:auditing', - cat: 'measure', - ts: 990000, - dur: 750000, - args: {}, - pid: 0, - tid: 50, - ph: 'X', - id: '0x2', - }, - { - name: 'lh:audit:is-on-https', - cat: 'measure', - ts: 1010000, - dur: 10000, - args: {}, - pid: 0, - tid: 50, - ph: 'X', - id: '0x3', - }, - ], -}; - describe('generateTraceEvents', () => { - let consoleError; - let origConsoleError; - - beforeEach(() => { - origConsoleError = console.error; - consoleError = jest.fn(); - console.error = consoleError; - }); - - afterEach(() => { - console.error = origConsoleError; - }); - - it('generates a single trace event', () => { - const event = generateTraceEvents(mockEntries); - assert.deepStrictEqual(event.slice(0, 1), expectedTrace.traceEvents.slice(0, 1)); - }); - - it('doesn\'t allow overlapping events', () => { - const overlappingEntries = [{ - startTime: 10, - name: 'overlap1', - duration: 100, - entryType: 'measure', - }, - { - startTime: 30, - name: 'overlap2', - duration: 100, - entryType: 'measure', - }, - ]; - - generateTraceEvents(overlappingEntries); - expect(consoleError).toHaveBeenCalled(); - expect(consoleError.mock.calls[0][0]).toContain('measures overlap'); + it('generates a pair of trace events', () => { + const events = generateTraceEvents([mockEntries[0]]); + expect(events.slice(0, 2)).toMatchSnapshot(); }); }); @@ -135,6 +53,6 @@ describe('createTraceString', () => { }); const traceJson = JSON.parse(jsonStr); const eventsWithoutMetadata = traceJson.traceEvents.filter(e => e.cat !== '__metadata'); - assert.deepStrictEqual(eventsWithoutMetadata, expectedTrace.traceEvents); + expect(eventsWithoutMetadata).toMatchSnapshot(); }); });