Repository: jlfwong/speedscope
Pull request #450 (2023-12-15 08:55:30)

Fix bug in selectQueueToTakeFromNext for trace profiles
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">


zacharyfmarion: @jlfwong can you take a look?
coveralls: 
[![Coverage Status](https://coveralls.io/builds/64589835/badge)](https://coveralls.io/builds/64589835)

coverage: 43.041%. remained the same
when pulling **12e03e46b18dd852c228c7d08d284fb4e61fd605 on zacharyfmarion:zac/fix-trace-bug**
into **ac4a0155596da13f3a76d752d63d06a31dc32ac0 on jlfwong:main**.

jlfwong: Hey @zacharyfmarion! Thanks for the investigation and the patch!

An example trace sent privately would be appreciated (you can send to jamie.lf.wong at gmail), but even better would be a dramatically reduced test file that minimally reproduces the issue. 

Patch:
diff --git a/sample/profiles/trace-event/simultaneous-anonymous-calls.json b/sample/profiles/trace-event/simultaneous-anonymous-calls.json
new file mode 100644
index 0000000..4f878de
--- /dev/null
+++ b/sample/profiles/trace-event/simultaneous-anonymous-calls.json
@@ -0,0 +1,14 @@
+[
+  {"pid": 0, "tid": 0, "ph": "B", "name": "anonymous", "ts": 0},
+  {"pid": 0, "tid": 0, "ph": "B", "name": "anonymous", "ts": 1, "args": { "parent": 1 }},
+  {"pid": 0, "tid": 0, "ph": "B", "name": "function1", "ts": 1, "args": { "parent": 2 }},
+  {"pid": 0, "tid": 0, "ph": "B", "name": "anonymous", "ts": 1, "args": { "parent": 3 }},
+  {"pid": 0, "tid": 0, "ph": "E", "name": "anonymous", "ts": 3, "args": { "parent": 3 }},
+  {"pid": 0, "tid": 0, "ph": "E", "name": "function1", "ts": 3, "args": { "parent": 2 }},
+  {"pid": 0, "tid": 0, "ph": "E", "name": "anonymous", "ts": 3, "args": { "parent": 1 }},
+  {"pid": 0, "tid": 0, "ph": "B", "name": "anonymous", "ts": 3, "args": { "parent": 1 }},
+  {"pid": 0, "tid": 0, "ph": "B", "name": "anonymous", "ts": 3, "args": { "parent": 8 }},
+  {"pid": 0, "tid": 0, "ph": "E", "name": "anonymous", "ts": 5, "args": { "parent": 8 }},
+  {"pid": 0, "tid": 0, "ph": "E", "name": "anonymous", "ts": 5, "args": { "parent": 1 }},
+  {"pid": 0, "tid": 0, "ph": "E", "name": "anonymous", "ts": 5}
+]
\ No newline at end of file
diff --git a/src/import/trace-event.ts b/src/import/trace-event.ts
index 0fa5ff5..6427070 100644
--- a/src/import/trace-event.ts
+++ b/src/import/trace-event.ts
@@ -103,12 +103,12 @@ function selectQueueToTakeFromNext(
   // 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,
+  // If the front of the 'E' queue matches the front of the 'B' queue by key,
   // 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'
+  return frameInfoForEvent(bFront).key === frameInfoForEvent(eFront).key ? 'B' : 'E'
 }
 
 function convertToEventQueues(events: ImportableTraceEvent[]): [BTraceEvent[], ETraceEvent[]] {


Test patch:
diff --git a/src/import/__snapshots__/trace-event.test.ts.snap b/src/import/__snapshots__/trace-event.test.ts.snap
index b5c3d4c..efc317a 100644
--- a/src/import/__snapshots__/trace-event.test.ts.snap
+++ b/src/import/__snapshots__/trace-event.test.ts.snap
@@ -172,6 +172,68 @@ exports[`importTraceEvents bad E events: indexToView 1`] = `0`;
 
 exports[`importTraceEvents bad E events: profileGroup.name 1`] = `"too-many-end-events.json"`;
 
+exports[`importTraceEvents different number of start and end calls to same function at same timestamp 1`] = `
+Object {
+  "frames": Array [
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "anonymous",
+      "line": undefined,
+      "name": "anonymous",
+      "selfWeight": 1,
+      "totalWeight": 5,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "anonymous {\\"parent\\":1}",
+      "line": undefined,
+      "name": "anonymous {\\"parent\\":1}",
+      "selfWeight": 0,
+      "totalWeight": 4,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "function1 {\\"parent\\":2}",
+      "line": undefined,
+      "name": "function1 {\\"parent\\":2}",
+      "selfWeight": 0,
+      "totalWeight": 2,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "anonymous {\\"parent\\":3}",
+      "line": undefined,
+      "name": "anonymous {\\"parent\\":3}",
+      "selfWeight": 2,
+      "totalWeight": 2,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "anonymous {\\"parent\\":8}",
+      "line": undefined,
+      "name": "anonymous {\\"parent\\":8}",
+      "selfWeight": 2,
+      "totalWeight": 2,
+    },
+  ],
+  "name": "pid 0, tid 0",
+  "stacks": Array [
+    "anonymous 1.00µs",
+    "anonymous;anonymous {\\"parent\\":1};function1 {\\"parent\\":2};anonymous {\\"parent\\":3} 2.00µs",
+    "anonymous;anonymous {\\"parent\\":1};anonymous {\\"parent\\":8} 2.00µs",
+  ],
+}
+`;
+
+exports[`importTraceEvents different number of start and end calls to same function at same timestamp: indexToView 1`] = `0`;
+
+exports[`importTraceEvents different number of start and end calls to same function at same timestamp: profileGroup.name 1`] = `"simultaneous-anonymous-calls.json"`;
+
 exports[`importTraceEvents end event with empty stack 1`] = `
 Object {
   "frames": Array [
diff --git a/src/import/trace-event.test.ts b/src/import/trace-event.test.ts
index 1fdd5f9..6a8e956 100644
--- a/src/import/trace-event.test.ts
+++ b/src/import/trace-event.test.ts
@@ -47,6 +47,10 @@ test('importTraceEvents bad E events', async () => {
   await checkProfileSnapshot('./sample/profiles/trace-event/too-many-end-events.json')
 })
 
+test('importTraceEvents different number of start and end calls to same function at same timestamp', async () => {
+  await checkProfileSnapshot('./sample/profiles/trace-event/simultaneous-anonymous-calls.json')
+})
+
 test('importTraceEvents event re-ordering', async () => {
   await checkProfileSnapshot('./sample/profiles/trace-event/must-retain-original-order.json')
 })