core(tracehouse): sort trace events by nesting order #9230

patrickhulce · 2019-06-18T22:16:17Z

Context
We expect trace events to be in the correct order when we try to build out our picture of main thread activity (main-thread-tasks, page-dependency-graph, etc). Up until today, we thought that meant just stable sorting by .ts based on previous conversations with tracing folks. Then @aslushnikov discovered that we should also be sorting by dur (aslushnikov/tracium#11). This isn't the full story though because that only covers X events and this situation pops up with interleaved B/X events as well.

This PR sorts our trace events by .ts and then breaks ties by sorting in the correct parent/child nesting order for parsing in main-thread-tasks rather than just stable sort.

I've convinced myself by this point that we can't solve the problem just this way though. There are traces in the wild that simply do not have a possible sorted order that is logically consistent and if we ever want to handle those we must make our trace event consumers robust enough to handle inconsistency. (If you've made it this far in the wall of text, enjoy this cookie 🍪:D) If we're doing that then there' no strong reason to have the duplicate-ish logic of robust event handling here, and we could continue to sort by timestamp and have that be the only invariant to traceEvents coming out of traceOfTab if folks prefer that approach.

Questions

Do we want to support these incoherent cases at all? IMO, yes.
If we do, should we try sorting the events in the order we thought we were receiving them like this PR does? IMO, yes.

Related Issues/PRs
aslushnikov/tracium#8
aslushnikov/tracium#11
#7764

brendankenny · 2019-06-21T01:53:18Z

There are traces in the wild that simply do not have a possible sorted order that is logically consistent

that doesn't really seem possible with just B/E/X events, unless you mean sorted order + additional constraints we know to be true? Nesting? Or more than that

(currently actually reviewing but was curious :)

patrickhulce · 2019-06-21T02:33:11Z

that doesn't really seem possible with just B/E/X events

Hahaha, well that's exactly the problem!

A child shouldn't possibly end after its parent, but sometimes in the wild the timestamps we're given indicate this.

Example:

Parent Event (1 X Event)
0 ------------------------------------- 100
Child Event (1 B + 1 E Event)
                50 -------------------- 101

Parent Event (1 X Event)
0 ------------------------------------- 100
Child Event (1 B + 1 E Event)
0 -------------------- 50

No amount of sorting the first 3 events will ever lead to an interpretation that is logically consistent with how traces/tasks should work, but situations like next set of 3 events can be solved by sorting events in the correct nesting order (with X event starting the task first).

patrickhulce · 2019-07-16T15:47:25Z

I haven't been pushing this because of the extra need for consumption changes, but a call either way if we're pursuing this is necessary for the next phase, so input welcome :)

brendankenny · 2019-07-16T16:03:24Z

From my quick review a month ago this seemed like the right call. Even if we still have to do more work in trace consumers, at least this level of event sorting will be correct.

Thanks for your extreme patience :) let's get it back in the active queue

patrickhulce · 2019-07-25T20:07:06Z

What are the next steps to receive feedback in the active queue? :)

brendankenny

looking good. The performance characteristics worry me a bit, but looking at some real traces, so few events go through this stage that it's not too bad at all. Current PR is about 38% slower than master on an example verge trace, trying out some ideas I mention below gets that down to about 23%, but we're talking 100 milliseconds so the absolute difference isn't very big.

lighthouse-core/lib/tracehouse/trace-processor.js

brendankenny · 2019-07-26T01:02:56Z

lighthouse-core/lib/tracehouse/trace-processor.js

