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

paulirish · 2018-11-01T00:42:33Z

Motivated by #6410

I was avoiding async events for .. mysterious reasons before. But really these will be overlapping, so it makes more sense to be async.

Overlapping happens in promise.all()s often:

Here's how a few timing traces look now:

patrickhulce · 2018-11-01T02:18:44Z

lighthouse-core/lib/timing-trace-saver.js

+    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' ;)


patrickhulce · 2018-11-01T02:22:36Z

lighthouse-core/lib/timing-trace-saver.js

      pid: 0,
-      tid: trackName === 'measures' ? 50 : 75,
-      ph: 'X',
+      tid: threadId,


I feel like I'm missing something.

I only see one call to this method changed with a threadId isn't this basically the same as what was happening before then?

Yeah totally the same as before. trackName => threadId has no functional changes, really. with these new events we can't label the track.
not a huge deal anyway.

patrickhulce · 2018-11-01T02:23:10Z

lighthouse-core/test/lib/timing-trace-saver-test.js

-    expect(consoleError.mock.calls[0][0]).toContain('measures overlap');
+  it('generates a pair of trace event', () => {
+    const events = generateTraceEvents(mockEntries[0]);
+    expect(events).toMatchSnapshot();


lighthouse-core/test/lib/__snapshots__/timing-trace-saver-test.js.snap

+]
+`;
+
+exports[`generateTraceEvents generates a pair of trace event 1`] = `Array []`;


lighthouse-core/lib/timing-trace-saver.js

paulirish · 2018-11-02T19:42:34Z

thoughts?

I've added support for DevTools Perf panel (via adding a TracingStartedInBrowser evt):

Though note: -G/-A traces are shown in two diff tracks in chrome:tracing but that's not supported in DevTools:

patrickhulce

code seems fine to me other than test Q!

paulirish · 2018-11-02T22:10:19Z

lighthouse-core/test/lib/timing-trace-saver-test.js

-    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, 1)).toMatchSnapshot();


exterkamp

nit: zero duration test cov not hit.

paulirish · 2018-11-02T22:10:45Z

lighthouse-core/test/lib/timing-trace-saver-test.js

-    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, 1)).toMatchSnapshot();
  });
 });


good call. actually we dont need the ph:'n' now that we're on async events.
problem solved. :)

brendankenny

LGTM!

brendankenny · 2018-11-02T23:37:36Z

lighthouse-core/lib/timing-trace-saver.js

-    }
-  }
-}
-
 /**
 * Generates a chromium trace file from user timing measures
 * Adapted from https://github.com/tdresser/performance-observer-tracing


maybe add a note about how threadId is used?

brendankenny · 2018-11-02T23:40:31Z

lighthouse-core/lib/timing-trace-saver.js

+      // 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, '꞉'),


😆

maybe do an explicit .replace(/:/g, '\ua789'), just to make it doubly clear that the character is different?

brendankenny · 2018-11-02T23:42:07Z

lighthouse-core/lib/timing-trace-saver.js

+      // 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, '꞉'),
+      cat: 'blink.user_timing',


it feels like doing this should be possible without faking out a browser trace but w/e traceviewer :)

traceviewer wont group these but give each measure its own track otherwise
and devtools needs it to view them.

brendankenny · 2018-11-02T23:44:07Z

lighthouse-core/scripts/generate-timing-trace.js

@@ -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 (or if it's a -G/A run, use chrome://tracing)


does -G/A run refer to a "-G or an -A run", or a -GA run or a regular run (that did both gathering and auditing)?

brendankenny · 2018-11-02T23:46:09Z

(with nits :)

move to async events for overlapping goodness.

151423a

paulirish requested a review from brendankenny as a code owner November 1, 2018 00:42

paulirish requested a review from connorjclark November 1, 2018 00:42

patrickhulce reviewed Nov 1, 2018

View reviewed changes

connorjclark reviewed Nov 1, 2018

View reviewed changes

lighthouse-core/lib/timing-trace-saver.js Show resolved Hide resolved

connorjclark reviewed Nov 1, 2018

View reviewed changes

lighthouse-core/lib/timing-trace-saver.js Outdated Show resolved Hide resolved

feedback

444be63

paulirish force-pushed the timing-trace-async-events branch from 2af3faf to 444be63 Compare November 1, 2018 02:38

add support for viewing trace in devtools

17fa602

patrickhulce reviewed Nov 2, 2018

View reviewed changes

exterkamp reviewed Nov 2, 2018

View reviewed changes

feedback

7397390

brendankenny approved these changes Nov 2, 2018

View reviewed changes

Brendan feedback

7c6941f

paulirish merged commit f4aa2c6 into master Nov 5, 2018

paulirish deleted the timing-trace-async-events branch May 2, 2019 21:56

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

paulirish commented Nov 1, 2018

patrickhulce Nov 1, 2018

patrickhulce Nov 1, 2018

paulirish Nov 1, 2018

patrickhulce Nov 1, 2018

This comment was marked as resolved.

paulirish commented Nov 2, 2018

patrickhulce left a comment

This comment was marked as resolved.

paulirish Nov 2, 2018

exterkamp left a comment

This comment was marked as resolved.

paulirish Nov 2, 2018

brendankenny left a comment

brendankenny Nov 2, 2018

brendankenny Nov 2, 2018

brendankenny Nov 2, 2018

paulirish Nov 5, 2018

brendankenny Nov 2, 2018

brendankenny commented Nov 2, 2018

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

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

Conversation

paulirish commented Nov 1, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

This comment was marked as resolved.

paulirish commented Nov 2, 2018

patrickhulce left a comment

Choose a reason for hiding this comment

This comment was marked as resolved.

Choose a reason for hiding this comment

exterkamp left a comment

Choose a reason for hiding this comment

This comment was marked as resolved.

Choose a reason for hiding this comment

brendankenny left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brendankenny commented Nov 2, 2018