misc(timing): move timing-trace to async events (#6440)

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;
 }

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)
 `);
 }
 

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,
+  },
+]
+`;

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();
   });
 });