From de3ab89eb5b00c5f9f7e2cac36d682c4bbb70f05 Mon Sep 17 00:00:00 2001 From: Jamie Wong Date: Sat, 24 Oct 2020 21:58:31 -0700 Subject: [PATCH] Fix import of trace event files where B/E events' args don't match (#321) In #273, I changed `CallTreeProfileBuilder.leaveFrame` to fail hard when you request to leave a frame different from the one at the top of the stack. It turns out we were intentionally doing this for trace event imports, because `args` are part of the frame key, and we want to allow profiles to be imported where the `"B"` and `"E"` events have differing `args` field. This PR fixes the import code to permissively allow the `"args"` field to not match between the `"B"` and `"E"` fields. **A note on intentional differences between speedscope and chrome://tracing** `chrome://tracing` will close whichever frame is at the top when it gets an `"E"` event, regardless of whether the name or the args match. speedscope will ignore the event entirely if the `"name"` field doesn't match, but will warn but still close the frame if the `"name"`s match but the `"args"` don't. ``` [ {"pid": 0, "tid": 0, "ph": "B", "name": "alpha", "ts": 0}, {"pid": 0, "tid": 0, "ph": "B", "name": "beta", "ts": 1}, {"pid": 0, "tid": 0, "ph": "E", "name": "gamma", "ts": 2}, {"pid": 0, "tid": 0, "ph": "E", "name": "beta", "ts": 9}, {"pid": 0, "tid": 0, "ph": "E", "name": "alpha", "ts": 10} ] ``` ### speedscope ![image](https://user-images.githubusercontent.com/150329/97098205-7365dd00-1637-11eb-9869-4e81ebebcee1.png) ``` warning: ts=2: Request to end "gamma" when "beta" was on the top of the stack. Doing nothing instead. ``` ### chrome://tracing ![image](https://user-images.githubusercontent.com/150329/97098215-87114380-1637-11eb-909c-b2e70c7291a4.png) --- .../end-event-with-empty-stack.json | 5 + .../trace-event/end-non-top-of-stack.json | 6 + .../profiles/trace-event/mismatched-args.json | 4 + .../profiles/trace-event/mismatched-name.json | 4 + .../trace-event/not-enough-end-events.json | 5 + .../trace-event/only-begin-events.json | 5 + .../out-of-order-unbalanced-name.json | 6 + sample/profiles/trace-event/out-of-order.json | 10 + .../profiles/trace-event/unbalanced-args.json | 6 + .../profiles/trace-event/unbalanced-name.json | 6 + .../trace-event/zero-duration-events.json | 9 + .../__snapshots__/trace-event.test.ts.snap | 392 ++++++++++++++++++ src/import/trace-event.test.ts | 44 ++ src/import/trace-event.ts | 78 +++- src/lib/profile.ts | 1 + 15 files changed, 566 insertions(+), 15 deletions(-) create mode 100644 sample/profiles/trace-event/end-event-with-empty-stack.json create mode 100644 sample/profiles/trace-event/end-non-top-of-stack.json create mode 100644 sample/profiles/trace-event/mismatched-args.json create mode 100644 sample/profiles/trace-event/mismatched-name.json create mode 100644 sample/profiles/trace-event/not-enough-end-events.json create mode 100644 sample/profiles/trace-event/only-begin-events.json create mode 100644 sample/profiles/trace-event/out-of-order-unbalanced-name.json create mode 100644 sample/profiles/trace-event/out-of-order.json create mode 100644 sample/profiles/trace-event/unbalanced-args.json create mode 100644 sample/profiles/trace-event/unbalanced-name.json create mode 100644 sample/profiles/trace-event/zero-duration-events.json diff --git a/sample/profiles/trace-event/end-event-with-empty-stack.json b/sample/profiles/trace-event/end-event-with-empty-stack.json new file mode 100644 index 0000000..f851ed2 --- /dev/null +++ b/sample/profiles/trace-event/end-event-with-empty-stack.json @@ -0,0 +1,5 @@ +[ + {"pid": 0, "tid": 0, "ph": "B", "name": "alpha", "ts": 0}, + {"pid": 0, "tid": 0, "ph": "E", "name": "alpha", "ts": 1}, + {"pid": 0, "tid": 0, "ph": "E", "name": "beta", "ts": 2} +] diff --git a/sample/profiles/trace-event/end-non-top-of-stack.json b/sample/profiles/trace-event/end-non-top-of-stack.json new file mode 100644 index 0000000..e633077 --- /dev/null +++ b/sample/profiles/trace-event/end-non-top-of-stack.json @@ -0,0 +1,6 @@ +[ + {"pid": 0, "tid": 0, "ph": "B", "name": "A", "args": {"x": 1}, "ts": 0}, + {"pid": 0, "tid": 0, "ph": "B", "name": "B", "args": {"x": 2}, "ts": 1}, + {"pid": 0, "tid": 0, "ph": "E", "name": "A", "args": {"x": 2}, "ts": 10}, + {"pid": 0, "tid": 0, "ph": "X", "name": "Z", "args": {"x": 1}, "ts": 10, "dur": 1} +] diff --git a/sample/profiles/trace-event/mismatched-args.json b/sample/profiles/trace-event/mismatched-args.json new file mode 100644 index 0000000..a753a2b --- /dev/null +++ b/sample/profiles/trace-event/mismatched-args.json @@ -0,0 +1,4 @@ +[ + {"pid": 0, "tid": 0, "ph": "B", "name": "A", "args": {"x": 1}, "ts": 0}, + {"pid": 0, "tid": 0, "ph": "E", "name": "A", "args": {"x": 2}, "ts": 10} +] \ No newline at end of file diff --git a/sample/profiles/trace-event/mismatched-name.json b/sample/profiles/trace-event/mismatched-name.json new file mode 100644 index 0000000..9c193ec --- /dev/null +++ b/sample/profiles/trace-event/mismatched-name.json @@ -0,0 +1,4 @@ +[ + {"pid": 0, "tid": 0, "ph": "B", "name": "alpha", "ts": 0}, + {"pid": 0, "tid": 0, "ph": "E", "name": "beta", "ts": 10} +] diff --git a/sample/profiles/trace-event/not-enough-end-events.json b/sample/profiles/trace-event/not-enough-end-events.json new file mode 100644 index 0000000..8ef42ac --- /dev/null +++ b/sample/profiles/trace-event/not-enough-end-events.json @@ -0,0 +1,5 @@ +[ + {"pid": 0, "tid": 0, "ph": "B", "name": "A", "args": {"x": 1}, "ts": 0}, + {"pid": 0, "tid": 0, "ph": "B", "name": "A", "args": {"x": 2}, "ts": 1}, + {"pid": 0, "tid": 0, "ph": "X", "name": "A", "args": {"x": 1}, "ts": 10, "dur": 1} +] diff --git a/sample/profiles/trace-event/only-begin-events.json b/sample/profiles/trace-event/only-begin-events.json new file mode 100644 index 0000000..bc2070c --- /dev/null +++ b/sample/profiles/trace-event/only-begin-events.json @@ -0,0 +1,5 @@ +[ + {"pid": 0, "tid": 0, "ph": "B", "name": "A", "args": {"x": 1}, "ts": 0}, + {"pid": 0, "tid": 0, "ph": "B", "name": "B", "args": {"x": 2}, "ts": 1}, + {"pid": 0, "tid": 0, "ph": "B", "name": "C", "args": {"x": 2}, "ts": 2} +] diff --git a/sample/profiles/trace-event/out-of-order-unbalanced-name.json b/sample/profiles/trace-event/out-of-order-unbalanced-name.json new file mode 100644 index 0000000..24f7bf3 --- /dev/null +++ b/sample/profiles/trace-event/out-of-order-unbalanced-name.json @@ -0,0 +1,6 @@ +[ + {"pid": 0, "tid": 0, "ph": "E", "name": "alpha", "ts": 9}, + {"pid": 0, "tid": 0, "ph": "E", "name": "beta", "ts": 10}, + {"pid": 0, "tid": 0, "ph": "B", "name": "alpha", "ts": 0}, + {"pid": 0, "tid": 0, "ph": "B", "name": "beta", "ts": 1} +] \ No newline at end of file diff --git a/sample/profiles/trace-event/out-of-order.json b/sample/profiles/trace-event/out-of-order.json new file mode 100644 index 0000000..bc74417 --- /dev/null +++ b/sample/profiles/trace-event/out-of-order.json @@ -0,0 +1,10 @@ +[ + {"pid": 0, "tid": 0, "ph": "B", "name": "B", "ts": 1}, + {"pid": 0, "tid": 0, "ph": "E", "name": "B", "ts": 9}, + + {"pid": 0, "tid": 0, "ph": "B", "name": "A", "ts": 0}, + {"pid": 0, "tid": 0, "ph": "E", "name": "A", "ts": 10}, + + {"pid": 0, "tid": 0, "ph": "B", "name": "C", "ts": 2}, + {"pid": 0, "tid": 0, "ph": "E", "name": "C", "ts": 8} +] diff --git a/sample/profiles/trace-event/unbalanced-args.json b/sample/profiles/trace-event/unbalanced-args.json new file mode 100644 index 0000000..6440ebe --- /dev/null +++ b/sample/profiles/trace-event/unbalanced-args.json @@ -0,0 +1,6 @@ +[ + {"pid": 0, "tid": 0, "ph": "B", "name": "A", "args": {"x": 1}, "ts": 0}, + {"pid": 0, "tid": 0, "ph": "B", "name": "A", "args": {"x": 2}, "ts": 1}, + {"pid": 0, "tid": 0, "ph": "E", "name": "A", "args": {"x": 1}, "ts": 9}, + {"pid": 0, "tid": 0, "ph": "E", "name": "A", "args": {"x": 2}, "ts": 10} +] diff --git a/sample/profiles/trace-event/unbalanced-name.json b/sample/profiles/trace-event/unbalanced-name.json new file mode 100644 index 0000000..cbe7b49 --- /dev/null +++ b/sample/profiles/trace-event/unbalanced-name.json @@ -0,0 +1,6 @@ +[ + {"pid": 0, "tid": 0, "ph": "B", "name": "alpha", "ts": 0}, + {"pid": 0, "tid": 0, "ph": "B", "name": "beta", "ts": 1}, + {"pid": 0, "tid": 0, "ph": "E", "name": "alpha", "ts": 9}, + {"pid": 0, "tid": 0, "ph": "E", "name": "beta", "ts": 10} +] diff --git a/sample/profiles/trace-event/zero-duration-events.json b/sample/profiles/trace-event/zero-duration-events.json new file mode 100644 index 0000000..8a9167d --- /dev/null +++ b/sample/profiles/trace-event/zero-duration-events.json @@ -0,0 +1,9 @@ +[ + {"pid": 0, "tid": 0, "ph": "B", "name": "A", "ts": 0}, + {"pid": 0, "tid": 0, "ph": "B", "name": "B", "ts": 1}, + {"pid": 0, "tid": 0, "ph": "E", "name": "B", "ts": 1}, + {"pid": 0, "tid": 0, "ph": "E", "name": "C", "ts": 2}, + {"pid": 0, "tid": 0, "ph": "B", "name": "C", "ts": 2}, + {"pid": 0, "tid": 0, "ph": "X", "name": "D", "ts": 3, "dur": 0}, + {"pid": 0, "tid": 0, "ph": "E", "name": "A", "ts": 10} +] diff --git a/src/import/__snapshots__/trace-event.test.ts.snap b/src/import/__snapshots__/trace-event.test.ts.snap index 0d31032..96c9484 100644 --- a/src/import/__snapshots__/trace-event.test.ts.snap +++ b/src/import/__snapshots__/trace-event.test.ts.snap @@ -35,6 +35,74 @@ exports[`importTraceEvents bad E events: indexToView 1`] = `0`; exports[`importTraceEvents bad E events: profileGroup.name 1`] = `"too-many-end-events.json"`; +exports[`importTraceEvents end event with empty stack 1`] = ` +Object { + "frames": Array [ + Frame { + "col": undefined, + "file": undefined, + "key": "alpha", + "line": undefined, + "name": "alpha", + "selfWeight": 1, + "totalWeight": 1, + }, + ], + "name": "pid 0, tid 0", + "stacks": Array [ + "alpha 1.00µs", + ], +} +`; + +exports[`importTraceEvents end event with empty stack: indexToView 1`] = `0`; + +exports[`importTraceEvents end event with empty stack: profileGroup.name 1`] = `"end-event-with-empty-stack.json"`; + +exports[`importTraceEvents end-non-top-of-stack 1`] = ` +Object { + "frames": Array [ + Frame { + "col": undefined, + "file": undefined, + "key": "A {\\"x\\":1}", + "line": undefined, + "name": "A {\\"x\\":1}", + "selfWeight": 1, + "totalWeight": 11, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "B {\\"x\\":2}", + "line": undefined, + "name": "B {\\"x\\":2}", + "selfWeight": 9, + "totalWeight": 10, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "Z {\\"x\\":1}", + "line": undefined, + "name": "Z {\\"x\\":1}", + "selfWeight": 1, + "totalWeight": 1, + }, + ], + "name": "pid 0, tid 0", + "stacks": Array [ + "A {\\"x\\":1} 1.00µs", + "A {\\"x\\":1};B {\\"x\\":2} 9.00µs", + "A {\\"x\\":1};B {\\"x\\":2};Z {\\"x\\":1} 1.00µs", + ], +} +`; + +exports[`importTraceEvents end-non-top-of-stack: indexToView 1`] = `0`; + +exports[`importTraceEvents end-non-top-of-stack: profileGroup.name 1`] = `"end-non-top-of-stack.json"`; + exports[`importTraceEvents event re-ordering 1`] = ` Object { "frames": Array [ @@ -93,6 +161,52 @@ exports[`importTraceEvents event re-ordering: indexToView 1`] = `0`; exports[`importTraceEvents event re-ordering: profileGroup.name 1`] = `"must-retain-original-order.json"`; +exports[`importTraceEvents mismatched args 1`] = ` +Object { + "frames": Array [ + Frame { + "col": undefined, + "file": undefined, + "key": "A {\\"x\\":1}", + "line": undefined, + "name": "A {\\"x\\":1}", + "selfWeight": 10, + "totalWeight": 10, + }, + ], + "name": "pid 0, tid 0", + "stacks": Array [ + "A {\\"x\\":1} 10.00µs", + ], +} +`; + +exports[`importTraceEvents mismatched args: indexToView 1`] = `0`; + +exports[`importTraceEvents mismatched args: profileGroup.name 1`] = `"mismatched-args.json"`; + +exports[`importTraceEvents mismatched name 1`] = ` +Object { + "frames": Array [ + Frame { + "col": undefined, + "file": undefined, + "key": "alpha", + "line": undefined, + "name": "alpha", + "selfWeight": 0, + "totalWeight": 0, + }, + ], + "name": "pid 0, tid 0", + "stacks": Array [], +} +`; + +exports[`importTraceEvents mismatched name: indexToView 1`] = `0`; + +exports[`importTraceEvents mismatched name: profileGroup.name 1`] = `"mismatched-name.json"`; + exports[`importTraceEvents multiprocess 1`] = ` Object { "frames": Array [ @@ -257,6 +371,164 @@ exports[`importTraceEvents multiprocess: indexToView 1`] = `0`; exports[`importTraceEvents multiprocess: profileGroup.name 1`] = `"multiprocess.json"`; +exports[`importTraceEvents not enough end events 1`] = ` +Object { + "frames": Array [ + Frame { + "col": undefined, + "file": undefined, + "key": "A {\\"x\\":1}", + "line": undefined, + "name": "A {\\"x\\":1}", + "selfWeight": 2, + "totalWeight": 11, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "A {\\"x\\":2}", + "line": undefined, + "name": "A {\\"x\\":2}", + "selfWeight": 9, + "totalWeight": 10, + }, + ], + "name": "pid 0, tid 0", + "stacks": Array [ + "A {\\"x\\":1} 1.00µs", + "A {\\"x\\":1};A {\\"x\\":2} 9.00µs", + "A {\\"x\\":1};A {\\"x\\":2};A {\\"x\\":1} 1.00µs", + ], +} +`; + +exports[`importTraceEvents not enough end events: indexToView 1`] = `0`; + +exports[`importTraceEvents not enough end events: profileGroup.name 1`] = `"not-enough-end-events.json"`; + +exports[`importTraceEvents not out-of-order 1`] = ` +Object { + "frames": Array [ + Frame { + "col": undefined, + "file": undefined, + "key": "A", + "line": undefined, + "name": "A", + "selfWeight": 2, + "totalWeight": 10, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "B", + "line": undefined, + "name": "B", + "selfWeight": 2, + "totalWeight": 8, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "C", + "line": undefined, + "name": "C", + "selfWeight": 6, + "totalWeight": 6, + }, + ], + "name": "pid 0, tid 0", + "stacks": Array [ + "A 1.00µs", + "A;B 1.00µs", + "A;B;C 6.00µs", + "A;B 1.00µs", + "A 1.00µs", + ], +} +`; + +exports[`importTraceEvents not out-of-order unbalanced name 1`] = ` +Object { + "frames": Array [ + Frame { + "col": undefined, + "file": undefined, + "key": "alpha", + "line": undefined, + "name": "alpha", + "selfWeight": 1, + "totalWeight": 10, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "beta", + "line": undefined, + "name": "beta", + "selfWeight": 9, + "totalWeight": 9, + }, + ], + "name": "pid 0, tid 0", + "stacks": Array [ + "alpha 1.00µs", + "alpha;beta 9.00µs", + ], +} +`; + +exports[`importTraceEvents not out-of-order unbalanced name: indexToView 1`] = `0`; + +exports[`importTraceEvents not out-of-order unbalanced name: profileGroup.name 1`] = `"out-of-order-unbalanced-name.json"`; + +exports[`importTraceEvents not out-of-order: indexToView 1`] = `0`; + +exports[`importTraceEvents not out-of-order: profileGroup.name 1`] = `"out-of-order.json"`; + +exports[`importTraceEvents only begin events 1`] = ` +Object { + "frames": Array [ + Frame { + "col": undefined, + "file": undefined, + "key": "A {\\"x\\":1}", + "line": undefined, + "name": "A {\\"x\\":1}", + "selfWeight": 1, + "totalWeight": 2, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "B {\\"x\\":2}", + "line": undefined, + "name": "B {\\"x\\":2}", + "selfWeight": 1, + "totalWeight": 1, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "C {\\"x\\":2}", + "line": undefined, + "name": "C {\\"x\\":2}", + "selfWeight": 0, + "totalWeight": 0, + }, + ], + "name": "pid 0, tid 0", + "stacks": Array [ + "A {\\"x\\":1} 1.00µs", + "A {\\"x\\":1};B {\\"x\\":2} 1.00µs", + ], +} +`; + +exports[`importTraceEvents only begin events: indexToView 1`] = `0`; + +exports[`importTraceEvents only begin events: profileGroup.name 1`] = `"only-begin-events.json"`; + exports[`importTraceEvents partial json import 1`] = ` Object { "frames": Array [ @@ -526,3 +798,123 @@ exports[`importTraceEvents simple object: profileGroup.name 1`] = `"simple-objec exports[`importTraceEvents simple: indexToView 1`] = `0`; exports[`importTraceEvents simple: profileGroup.name 1`] = `"simple.json"`; + +exports[`importTraceEvents unbalanced args 1`] = ` +Object { + "frames": Array [ + Frame { + "col": undefined, + "file": undefined, + "key": "A {\\"x\\":1}", + "line": undefined, + "name": "A {\\"x\\":1}", + "selfWeight": 2, + "totalWeight": 10, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "A {\\"x\\":2}", + "line": undefined, + "name": "A {\\"x\\":2}", + "selfWeight": 8, + "totalWeight": 8, + }, + ], + "name": "pid 0, tid 0", + "stacks": Array [ + "A {\\"x\\":1} 1.00µs", + "A {\\"x\\":1};A {\\"x\\":2} 8.00µs", + "A {\\"x\\":1} 1.00µs", + ], +} +`; + +exports[`importTraceEvents unbalanced args: indexToView 1`] = `0`; + +exports[`importTraceEvents unbalanced args: profileGroup.name 1`] = `"unbalanced-args.json"`; + +exports[`importTraceEvents unbalanced name 1`] = ` +Object { + "frames": Array [ + Frame { + "col": undefined, + "file": undefined, + "key": "alpha", + "line": undefined, + "name": "alpha", + "selfWeight": 1, + "totalWeight": 10, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "beta", + "line": undefined, + "name": "beta", + "selfWeight": 9, + "totalWeight": 9, + }, + ], + "name": "pid 0, tid 0", + "stacks": Array [ + "alpha 1.00µs", + "alpha;beta 9.00µs", + ], +} +`; + +exports[`importTraceEvents unbalanced name: indexToView 1`] = `0`; + +exports[`importTraceEvents unbalanced name: profileGroup.name 1`] = `"unbalanced-name.json"`; + +exports[`importTraceEvents zero duration events 1`] = ` +Object { + "frames": Array [ + Frame { + "col": undefined, + "file": undefined, + "key": "A", + "line": undefined, + "name": "A", + "selfWeight": 10, + "totalWeight": 10, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "B", + "line": undefined, + "name": "B", + "selfWeight": 0, + "totalWeight": 0, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "C", + "line": undefined, + "name": "C", + "selfWeight": 0, + "totalWeight": 0, + }, + Frame { + "col": undefined, + "file": undefined, + "key": "D", + "line": undefined, + "name": "D", + "selfWeight": 0, + "totalWeight": 0, + }, + ], + "name": "pid 0, tid 0", + "stacks": Array [ + "A 10.00µs", + ], +} +`; + +exports[`importTraceEvents zero duration events: indexToView 1`] = `0`; + +exports[`importTraceEvents zero duration events: profileGroup.name 1`] = `"zero-duration-events.json"`; diff --git a/src/import/trace-event.test.ts b/src/import/trace-event.test.ts index de9bd27..3d2806c 100644 --- a/src/import/trace-event.test.ts +++ b/src/import/trace-event.test.ts @@ -31,3 +31,47 @@ test('importTraceEvents bad E events', async () => { test('importTraceEvents event re-ordering', async () => { await checkProfileSnapshot('./sample/profiles/trace-event/must-retain-original-order.json') }) + +test('importTraceEvents end-non-top-of-stack', async () => { + await checkProfileSnapshot('./sample/profiles/trace-event/end-non-top-of-stack.json') +}) + +test('importTraceEvents mismatched args', async () => { + await checkProfileSnapshot('./sample/profiles/trace-event/mismatched-args.json') +}) + +test('importTraceEvents mismatched name', async () => { + await checkProfileSnapshot('./sample/profiles/trace-event/mismatched-name.json') +}) + +test('importTraceEvents not enough end events', async () => { + await checkProfileSnapshot('./sample/profiles/trace-event/not-enough-end-events.json') +}) + +test('importTraceEvents not out-of-order unbalanced name', async () => { + await checkProfileSnapshot('./sample/profiles/trace-event/out-of-order-unbalanced-name.json') +}) + +test('importTraceEvents not out-of-order', async () => { + await checkProfileSnapshot('./sample/profiles/trace-event/out-of-order.json') +}) + +test('importTraceEvents unbalanced name', async () => { + await checkProfileSnapshot('./sample/profiles/trace-event/unbalanced-name.json') +}) + +test('importTraceEvents unbalanced args', async () => { + await checkProfileSnapshot('./sample/profiles/trace-event/unbalanced-args.json') +}) + +test('importTraceEvents end event with empty stack', async () => { + await checkProfileSnapshot('./sample/profiles/trace-event/end-event-with-empty-stack.json') +}) + +test('importTraceEvents only begin events', async () => { + await checkProfileSnapshot('./sample/profiles/trace-event/only-begin-events.json') +}) + +test('importTraceEvents zero duration events', async () => { + await checkProfileSnapshot('./sample/profiles/trace-event/zero-duration-events.json') +}) diff --git a/src/import/trace-event.ts b/src/import/trace-event.ts index 6d59f53..bc0b79e 100644 --- a/src/import/trace-event.ts +++ b/src/import/trace-event.ts @@ -143,6 +143,14 @@ function keyForEvent(event: TraceEvent): string { return name } +function frameInfoForEvent(event: TraceEvent): FrameInfo { + const key = keyForEvent(event) + return { + name: key, + key: key, + } +} + type TraceEventProfileState = {profile: CallTreeProfileBuilder; eventStack: BTraceEvent[]} function eventListToProfileGroup(events: TraceEvent[]): ProfileGroup { @@ -219,11 +227,7 @@ function eventListToProfileGroup(events: TraceEvent[]): ProfileGroup { for (let ev of durationEvents) { const {profile, eventStack} = getOrCreateProfileState(ev.pid, ev.tid) - const key = keyForEvent(ev) - const frameInfo: FrameInfo = { - key: key, - name: key, - } + const frameInfo = frameInfoForEvent(ev) switch (ev.ph) { case 'B': eventStack.push(ev) @@ -231,18 +235,46 @@ function eventListToProfileGroup(events: TraceEvent[]): ProfileGroup { break case 'E': - const lastEvent = lastOf(eventStack) - if (lastEvent != null && lastEvent.name === ev.name) { - profile.leaveFrame(frameInfo, ev.ts) - eventStack.pop() - } else { + const topFrame = lastOf(eventStack) + if (topFrame == null) { console.warn( - 'Event discarded because it did not match top-of-stack. Discarded event:', - ev, - 'Top of stack:', - lastEvent, + `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: @@ -258,7 +290,23 @@ function eventListToProfileGroup(events: TraceEvent[]): ProfileGroup { const profilePairs = Array.from(stateByPidTid.entries()) sortBy(profilePairs, p => p[0]) - return {name: '', indexToView: 0, profiles: profilePairs.map(p => p[1].profile)} + 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() + }), + } } function isTraceEventList(maybeEventList: any): maybeEventList is TraceEvent[] { diff --git a/src/lib/profile.ts b/src/lib/profile.ts index 558fc1a..f900bc0 100644 --- a/src/lib/profile.ts +++ b/src/lib/profile.ts @@ -621,6 +621,7 @@ export class CallTreeProfileBuilder extends Profile { const frameCount = this.framesInStack.get(frame) || 0 this.framesInStack.set(frame, frameCount + 1) this.lastValue = value + this.totalWeight = Math.max(this.totalWeight, this.lastValue) } private _leaveFrame(frame: Frame, value: number, useAppendOrder: boolean) {