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
This commit is contained in:
Jamie Wong
25
sample/profiles/trace-event/bex-interaction.json
Normal file
25
sample/profiles/trace-event/bex-interaction.json
Normal file
@@ -0,0 +1,25 @@
|
||||
[
|
||||
{ "pid": 0, "tid": 0, "ph": "B", "ts": 0, "name": "A" },
|
||||
{ "pid": 0, "tid": 0, "ph": "E", "ts": 2, "name": "A" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 0, "dur": 2, "name": "B" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 10, "dur": 2, "name": "C" },
|
||||
{ "pid": 0, "tid": 0, "ph": "B", "ts": 10, "name": "D" },
|
||||
{ "pid": 0, "tid": 0, "ph": "E", "ts": 12, "name": "D" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 20, "dur": 1, "name": "E" },
|
||||
{ "pid": 0, "tid": 0, "ph": "B", "ts": 20, "name": "F" },
|
||||
{ "pid": 0, "tid": 0, "ph": "E", "ts": 22, "name": "F" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "B", "ts": 30, "name": "G" },
|
||||
{ "pid": 0, "tid": 0, "ph": "E", "ts": 32, "name": "G" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 30, "dur": 1, "name": "H" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 41, "dur": 1, "name": "I" },
|
||||
{ "pid": 0, "tid": 0, "ph": "B", "ts": 40, "name": "J" },
|
||||
{ "pid": 0, "tid": 0, "ph": "E", "ts": 42, "name": "J" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "B", "ts": 50, "name": "K" },
|
||||
{ "pid": 0, "tid": 0, "ph": "E", "ts": 52, "name": "K" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 51, "dur": 1, "name": "L" }
|
||||
]
|
||||
@@ -0,0 +1,7 @@
|
||||
[
|
||||
{"tid": 1, "ph": "X", "pid": 0, "name": "alpha", "args": {"x": 0}, "ts": 0, "dur": 10},
|
||||
{"tid": 1, "ph": "B", "pid": 0, "name": "beta", "args": {"x": 0}, "ts": 1},
|
||||
{"tid": 1, "ph": "B", "pid": 0, "name": "gamma", "args": {"x": 0}, "ts": 1},
|
||||
{"tid": 1, "ph": "E", "pid": 0, "name": "beta", "args": {"x": 1}, "ts": 2},
|
||||
{"tid": 1, "ph": "E", "pid": 0, "name": "gamma", "args": {"x": 1}, "ts": 2}
|
||||
]
|
||||
4
sample/profiles/trace-event/invalid-x-nesting.json
Normal file
4
sample/profiles/trace-event/invalid-x-nesting.json
Normal file
@@ -0,0 +1,4 @@
|
||||
[
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 0, "dur": 10, "name": "alpha" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 5, "dur": 10, "name": "beta" }
|
||||
]
|
||||
7
sample/profiles/trace-event/matching-x.json
Normal file
7
sample/profiles/trace-event/matching-x.json
Normal file
@@ -0,0 +1,7 @@
|
||||
[
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 0, "dur": 10, "name": "alpha" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 1, "dur": 1, "name": "beta" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 1, "dur": 1, "name": "gamma" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 5, "dur": 1, "name": "gamma" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 5, "dur": 1, "name": "beta" }
|
||||
]
|
||||
15
sample/profiles/trace-event/x-events-matching-end.json
Normal file
15
sample/profiles/trace-event/x-events-matching-end.json
Normal file
@@ -0,0 +1,15 @@
|
||||
[
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 0, "dur": 20, "name": "alpha" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 1, "dur": 2, "name": "beta" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 2, "dur": 1, "name": "gamma" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 5, "dur": 2, "name": "gamma" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 6, "dur": 1, "name": "beta" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 10, "dur": 1, "name": "gamma" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 9, "dur": 2, "name": "beta" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 15, "dur": 1, "name": "beta" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 14, "dur": 2, "name": "gamma" }
|
||||
]
|
||||
15
sample/profiles/trace-event/x-events-matching-start.json
Normal file
15
sample/profiles/trace-event/x-events-matching-start.json
Normal file
@@ -0,0 +1,15 @@
|
||||
[
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 0, "dur": 20, "name": "alpha" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 1, "dur": 2, "name": "beta" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 1, "dur": 1, "name": "gamma" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 5, "dur": 2, "name": "gamma" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 5, "dur": 1, "name": "beta" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 9, "dur": 1, "name": "beta" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 9, "dur": 2, "name": "gamma" },
|
||||
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 13, "dur": 1, "name": "gamma" },
|
||||
{ "pid": 0, "tid": 0, "ph": "X", "ts": 13, "dur": 2, "name": "beta" }
|
||||
]
|
||||
@@ -1,5 +1,142 @@
|
||||
// Jest Snapshot v1, https://goo.gl/fbAQLP
|
||||
|
||||
exports[`importTraceEvents BEX interaction 1`] = `
|
||||
Object {
|
||||
"frames": Array [
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "A",
|
||||
"line": undefined,
|
||||
"name": "A",
|
||||
"selfWeight": 0,
|
||||
"totalWeight": 2,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "B",
|
||||
"line": undefined,
|
||||
"name": "B",
|
||||
"selfWeight": 2,
|
||||
"totalWeight": 2,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "D",
|
||||
"line": undefined,
|
||||
"name": "D",
|
||||
"selfWeight": 0,
|
||||
"totalWeight": 2,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "C",
|
||||
"line": undefined,
|
||||
"name": "C",
|
||||
"selfWeight": 2,
|
||||
"totalWeight": 2,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "F",
|
||||
"line": undefined,
|
||||
"name": "F",
|
||||
"selfWeight": 1,
|
||||
"totalWeight": 2,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "E",
|
||||
"line": undefined,
|
||||
"name": "E",
|
||||
"selfWeight": 1,
|
||||
"totalWeight": 1,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "G",
|
||||
"line": undefined,
|
||||
"name": "G",
|
||||
"selfWeight": 1,
|
||||
"totalWeight": 2,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "H",
|
||||
"line": undefined,
|
||||
"name": "H",
|
||||
"selfWeight": 1,
|
||||
"totalWeight": 1,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "J",
|
||||
"line": undefined,
|
||||
"name": "J",
|
||||
"selfWeight": 1,
|
||||
"totalWeight": 2,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "I",
|
||||
"line": undefined,
|
||||
"name": "I",
|
||||
"selfWeight": 1,
|
||||
"totalWeight": 1,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "K",
|
||||
"line": undefined,
|
||||
"name": "K",
|
||||
"selfWeight": 1,
|
||||
"totalWeight": 2,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "L",
|
||||
"line": undefined,
|
||||
"name": "L",
|
||||
"selfWeight": 1,
|
||||
"totalWeight": 1,
|
||||
},
|
||||
],
|
||||
"name": "pid 0, tid 0",
|
||||
"stacks": Array [
|
||||
"A;B 2.00µs",
|
||||
" 8.00µs",
|
||||
"D;C 2.00µs",
|
||||
" 8.00µs",
|
||||
"F;E 1.00µs",
|
||||
"F 1.00µs",
|
||||
" 8.00µs",
|
||||
"G;H 1.00µs",
|
||||
"G 1.00µs",
|
||||
" 8.00µs",
|
||||
"J 1.00µs",
|
||||
"J;I 1.00µs",
|
||||
" 8.00µs",
|
||||
"K 1.00µs",
|
||||
"K;L 1.00µs",
|
||||
],
|
||||
}
|
||||
`;
|
||||
|
||||
exports[`importTraceEvents BEX interaction: indexToView 1`] = `0`;
|
||||
|
||||
exports[`importTraceEvents BEX interaction: profileGroup.name 1`] = `"bex-interaction.json"`;
|
||||
|
||||
exports[`importTraceEvents bad E events 1`] = `
|
||||
Object {
|
||||
"frames": Array [
|
||||
@@ -161,6 +298,130 @@ exports[`importTraceEvents event re-ordering: indexToView 1`] = `0`;
|
||||
|
||||
exports[`importTraceEvents event re-ordering: profileGroup.name 1`] = `"must-retain-original-order.json"`;
|
||||
|
||||
exports[`importTraceEvents event reordering name match 1`] = `
|
||||
Object {
|
||||
"frames": Array [
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "alpha {\\"x\\":0}",
|
||||
"line": undefined,
|
||||
"name": "alpha {\\"x\\":0}",
|
||||
"selfWeight": 9,
|
||||
"totalWeight": 10,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "beta {\\"x\\":0}",
|
||||
"line": undefined,
|
||||
"name": "beta {\\"x\\":0}",
|
||||
"selfWeight": 0,
|
||||
"totalWeight": 1,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "gamma {\\"x\\":0}",
|
||||
"line": undefined,
|
||||
"name": "gamma {\\"x\\":0}",
|
||||
"selfWeight": 1,
|
||||
"totalWeight": 1,
|
||||
},
|
||||
],
|
||||
"name": "pid 0, tid 1",
|
||||
"stacks": Array [
|
||||
"alpha {\\"x\\":0} 1.00µs",
|
||||
"alpha {\\"x\\":0};beta {\\"x\\":0};gamma {\\"x\\":0} 1.00µs",
|
||||
"alpha {\\"x\\":0} 8.00µs",
|
||||
],
|
||||
}
|
||||
`;
|
||||
|
||||
exports[`importTraceEvents event reordering name match: indexToView 1`] = `0`;
|
||||
|
||||
exports[`importTraceEvents event reordering name match: profileGroup.name 1`] = `"event-reordering-name-match.json"`;
|
||||
|
||||
exports[`importTraceEvents invalid x nesting 1`] = `
|
||||
Object {
|
||||
"frames": Array [
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "alpha",
|
||||
"line": undefined,
|
||||
"name": "alpha",
|
||||
"selfWeight": 5,
|
||||
"totalWeight": 15,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "beta",
|
||||
"line": undefined,
|
||||
"name": "beta",
|
||||
"selfWeight": 10,
|
||||
"totalWeight": 10,
|
||||
},
|
||||
],
|
||||
"name": "pid 0, tid 0",
|
||||
"stacks": Array [
|
||||
"alpha 5.00µs",
|
||||
"alpha;beta 10.00µs",
|
||||
],
|
||||
}
|
||||
`;
|
||||
|
||||
exports[`importTraceEvents invalid x nesting: indexToView 1`] = `0`;
|
||||
|
||||
exports[`importTraceEvents invalid x nesting: profileGroup.name 1`] = `"invalid-x-nesting.json"`;
|
||||
|
||||
exports[`importTraceEvents matching x 1`] = `
|
||||
Object {
|
||||
"frames": Array [
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "alpha",
|
||||
"line": undefined,
|
||||
"name": "alpha",
|
||||
"selfWeight": 8,
|
||||
"totalWeight": 10,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "beta",
|
||||
"line": undefined,
|
||||
"name": "beta",
|
||||
"selfWeight": 1,
|
||||
"totalWeight": 2,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "gamma",
|
||||
"line": undefined,
|
||||
"name": "gamma",
|
||||
"selfWeight": 1,
|
||||
"totalWeight": 2,
|
||||
},
|
||||
],
|
||||
"name": "pid 0, tid 0",
|
||||
"stacks": Array [
|
||||
"alpha 1.00µs",
|
||||
"alpha;beta;gamma 1.00µs",
|
||||
"alpha 3.00µs",
|
||||
"alpha;gamma;beta 1.00µs",
|
||||
"alpha 4.00µs",
|
||||
],
|
||||
}
|
||||
`;
|
||||
|
||||
exports[`importTraceEvents matching x: indexToView 1`] = `0`;
|
||||
|
||||
exports[`importTraceEvents matching x: profileGroup.name 1`] = `"matching-x.json"`;
|
||||
|
||||
exports[`importTraceEvents mismatched args 1`] = `
|
||||
Object {
|
||||
"frames": Array [
|
||||
@@ -868,6 +1129,114 @@ exports[`importTraceEvents unbalanced name: indexToView 1`] = `0`;
|
||||
|
||||
exports[`importTraceEvents unbalanced name: profileGroup.name 1`] = `"unbalanced-name.json"`;
|
||||
|
||||
exports[`importTraceEvents x events matching end 1`] = `
|
||||
Object {
|
||||
"frames": Array [
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "alpha",
|
||||
"line": undefined,
|
||||
"name": "alpha",
|
||||
"selfWeight": 12,
|
||||
"totalWeight": 20,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "beta",
|
||||
"line": undefined,
|
||||
"name": "beta",
|
||||
"selfWeight": 4,
|
||||
"totalWeight": 6,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "gamma",
|
||||
"line": undefined,
|
||||
"name": "gamma",
|
||||
"selfWeight": 4,
|
||||
"totalWeight": 6,
|
||||
},
|
||||
],
|
||||
"name": "pid 0, tid 0",
|
||||
"stacks": Array [
|
||||
"alpha 1.00µs",
|
||||
"alpha;beta 1.00µs",
|
||||
"alpha;beta;gamma 1.00µs",
|
||||
"alpha 2.00µs",
|
||||
"alpha;gamma 1.00µs",
|
||||
"alpha;gamma;beta 1.00µs",
|
||||
"alpha 2.00µs",
|
||||
"alpha;beta 1.00µs",
|
||||
"alpha;beta;gamma 1.00µs",
|
||||
"alpha 3.00µs",
|
||||
"alpha;gamma 1.00µs",
|
||||
"alpha;gamma;beta 1.00µs",
|
||||
"alpha 4.00µs",
|
||||
],
|
||||
}
|
||||
`;
|
||||
|
||||
exports[`importTraceEvents x events matching end: indexToView 1`] = `0`;
|
||||
|
||||
exports[`importTraceEvents x events matching end: profileGroup.name 1`] = `"x-events-matching-end.json"`;
|
||||
|
||||
exports[`importTraceEvents x events matching start 1`] = `
|
||||
Object {
|
||||
"frames": Array [
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "alpha",
|
||||
"line": undefined,
|
||||
"name": "alpha",
|
||||
"selfWeight": 12,
|
||||
"totalWeight": 20,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "beta",
|
||||
"line": undefined,
|
||||
"name": "beta",
|
||||
"selfWeight": 4,
|
||||
"totalWeight": 6,
|
||||
},
|
||||
Frame {
|
||||
"col": undefined,
|
||||
"file": undefined,
|
||||
"key": "gamma",
|
||||
"line": undefined,
|
||||
"name": "gamma",
|
||||
"selfWeight": 4,
|
||||
"totalWeight": 6,
|
||||
},
|
||||
],
|
||||
"name": "pid 0, tid 0",
|
||||
"stacks": Array [
|
||||
"alpha 1.00µs",
|
||||
"alpha;beta;gamma 1.00µs",
|
||||
"alpha;beta 1.00µs",
|
||||
"alpha 2.00µs",
|
||||
"alpha;gamma;beta 1.00µs",
|
||||
"alpha;gamma 1.00µs",
|
||||
"alpha 2.00µs",
|
||||
"alpha;gamma;beta 1.00µs",
|
||||
"alpha;gamma 1.00µs",
|
||||
"alpha 2.00µs",
|
||||
"alpha;beta;gamma 1.00µs",
|
||||
"alpha;beta 1.00µs",
|
||||
"alpha 5.00µs",
|
||||
],
|
||||
}
|
||||
`;
|
||||
|
||||
exports[`importTraceEvents x events matching start: indexToView 1`] = `0`;
|
||||
|
||||
exports[`importTraceEvents x events matching start: profileGroup.name 1`] = `"x-events-matching-start.json"`;
|
||||
|
||||
exports[`importTraceEvents zero duration events 1`] = `
|
||||
Object {
|
||||
"frames": Array [
|
||||
|
||||
@@ -75,3 +75,27 @@ test('importTraceEvents only begin events', async () => {
|
||||
test('importTraceEvents zero duration events', async () => {
|
||||
await checkProfileSnapshot('./sample/profiles/trace-event/zero-duration-events.json')
|
||||
})
|
||||
|
||||
test('importTraceEvents matching x', async () => {
|
||||
await checkProfileSnapshot('./sample/profiles/trace-event/matching-x.json')
|
||||
})
|
||||
|
||||
test('importTraceEvents x events matching start', async () => {
|
||||
await checkProfileSnapshot('./sample/profiles/trace-event/x-events-matching-start.json')
|
||||
})
|
||||
|
||||
test('importTraceEvents x events matching end', async () => {
|
||||
await checkProfileSnapshot('./sample/profiles/trace-event/x-events-matching-end.json')
|
||||
})
|
||||
|
||||
test('importTraceEvents BEX interaction', async () => {
|
||||
await checkProfileSnapshot('./sample/profiles/trace-event/bex-interaction.json')
|
||||
})
|
||||
|
||||
test('importTraceEvents invalid x nesting', async () => {
|
||||
await checkProfileSnapshot('./sample/profiles/trace-event/invalid-x-nesting.json')
|
||||
})
|
||||
|
||||
test('importTraceEvents event reordering name match', async () => {
|
||||
await checkProfileSnapshot('./sample/profiles/trace-event/event-reordering-name-match.json')
|
||||
})
|
||||
|
||||
@@ -1,5 +1,5 @@
|
||||
import {sortBy, zeroPad, lastOf} from '../lib/utils'
|
||||
import {ProfileGroup, CallTreeProfileBuilder, FrameInfo} from '../lib/profile'
|
||||
import {sortBy, zeroPad, getOrInsert, lastOf} from '../lib/utils'
|
||||
import {ProfileGroup, CallTreeProfileBuilder, FrameInfo, Profile} from '../lib/profile'
|
||||
import {TimeFormatter} from '../lib/value-formatters'
|
||||
|
||||
// This file concerns import from the "Trace Event Format", authored by Google
|
||||
@@ -64,7 +64,135 @@ interface XTraceEvent extends TraceEvent {
|
||||
|
||||
// The trace format supports a number of event types that we ignore.
|
||||
type ImportableTraceEvent = BTraceEvent | ETraceEvent | XTraceEvent
|
||||
type DurationEvent = BTraceEvent | ETraceEvent
|
||||
|
||||
function pidTidKey(pid: number, tid: number): string {
|
||||
// We zero-pad the PID and TID to make sorting them by pid/tid pair later easier.
|
||||
return `${zeroPad('' + pid, 10)}:${zeroPad('' + tid, 10)}`
|
||||
}
|
||||
|
||||
function partitionByPidTid(events: ImportableTraceEvent[]): Map<string, ImportableTraceEvent[]> {
|
||||
const map = new Map<string, ImportableTraceEvent[]>()
|
||||
|
||||
for (let ev of events) {
|
||||
const list = getOrInsert(map, pidTidKey(ev.pid, ev.tid), () => [])
|
||||
list.push(ev)
|
||||
}
|
||||
|
||||
return map
|
||||
}
|
||||
|
||||
function selectQueueToTakeFromNext(
|
||||
bEventQueue: BTraceEvent[],
|
||||
eEventQueue: ETraceEvent[],
|
||||
): 'B' | 'E' {
|
||||
if (bEventQueue.length === 0 && eEventQueue.length === 0) {
|
||||
throw new Error('This method should not be given both queues empty')
|
||||
}
|
||||
if (eEventQueue.length === 0) return 'B'
|
||||
if (bEventQueue.length === 0) return 'E'
|
||||
|
||||
const bFront = bEventQueue[0]
|
||||
const eFront = eEventQueue[0]
|
||||
|
||||
const bts = bFront.ts
|
||||
const ets = eFront.ts
|
||||
|
||||
if (bts < ets) return 'B'
|
||||
if (ets < bts) return 'E'
|
||||
|
||||
// If we got here, the 'B' event queue and the 'E' event queue have events at
|
||||
// the front with equal timestamps.
|
||||
|
||||
// If the front of the 'E' queue matches the front of the 'B' queue by name,
|
||||
// then it means we have a zero duration event. Process the 'B' queue first
|
||||
// to ensure it opens before we try to close it.
|
||||
//
|
||||
// Otherwise, process the 'E' queue first.
|
||||
return bFront.name === eFront.name ? 'B' : 'E'
|
||||
}
|
||||
|
||||
function convertToEventQueues(events: ImportableTraceEvent[]): [BTraceEvent[], ETraceEvent[]] {
|
||||
const beginEvents: BTraceEvent[] = []
|
||||
const endEvents: ETraceEvent[] = []
|
||||
|
||||
// Rebase all of the timestamps on the lowest timestamp
|
||||
if (events.length > 0) {
|
||||
let firstTs = Number.MAX_SAFE_INTEGER
|
||||
for (let ev of events) {
|
||||
firstTs = Math.min(firstTs, ev.ts)
|
||||
}
|
||||
for (let ev of events) {
|
||||
ev.ts -= firstTs
|
||||
}
|
||||
}
|
||||
|
||||
// Next, combine B, E, and X events into two timestamp ordered queues.
|
||||
const xEvents: XTraceEvent[] = []
|
||||
for (let ev of events) {
|
||||
switch (ev.ph) {
|
||||
case 'B': {
|
||||
beginEvents.push(ev)
|
||||
break
|
||||
}
|
||||
|
||||
case 'E': {
|
||||
endEvents.push(ev)
|
||||
break
|
||||
}
|
||||
|
||||
case 'X': {
|
||||
xEvents.push(ev)
|
||||
break
|
||||
}
|
||||
|
||||
default: {
|
||||
const _exhaustiveCheck: never = ev
|
||||
return _exhaustiveCheck
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
function dur(x: XTraceEvent): number {
|
||||
return x.dur ?? x.tdur ?? 0
|
||||
}
|
||||
|
||||
xEvents.sort((a, b) => {
|
||||
if (a.ts < b.ts) return -1
|
||||
if (a.ts > b.ts) return 1
|
||||
|
||||
// Super weird special case: if we have two 'X' events with the same 'ts'
|
||||
// but different 'dur' the only valid interpretation is to put the one with
|
||||
// the longer 'dur' first, because you can't nest longer things in shorter
|
||||
// things.
|
||||
const aDur = dur(a)
|
||||
const bDur = dur(b)
|
||||
if (aDur > bDur) return -1
|
||||
if (aDur < bDur) return 1
|
||||
|
||||
// Otherwise, retain the original order by relying upon a stable sort here.
|
||||
return 0
|
||||
})
|
||||
|
||||
for (let x of xEvents) {
|
||||
const xDur = dur(x)
|
||||
beginEvents.push({...x, ph: 'B'} as BTraceEvent)
|
||||
endEvents.push({...x, ph: 'E', ts: x.ts + xDur} as ETraceEvent)
|
||||
}
|
||||
|
||||
function compareTimestamps(a: TraceEvent, b: TraceEvent) {
|
||||
if (a.ts < b.ts) return -1
|
||||
if (a.ts > b.ts) return 1
|
||||
|
||||
// Important: if the timestamps are the same, return zero. We're going to
|
||||
// rely upon a stable sort here.
|
||||
return 0
|
||||
}
|
||||
|
||||
beginEvents.sort(compareTimestamps)
|
||||
endEvents.sort(compareTimestamps)
|
||||
|
||||
return [beginEvents, endEvents]
|
||||
}
|
||||
|
||||
function filterIgnoredEventTypes(events: TraceEvent[]): ImportableTraceEvent[] {
|
||||
const ret: ImportableTraceEvent[] = []
|
||||
@@ -79,40 +207,6 @@ function filterIgnoredEventTypes(events: TraceEvent[]): ImportableTraceEvent[] {
|
||||
return ret
|
||||
}
|
||||
|
||||
function convertToDurationEvents(events: ImportableTraceEvent[]): DurationEvent[] {
|
||||
const ret: DurationEvent[] = []
|
||||
for (let ev of events) {
|
||||
switch (ev.ph) {
|
||||
case 'B':
|
||||
ret.push(ev)
|
||||
break
|
||||
|
||||
case 'E':
|
||||
ret.push(ev)
|
||||
break
|
||||
|
||||
case 'X':
|
||||
let dur: number | null = null
|
||||
if (ev.dur != null) dur = ev.dur
|
||||
else if (ev.tdur != null) dur = ev.tdur
|
||||
|
||||
if (dur == null) {
|
||||
console.warn('Found a complete event (X) with no duration. Skipping: ', ev)
|
||||
continue
|
||||
}
|
||||
|
||||
ret.push({...ev, ph: 'B'} as BTraceEvent)
|
||||
ret.push({...ev, ph: 'E', ts: ev.ts + dur} as ETraceEvent)
|
||||
break
|
||||
|
||||
default:
|
||||
const _exhaustiveCheck: never = ev
|
||||
return _exhaustiveCheck
|
||||
}
|
||||
}
|
||||
return ret
|
||||
}
|
||||
|
||||
function getProcessNamesByPid(events: TraceEvent[]): Map<number, string> {
|
||||
const processNamesByPid = new Map<number, string>()
|
||||
for (let ev of events) {
|
||||
@@ -128,8 +222,7 @@ function getThreadNamesByPidTid(events: TraceEvent[]): Map<string, string> {
|
||||
|
||||
for (let ev of events) {
|
||||
if (ev.ph === 'M' && ev.name === 'thread_name' && ev.args && ev.args.name) {
|
||||
const key = `${ev.pid}:${ev.tid}`
|
||||
threadNameByPidTid.set(key, ev.args.name)
|
||||
threadNameByPidTid.set(pidTidKey(ev.pid, ev.tid), ev.args.name)
|
||||
}
|
||||
}
|
||||
return threadNameByPidTid
|
||||
@@ -151,66 +244,25 @@ function frameInfoForEvent(event: TraceEvent): FrameInfo {
|
||||
}
|
||||
}
|
||||
|
||||
type TraceEventProfileState = {profile: CallTreeProfileBuilder; eventStack: BTraceEvent[]}
|
||||
|
||||
function eventListToProfileGroup(events: TraceEvent[]): ProfileGroup {
|
||||
const stateByPidTid = new Map<string, TraceEventProfileState>()
|
||||
|
||||
const importableEvents = filterIgnoredEventTypes(events)
|
||||
const durationEvents = convertToDurationEvents(importableEvents)
|
||||
const partitioned = partitionByPidTid(importableEvents)
|
||||
|
||||
const processNamesByPid = getProcessNamesByPid(events)
|
||||
const threadNamesByPidTid = getThreadNamesByPidTid(events)
|
||||
|
||||
durationEvents.sort((a, b) => {
|
||||
if (a.ts < b.ts) return -1
|
||||
if (a.ts > b.ts) return 1
|
||||
if (a.pid < b.pid) return -1
|
||||
if (a.pid > b.pid) return 1
|
||||
if (a.tid < b.tid) return -1
|
||||
if (a.tid > b.tid) return 1
|
||||
const profilePairs: [string, Profile][] = []
|
||||
|
||||
// We have to be careful with events that have the same timestamp
|
||||
// and the same pid/tid
|
||||
const aKey = keyForEvent(a)
|
||||
const bKey = keyForEvent(b)
|
||||
if (aKey === bKey) {
|
||||
// If the two elements have the same key, we need to process the begin
|
||||
// event before the end event. This will be a zero-duration event.
|
||||
if (a.ph === 'B' && b.ph === 'E') return -1
|
||||
if (a.ph === 'E' && b.ph === 'B') return 1
|
||||
} else {
|
||||
// If the two elements have *different* keys, we want to process
|
||||
// the end of an event before the beginning of the event to prevent
|
||||
// out-of-order push/pops from the call-stack.
|
||||
if (a.ph === 'B' && b.ph === 'E') return 1
|
||||
if (a.ph === 'E' && b.ph === 'B') return -1
|
||||
}
|
||||
partitioned.forEach(eventsForThread => {
|
||||
if (eventsForThread.length === 0) return
|
||||
|
||||
// In all other cases, retain the original sort order.
|
||||
return 0
|
||||
})
|
||||
const {pid, tid} = eventsForThread[0]
|
||||
|
||||
if (durationEvents.length > 0) {
|
||||
const firstTs = durationEvents[0].ts
|
||||
for (let ev of durationEvents) {
|
||||
ev.ts -= firstTs
|
||||
}
|
||||
}
|
||||
|
||||
function getOrCreateProfileState(pid: number, tid: number): TraceEventProfileState {
|
||||
// We zero-pad the PID and TID to make sorting them by pid/tid pair later easier.
|
||||
const pidTid = `${zeroPad('' + pid, 10)}:${zeroPad('' + tid, 10)}`
|
||||
|
||||
let state = stateByPidTid.get(pidTid)
|
||||
if (state != null) return state
|
||||
let profile = new CallTreeProfileBuilder()
|
||||
state = {profile, eventStack: []}
|
||||
const profile = new CallTreeProfileBuilder()
|
||||
profile.setValueFormatter(new TimeFormatter('microseconds'))
|
||||
stateByPidTid.set(pidTid, state)
|
||||
|
||||
const processName = processNamesByPid.get(pid)
|
||||
const threadName = threadNamesByPidTid.get(`${pid}:${tid}`)
|
||||
const threadName = threadNamesByPidTid.get(pidTidKey(pid, tid))
|
||||
|
||||
if (processName != null && threadName != null) {
|
||||
profile.setName(`${processName} (pid ${pid}), ${threadName} (tid ${tid})`)
|
||||
@@ -222,90 +274,153 @@ function eventListToProfileGroup(events: TraceEvent[]): ProfileGroup {
|
||||
profile.setName(`pid ${pid}, tid ${tid}`)
|
||||
}
|
||||
|
||||
return state
|
||||
}
|
||||
// The trace event format is hard to deal with because it specifically
|
||||
// allows events to be recorded out of order, *but* event ordering is still
|
||||
// important for events with the same timestamp. Because of this, rather
|
||||
// than thinking about the entire event stream as a single queue of events,
|
||||
// we're going to first construct two time-ordered lists of events:
|
||||
//
|
||||
// 1. ts ordered queue of 'B' events
|
||||
// 2. ts ordered queue of 'E' events
|
||||
//
|
||||
// We deal with 'X' events by converting them to one entry in the 'B' event
|
||||
// queue and one entry in the 'E' event queue.
|
||||
//
|
||||
// The high level goal is to deal with 'B' events in 'ts' order, breaking
|
||||
// ties by the order the events occurred in the file, and deal with 'E'
|
||||
// events in 'ts' order, breaking ties in whatever order causes the 'E'
|
||||
// events to match whatever is on the top of the stack.
|
||||
const [bEventQueue, eEventQueue] = convertToEventQueues(eventsForThread)
|
||||
|
||||
for (let ev of durationEvents) {
|
||||
const {profile, eventStack} = getOrCreateProfileState(ev.pid, ev.tid)
|
||||
const frameInfo = frameInfoForEvent(ev)
|
||||
switch (ev.ph) {
|
||||
case 'B':
|
||||
eventStack.push(ev)
|
||||
profile.enterFrame(frameInfo, ev.ts)
|
||||
break
|
||||
|
||||
case 'E':
|
||||
const topFrame = lastOf(eventStack)
|
||||
if (topFrame == null) {
|
||||
console.warn(
|
||||
`ts=${ev.ts}: Request to end "${frameInfo?.key}" when stack is empty. Doing nothing instead.`,
|
||||
)
|
||||
break
|
||||
}
|
||||
|
||||
const topFrameInfo = frameInfoForEvent(topFrame)
|
||||
|
||||
// We treat mismatched names & mismatched keys differently, because it's
|
||||
// unclear from the spec what to do when you receive an "E" event when
|
||||
// the corresponding "B" event is not at the top of the stack, and also
|
||||
// unclear whether "B" and "E" events should be matched just based on
|
||||
// "name", or should also includes all of "args".
|
||||
//
|
||||
// Based on
|
||||
// https://github.com/catapult-project/catapult/blob/7874beb5c5a18ed8ba1264fac8dc4e857be23e35/tracing/tracing/extras/importer/trace_event_importer.html#L531-L542,
|
||||
// it seems like chrome://tracing warns on mismatching names, but
|
||||
// doesn't warn on mismatching args.
|
||||
//
|
||||
// As a rough compromise, if the names mismatch, we assume this is
|
||||
// definitely a mistake, and discard the event. If the names match, but
|
||||
// the args mismatch, we assume the args aren't supposed to match, and
|
||||
// warn, but close the top-of-stack frame anyway.
|
||||
if (ev.name !== topFrame.name) {
|
||||
console.warn(
|
||||
`ts=${ev.ts}: Request to end "${frameInfo.key}" when "${topFrameInfo.key}" was on the top of the stack. Doing nothing instead.`,
|
||||
)
|
||||
break
|
||||
}
|
||||
|
||||
if (frameInfo.key !== topFrameInfo.key) {
|
||||
console.warn(
|
||||
`ts=${ev.ts}: Request to end "${frameInfo.key}" when "${topFrameInfo.key}" was on the top of the stack. Ending "${topFrameInfo.key} instead.`,
|
||||
)
|
||||
}
|
||||
|
||||
profile.leaveFrame(topFrameInfo, ev.ts)
|
||||
eventStack.pop()
|
||||
break
|
||||
|
||||
default:
|
||||
const _exhaustiveCheck: never = ev
|
||||
return _exhaustiveCheck
|
||||
const frameStack: BTraceEvent[] = []
|
||||
const enterFrame = (b: BTraceEvent) => {
|
||||
frameStack.push(b)
|
||||
profile.enterFrame(frameInfoForEvent(b), b.ts)
|
||||
}
|
||||
}
|
||||
|
||||
const tryToLeaveFrame = (e: ETraceEvent) => {
|
||||
const b = lastOf(frameStack)
|
||||
|
||||
if (b == null) {
|
||||
console.warn(
|
||||
`Tried to end frame "${
|
||||
frameInfoForEvent(e).key
|
||||
}", but the stack was empty. Doing nothing instead.`,
|
||||
)
|
||||
return
|
||||
}
|
||||
|
||||
const eFrameInfo = frameInfoForEvent(e)
|
||||
const bFrameInfo = frameInfoForEvent(b)
|
||||
|
||||
if (e.name !== b.name) {
|
||||
console.warn(
|
||||
`ts=${e.ts}: Tried to end "${eFrameInfo.key}" when "${bFrameInfo.key}" was on the top of the stack. Doing nothing instead.`,
|
||||
)
|
||||
return
|
||||
}
|
||||
|
||||
if (eFrameInfo.key !== bFrameInfo.key) {
|
||||
console.warn(
|
||||
`ts=${e.ts}: Tried to end "${eFrameInfo.key}" when "${bFrameInfo.key}" was on the top of the stack. Ending ${bFrameInfo.key} instead.`,
|
||||
)
|
||||
}
|
||||
|
||||
frameStack.pop()
|
||||
profile.leaveFrame(bFrameInfo, e.ts)
|
||||
}
|
||||
|
||||
while (bEventQueue.length > 0 || eEventQueue.length > 0) {
|
||||
const queueName = selectQueueToTakeFromNext(bEventQueue, eEventQueue)
|
||||
switch (queueName) {
|
||||
case 'B': {
|
||||
enterFrame(bEventQueue.shift()!)
|
||||
break
|
||||
}
|
||||
case 'E': {
|
||||
// Before we take the first event in the 'E' queue, let's first see if
|
||||
// there are any e events that exactly match the top of the stack.
|
||||
// We'll prioritize first by key, then by name if we can't find a key
|
||||
// match.
|
||||
const stackTop = lastOf(frameStack)
|
||||
if (stackTop != null) {
|
||||
const bFrameInfo = frameInfoForEvent(stackTop)
|
||||
|
||||
let swapped: boolean = false
|
||||
|
||||
for (let i = 1; i < eEventQueue.length; i++) {
|
||||
const eEvent = eEventQueue[i]
|
||||
if (eEvent.ts > eEventQueue[0].ts) {
|
||||
// Only consider 'E' events with the same ts as the front of the queue.
|
||||
break
|
||||
}
|
||||
|
||||
const eFrameInfo = frameInfoForEvent(eEvent)
|
||||
if (bFrameInfo.key === eFrameInfo.key) {
|
||||
// We have a match! Process this one first.
|
||||
const temp = eEventQueue[0]
|
||||
eEventQueue[0] = eEventQueue[i]
|
||||
eEventQueue[i] = temp
|
||||
swapped = true
|
||||
break
|
||||
}
|
||||
}
|
||||
|
||||
if (!swapped) {
|
||||
// There was no key match, let's see if we can find a name match
|
||||
for (let i = 1; i < eEventQueue.length; i++) {
|
||||
const eEvent = eEventQueue[i]
|
||||
if (eEvent.ts > eEventQueue[0].ts) {
|
||||
// Only consider 'E' events with the same ts as the front of the queue.
|
||||
break
|
||||
}
|
||||
|
||||
if (eEvent.name === stackTop.name) {
|
||||
// We have a match! Process this one first.
|
||||
const temp = eEventQueue[0]
|
||||
eEventQueue[0] = eEventQueue[i]
|
||||
eEventQueue[i] = temp
|
||||
swapped = true
|
||||
break
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// If swapped is still false at this point, it means we're about to
|
||||
// pop a stack frame that doesn't even match by name. Bummer.
|
||||
}
|
||||
|
||||
const e = eEventQueue.shift()!
|
||||
|
||||
tryToLeaveFrame(e)
|
||||
break
|
||||
}
|
||||
|
||||
default:
|
||||
const _exhaustiveCheck: never = queueName
|
||||
return _exhaustiveCheck
|
||||
}
|
||||
}
|
||||
|
||||
for (let i = frameStack.length - 1; i >= 0; i--) {
|
||||
const frame = frameInfoForEvent(frameStack[i])
|
||||
console.warn(`Frame "${frame.key}" was still open at end of profile. Closing automatically.`)
|
||||
profile.leaveFrame(frame, profile.getTotalWeight())
|
||||
}
|
||||
|
||||
profilePairs.push([pidTidKey(pid, tid), profile.build()])
|
||||
})
|
||||
|
||||
// For now, we just sort processes by pid & tid.
|
||||
// TODO: The standard specifies that metadata events with the name
|
||||
// "process_sort_index" and "thread_sort_index" can be used to influence the
|
||||
// order, but for simplicity we'll ignore that until someone complains :)
|
||||
const profilePairs = Array.from(stateByPidTid.entries())
|
||||
sortBy(profilePairs, p => p[0])
|
||||
|
||||
return {
|
||||
name: '',
|
||||
indexToView: 0,
|
||||
profiles: profilePairs.map(p => {
|
||||
const {eventStack, profile} = p[1]
|
||||
if (eventStack.length > 0) {
|
||||
for (let i = eventStack.length - 1; i >= 0; i--) {
|
||||
const frame = frameInfoForEvent(eventStack[i])
|
||||
console.warn(
|
||||
`Frame "${frame.key}" was still open at end of profile. Closing automatically.`,
|
||||
)
|
||||
profile.leaveFrame(frame, profile.getTotalWeight())
|
||||
}
|
||||
}
|
||||
return profile.build()
|
||||
}),
|
||||
profiles: profilePairs.map(p => p[1]),
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
Reference in New Issue
Block a user