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)
This commit is contained in:
Jamie Wong 2020-10-24 21:58:31 -07:00 committed by GitHub
parent aee2dfdf89
commit de3ab89eb5
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
15 changed files with 566 additions and 15 deletions

View File

@ -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}
]

View File

@ -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}
]

View File

@ -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}
]

View File

@ -0,0 +1,4 @@
[
{"pid": 0, "tid": 0, "ph": "B", "name": "alpha", "ts": 0},
{"pid": 0, "tid": 0, "ph": "E", "name": "beta", "ts": 10}
]

View File

@ -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}
]

View File

@ -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}
]

View File

@ -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}
]

View File

@ -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}
]

View File

@ -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}
]

View File

@ -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}
]

View File

@ -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}
]

View File

@ -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"`;

View File

@ -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')
})

View File

@ -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[] {

View File

@ -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) {