Skip to content

Commit dfd3a0d

Browse files
Fix bug in selectQueueToTakeFromNext for trace profiles (#450)
I have been taking a lot of profiles using the Hermes profiler, but I noticed that they sometimes to not show up properly. After debugging what exactly was going on, I realized it was because the logic in `selectQueueToTakeFromNext` only checks for name, instead of the key for the event. I had a bunch of events with the name `anonymous` that were getting improperly exited before they should have been due to this logic. This fix makes the code more robust if there are added "args" which differentiate an event from another (as is the case in Hermes profiles), however it would still be an issue if they key just defaults to the name. Example profile before: <img width="1728" alt="Screenshot 2023-12-15 at 12 54 04 AM" src="https://github.com/jlfwong/speedscope/assets/9957046/345f556e-f944-40f1-b59c-748133acb950"> What it should look like (in Perfetto): <img width="1051" alt="Screenshot 2023-12-15 at 8 51 38 AM" src="https://github.com/jlfwong/speedscope/assets/9957046/7473cdf8-95f1-49de-a0c7-ef4ac081ff85"> After the fix: <img width="1728" alt="Screenshot 2023-12-15 at 12 54 29 AM" src="https://github.com/jlfwong/speedscope/assets/9957046/56b0870a-538b-4916-acc8-de2b7dfd78eb">
1 parent ac4a015 commit dfd3a0d

File tree

4 files changed

+82
-2
lines changed

4 files changed

+82
-2
lines changed
Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,14 @@
1+
[
2+
{"pid": 0, "tid": 0, "ph": "B", "name": "anonymous", "ts": 0},
3+
{"pid": 0, "tid": 0, "ph": "B", "name": "anonymous", "ts": 1, "args": { "parent": 1 }},
4+
{"pid": 0, "tid": 0, "ph": "B", "name": "function1", "ts": 1, "args": { "parent": 2 }},
5+
{"pid": 0, "tid": 0, "ph": "B", "name": "anonymous", "ts": 1, "args": { "parent": 3 }},
6+
{"pid": 0, "tid": 0, "ph": "E", "name": "anonymous", "ts": 3, "args": { "parent": 3 }},
7+
{"pid": 0, "tid": 0, "ph": "E", "name": "function1", "ts": 3, "args": { "parent": 2 }},
8+
{"pid": 0, "tid": 0, "ph": "E", "name": "anonymous", "ts": 3, "args": { "parent": 1 }},
9+
{"pid": 0, "tid": 0, "ph": "B", "name": "anonymous", "ts": 3, "args": { "parent": 1 }},
10+
{"pid": 0, "tid": 0, "ph": "B", "name": "anonymous", "ts": 3, "args": { "parent": 8 }},
11+
{"pid": 0, "tid": 0, "ph": "E", "name": "anonymous", "ts": 5, "args": { "parent": 8 }},
12+
{"pid": 0, "tid": 0, "ph": "E", "name": "anonymous", "ts": 5, "args": { "parent": 1 }},
13+
{"pid": 0, "tid": 0, "ph": "E", "name": "anonymous", "ts": 5}
14+
]

src/import/__snapshots__/trace-event.test.ts.snap

Lines changed: 62 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -172,6 +172,68 @@ exports[`importTraceEvents bad E events: indexToView 1`] = `0`;
172172

173173
exports[`importTraceEvents bad E events: profileGroup.name 1`] = `"too-many-end-events.json"`;
174174

175+
exports[`importTraceEvents different number of start and end calls to same function at same timestamp 1`] = `
176+
Object {
177+
"frames": Array [
178+
Frame {
179+
"col": undefined,
180+
"file": undefined,
181+
"key": "anonymous",
182+
"line": undefined,
183+
"name": "anonymous",
184+
"selfWeight": 1,
185+
"totalWeight": 5,
186+
},
187+
Frame {
188+
"col": undefined,
189+
"file": undefined,
190+
"key": "anonymous {\\"parent\\":1}",
191+
"line": undefined,
192+
"name": "anonymous {\\"parent\\":1}",
193+
"selfWeight": 0,
194+
"totalWeight": 4,
195+
},
196+
Frame {
197+
"col": undefined,
198+
"file": undefined,
199+
"key": "function1 {\\"parent\\":2}",
200+
"line": undefined,
201+
"name": "function1 {\\"parent\\":2}",
202+
"selfWeight": 0,
203+
"totalWeight": 2,
204+
},
205+
Frame {
206+
"col": undefined,
207+
"file": undefined,
208+
"key": "anonymous {\\"parent\\":3}",
209+
"line": undefined,
210+
"name": "anonymous {\\"parent\\":3}",
211+
"selfWeight": 2,
212+
"totalWeight": 2,
213+
},
214+
Frame {
215+
"col": undefined,
216+
"file": undefined,
217+
"key": "anonymous {\\"parent\\":8}",
218+
"line": undefined,
219+
"name": "anonymous {\\"parent\\":8}",
220+
"selfWeight": 2,
221+
"totalWeight": 2,
222+
},
223+
],
224+
"name": "pid 0, tid 0",
225+
"stacks": Array [
226+
"anonymous 1.00µs",
227+
"anonymous;anonymous {\\"parent\\":1};function1 {\\"parent\\":2};anonymous {\\"parent\\":3} 2.00µs",
228+
"anonymous;anonymous {\\"parent\\":1};anonymous {\\"parent\\":8} 2.00µs",
229+
],
230+
}
231+
`;
232+
233+
exports[`importTraceEvents different number of start and end calls to same function at same timestamp: indexToView 1`] = `0`;
234+
235+
exports[`importTraceEvents different number of start and end calls to same function at same timestamp: profileGroup.name 1`] = `"simultaneous-anonymous-calls.json"`;
236+
175237
exports[`importTraceEvents end event with empty stack 1`] = `
176238
Object {
177239
"frames": Array [

src/import/trace-event.test.ts

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,10 @@ test('importTraceEvents bad E events', async () => {
4747
await checkProfileSnapshot('./sample/profiles/trace-event/too-many-end-events.json')
4848
})
4949

50+
test('importTraceEvents different number of start and end calls to same function at same timestamp', async () => {
51+
await checkProfileSnapshot('./sample/profiles/trace-event/simultaneous-anonymous-calls.json')
52+
})
53+
5054
test('importTraceEvents event re-ordering', async () => {
5155
await checkProfileSnapshot('./sample/profiles/trace-event/must-retain-original-order.json')
5256
})

src/import/trace-event.ts

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -103,12 +103,12 @@ function selectQueueToTakeFromNext(
103103
// If we got here, the 'B' event queue and the 'E' event queue have events at
104104
// the front with equal timestamps.
105105

106-
// If the front of the 'E' queue matches the front of the 'B' queue by name,
106+
// If the front of the 'E' queue matches the front of the 'B' queue by key,
107107
// then it means we have a zero duration event. Process the 'B' queue first
108108
// to ensure it opens before we try to close it.
109109
//
110110
// Otherwise, process the 'E' queue first.
111-
return bFront.name === eFront.name ? 'B' : 'E'
111+
return frameInfoForEvent(bFront).key === frameInfoForEvent(eFront).key ? 'B' : 'E'
112112
}
113113

114114
function convertToEventQueues(events: ImportableTraceEvent[]): [BTraceEvent[], ETraceEvent[]] {

0 commit comments

Comments
 (0)