@@ -66,10 +66,68 @@ class TraceProcessor {
  }

  /**
+   * This method sorts a group of trace events that have the same timestamp. We want to...
+   *
+   * 1. Put E events first, we finish off our existing events before we start new ones.


can a B/E pair ever have the same ts? If so, this would misorder them.

If so, there's no other way for us to know at this stage either because we now know the order they came in doesn't really mean anything. We'll have to handle this on consumption side like we do with the other problematic cases then.

If so, there's no other way for us to know at this stage either because we now know the order they came in doesn't really mean anything. We'll have to handle this on consumption side like we do with the other problematic cases then.

hmm, but in that case wouldn't just ordering them B then E fix it? The hard part would be knowing how to connect the two

this kinda gets at the fact that there are still lots of edge cases where we have to change our consumption. this won't particularly matter with the PR I'm about to open so I have no strong feelings here.

can a B/E pair ever have the same ts?

so I instrumented this code a bit and ran it over a good set of gnarly traces and never found any instance where this happened if we differentiate by event name and pid.

so I instrumented this code a bit and ran it over a good set of gnarly traces and never found any instance where this happened if we differentiate by event name and pid.

Actually, lighthouse-core/test/fixtures/traces/tracingstarted-after-navstart.json does fail at this, but unclear if it's from us editing it :)

this conflict should be resolved by #9491 + this existing work, so I would vote to punt, it's already captured in a test in #9491 👍

lighthouse-core/lib/tracehouse/trace-processor.js

brendankenny · 2019-08-01T00:08:01Z

lighthouse-core/lib/tracehouse/trace-processor.js

@@ -66,10 +66,68 @@ class TraceProcessor {
  }

  /**
+   * This method sorts a group of trace events that have the same timestamp. We want to...
+   *
+   * 1. Put E events first, we finish off our existing events before we start new ones.


can a B/E pair ever have the same ts?

so I instrumented this code a bit and ran it over a good set of gnarly traces and never found any instance where this happened if we differentiate by event name and pid.

lighthouse-core/lib/tracehouse/trace-processor.js

brendankenny

LGTM! This is going to be a great improvement

brendankenny · 2019-08-01T18:42:41Z

lighthouse-core/lib/tracehouse/trace-processor.js

+   * 1. Put E events first, we finish off our existing events before we start new ones.
+   * 2. Order B/X events by their duration, we want parents to start before child events.
+   * 3. If we don't have any of this to go on, just use the position in the original array (stable sort).
+   *


is it worth calling out for future readers that this is expected to usually get tsGroupIndices lengths on the order of 10 (and often closer to 1?). Obviously future readers can use profilers, too, but it does jump out as something pretty heavyweight to run over a whole trace when actually it's run over a pretty small part of a trace

yeah good call, it's a good reminder we'll all need for the next poor sap to touch trace events 👍 😆

core(tracehouse): sort trace events by nesting order

4852262

patrickhulce requested review from brendankenny and paulirish as code owners June 18, 2019 22:16

googlebot added the cla: yes label Jun 18, 2019

patrickhulce mentioned this pull request Jun 19, 2019

Fatal trace logic error - expected start event, got X #7764

Closed

brendankenny mentioned this pull request Jun 26, 2019

Investigate increase in "bootup-time" errors #7691

Closed

paulirish mentioned this pull request Jul 16, 2019

Merging into Lighthouse aslushnikov/tracium#2

Open

brendankenny reviewed Jul 26, 2019

View reviewed changes

patrickhulce added 3 commits July 30, 2019 10:30

Merge branch 'master' into sort_same_ts

575aa1d

feedback

5db102d

lint

79a53fe

vercel bot deployed to staging July 30, 2019 16:22 View deployment

patrickhulce mentioned this pull request Jul 31, 2019

core(tracehouse): structure main thread task creation to be more forgiving #9491

Merged

brendankenny reviewed Aug 1, 2019

View reviewed changes

clarify index types

30b5eb7

vercel bot deployed to staging August 1, 2019 16:03 View deployment

brendankenny approved these changes Aug 1, 2019

View reviewed changes

add comment about trace size

28876ba

vercel bot deployed to staging August 1, 2019 20:57 View deployment

patrickhulce merged commit 959c499 into master Aug 5, 2019

patrickhulce deleted the sort_same_ts branch August 5, 2019 17:51

patrickhulce mentioned this pull request Oct 18, 2019

Javascript audits failing #9865

Closed

paulirish pushed a commit that referenced this pull request Nov 6, 2019

core(tracehouse): sort trace events by nesting order (#9230)

67f96d9

snyk-bot mentioned this pull request Mar 21, 2020

[Snyk] Upgrade lighthouse from 5.1.0 to 5.6.0 godaddy/lighthouse4u#13

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

core(tracehouse): sort trace events by nesting order #9230

core(tracehouse): sort trace events by nesting order #9230

patrickhulce commented Jun 18, 2019 •

edited by paulirish

brendankenny commented Jun 21, 2019

patrickhulce commented Jun 21, 2019

patrickhulce commented Jul 16, 2019

brendankenny commented Jul 16, 2019

patrickhulce commented Jul 25, 2019

brendankenny left a comment

brendankenny Jul 26, 2019

patrickhulce Jul 30, 2019

brendankenny Jul 31, 2019

patrickhulce Jul 31, 2019

brendankenny Aug 1, 2019

brendankenny Aug 1, 2019

patrickhulce Aug 1, 2019

brendankenny Aug 1, 2019

brendankenny left a comment

brendankenny Aug 1, 2019

patrickhulce Aug 1, 2019

core(tracehouse): sort trace events by nesting order #9230

core(tracehouse): sort trace events by nesting order #9230

Conversation

patrickhulce commented Jun 18, 2019 • edited by paulirish

brendankenny commented Jun 21, 2019

patrickhulce commented Jun 21, 2019

patrickhulce commented Jul 16, 2019

brendankenny commented Jul 16, 2019

patrickhulce commented Jul 25, 2019

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

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

patrickhulce commented Jun 18, 2019 •

edited by paulirish