Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
Fix trace-event import for many cases where there are 'ts' collisions (…
…#322) The trace event format has a very unfortunate combination of requirements in order to give a best-effort interpretation of a given trace file: 1. Events may be recorded out-of-order by timestamp 2. Events with the *same* timestamp should be processed in the order they were provided in the file. Mostly. The first requirement is written explicitly [in the spec](https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview). > The events do not have to be in timestamp-sorted order. The second one isn't explicitly written, but it's implicitly true because otherwise the interpretation of a file is ambiguous. For example, the following file has all events with the same `ts` field, but re-ordering the fields changes the interpretation. ``` [ { "pid": 0, "tid": 0, "ph": "X", "ts": 0, "dur": 20, "name": "alpha" }, { "pid": 0, "tid": 0, "ph": "X", "ts": 0, "dur": 20, "name": "beta" } } ``` If we allowed arbitrary reordering, it would be ambiguous whether the alpha frame should be nested inside of the beta frame or vice versa. Since traces are interpreted as call trees, it's not okay to just arbitrarily choose. So you might next guess that a reasonable approach would be to do a [stable sort](https://wiki.c2.com/?StableSort) by "ts", then process the events one-by-one. This almost works, except for two additional problems. The first problem is that in some situations this would still yield invalid results. ``` [ {"pid": 0, "tid": 0, "ph": "B", "name": "alpha", "ts": 0}, {"pid": 0, "tid": 0, "ph": "B", "name": "beta", "ts": 0}, {"pid": 0, "tid": 0, "ph": "E", "name": "alpha", "ts": 1}, {"pid": 0, "tid": 0, "ph": "E", "name": "beta", "ts": 1} ] ``` If we were to follow this rule, we would try to execute the `"E"` for alpha before the `"E"` for beta, even though beta is on the top of the stack. So in *that* case, we actually need to execute the `"E"` for beta first, otherwise the resulting profile is incorrect. The other problem with this approach of using the stable sort order is the question of how to deal with `"X"` events. speedscope translates `"X"` events into a `"B"` and `"E"` event pair. But where should it put the `"E"` event? Your first guess might be "at the index where the `"X"` events occur in the file". This runs into trouble in cases like this: ``` [ { "pid": 0, "tid": 0, "ph": "X", "ts": 9, "dur": 1, "name": "beta" }, { "pid": 0, "tid": 0, "ph": "X", "ts": 9, "dur": 2, "name": "gamma" }, ] ``` The most natural translation of this would be to convert it into the following `"B"` and `"E"` events: ``` [ { "pid": 0, "tid": 0, "ph": "B", "ts": 9, "name": "beta" }, { "pid": 0, "tid": 0, "ph": "E", "ts": 10, "name": "beta" }, { "pid": 0, "tid": 0, "ph": "B", "ts": 9, "name": "gamma" }, { "pid": 0, "tid": 0, "ph": "E", "ts": 11, "name": "gamma" }, ] ``` Which, after a stable sort turns into this: ``` [ { "pid": 0, "tid": 0, "ph": "B", "ts": 9, "name": "beta" }, { "pid": 0, "tid": 0, "ph": "B", "ts": 9, "name": "gamma" }, { "pid": 0, "tid": 0, "ph": "E", "ts": 10, "name": "beta" }, { "pid": 0, "tid": 0, "ph": "E", "ts": 11, "name": "gamma" }, ] ``` Notice that we again have a problem where we open "beta" before "gamma", but we need to close "beta" first because it ends first! Ultimately, I couldn't figure out any sort order that would allow me to predict ahead-of-time what order to process the events in. So instead, I create two event queues: one for `"B"` events, and one for `"E"` events, and then try to be clever about how I merge them together. AFAICT, chrome://tracing does not sort events before processing them, which is kind of baffling. But chrome://tracing also has really bizarre behaviour for things like this where the resulting flamegraph isn't even a valid tree (there are overlapping ranges): ``` [ { "pid": 0, "tid": 0, "ph": "X", "ts": 0, "dur": 10, "name": "alpha" }, { "pid": 0, "tid": 0, "ph": "X", "ts": 5, "dur": 10, "name": "beta" } } ``` So I'm going to call this "good enough" for now. Fixes #223 Fixes #320
- Loading branch information
