Repository: jlfwong/speedscope (ts)

Issue:
Incorrect scoping for chrome tracing format file
When importing from a chrome tracing format file I see some problems with scoping.

![speedscope](https://user-images.githubusercontent.com/8567076/60436645-616f5800-9c04-11e9-8214-97205b801070.PNG)

The difference between good.json and bad.json is just the order of events in the file. good.json has the events in ascending timestamp order, bad.json has two events out of order. The trace event format specification says that "The events do not have to be in timestamp-sorted order." so this shouldn't matter. Both display fine in chrome://tracing.

[good.json.txt](https://github.com/jlfwong/speedscope/files/3345555/good.json.txt)
[bad.json.txt](https://github.com/jlfwong/speedscope/files/3345558/bad.json.txt)

The original data is from LLVM -ftime-trace with some additional processing afterwards.


Trace event profiles containing multiple 'X' events w/ identical ts & dur fail to import
I'm using speedscope to analyze clang's `-ftime-trace`. However speedscope is unable to analyze some of my .json files (possibly due to updating to Clang 11).

"😿 Something went wrong. Check the JS console for more details."

```
Failed to load format Error: Tried to leave frame "DebugType {"detail":"std::_Locinfo"}" while frame "DebugType {"detail":"const std::_Locinfo"}" was at the top at 3403256
    _leaveFrame https://www.speedscope.app/speedscope.a3aeba39.js:168
    leaveFrame https://www.speedscope.app/speedscope.a3aeba39.js:168
    o https://www.speedscope.app/import.1c646c77.js:111
    p https://www.speedscope.app/import.1c646c77.js:111
    S https://www.speedscope.app/import.1c646c77.js:113
    s https://www.speedscope.app/import.1c646c77.js:113
```

or similar errors. I uploaded two files, one of which breaks speedscope:

[speedscope-json.zip](https://github.com/jlfwong/speedscope/files/5416452/speedscope-json.zip)

- output.cpp.json works.
- sample_docs.cpp.json throws an error, but with a much longer stack trace.

This seems similar but not identical to https://github.com/jlfwong/speedscope/issues/299.

```
C:\Users\nyanpasu>clang --version
clang version 11.0.0
Target: x86_64-pc-windows-msvc
Thread model: posix
InstalledDir: C:\Program Files\LLVM\bin
```

Pull request:
Fix trace-event import for many cases where there are 'ts' collisions
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 

Patch:
diff --git a/sample/profiles/trace-event/bex-interaction.json b/sample/profiles/trace-event/bex-interaction.json
new file mode 100644
index 0000000..a75f4de
--- /dev/null
+++ b/sample/profiles/trace-event/bex-interaction.json
@@ -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" }
+]
\ No newline at end of file
diff --git a/sample/profiles/trace-event/event-reordering-name-match.json b/sample/profiles/trace-event/event-reordering-name-match.json
new file mode 100644
index 0000000..0dea1ff
--- /dev/null
+++ b/sample/profiles/trace-event/event-reordering-name-match.json
@@ -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}
+]
diff --git a/sample/profiles/trace-event/invalid-x-nesting.json b/sample/profiles/trace-event/invalid-x-nesting.json
new file mode 100644
index 0000000..eb518e6
--- /dev/null
+++ b/sample/profiles/trace-event/invalid-x-nesting.json
@@ -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" }
+]
\ No newline at end of file
diff --git a/sample/profiles/trace-event/matching-x.json b/sample/profiles/trace-event/matching-x.json
new file mode 100644
index 0000000..f7c346e
--- /dev/null
+++ b/sample/profiles/trace-event/matching-x.json
@@ -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" }
+]
\ No newline at end of file
diff --git a/sample/profiles/trace-event/x-events-matching-end.json b/sample/profiles/trace-event/x-events-matching-end.json
new file mode 100644
index 0000000..121e247
--- /dev/null
+++ b/sample/profiles/trace-event/x-events-matching-end.json
@@ -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" }
+]
\ No newline at end of file
diff --git a/sample/profiles/trace-event/x-events-matching-start.json b/sample/profiles/trace-event/x-events-matching-start.json
new file mode 100644
index 0000000..71287bd
--- /dev/null
+++ b/sample/profiles/trace-event/x-events-matching-start.json
@@ -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" }
+]
\ No newline at end of file
diff --git a/src/import/trace-event.ts b/src/import/trace-event.ts
index bc0b79e..0fa5ff5 100644
--- a/src/import/trace-event.ts
+++ b/src/import/trace-event.ts
@@ -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,50 +64,144 @@ 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 filterIgnoredEventTypes(events: TraceEvent[]): ImportableTraceEvent[] {
-  const ret: ImportableTraceEvent[] = []
+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) {
-    switch (ev.ph) {
-      case 'B':
-      case 'E':
-      case 'X':
-        ret.push(ev as ImportableTraceEvent)
-    }
+    const list = getOrInsert(map, pidTidKey(ev.pid, ev.tid), () => [])
+    list.push(ev)
   }
-  return ret
+
+  return map
 }
 
-function convertToDurationEvents(events: ImportableTraceEvent[]): DurationEvent[] {
-  const ret: DurationEvent[] = []
+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':
-        ret.push(ev)
+      case 'B': {
+        beginEvents.push(ev)
         break
+      }
 
-      case 'E':
-        ret.push(ev)
+      case 'E': {
+        endEvents.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)
+      case 'X': {
+        xEvents.push(ev)
         break
+      }
 
-      default:
+      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[] = []
+  for (let ev of events) {
+    switch (ev.ph) {
+      case 'B':
+      case 'E':
+      case 'X':
+        ret.push(ev as ImportableTraceEvent)
     }
   }
   return ret
@@ -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
-
-    // 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
-    }
+  const profilePairs: [string, Profile][] = []
 
-    // In all other cases, retain the original sort order.
-    return 0
-  })
-
-  if (durationEvents.length > 0) {
-    const firstTs = durationEvents[0].ts
-    for (let ev of durationEvents) {
-      ev.ts -= firstTs
-    }
-  }
+  partitioned.forEach(eventsForThread => {
+    if (eventsForThread.length === 0) return
 
-  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)}`
+    const {pid, tid} = eventsForThread[0]
 
-    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)
+
+    const frameStack: BTraceEvent[] = []
+    const enterFrame = (b: BTraceEvent) => {
+      frameStack.push(b)
+      profile.enterFrame(frameInfoForEvent(b), b.ts)
+    }
 
-  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
+    const tryToLeaveFrame = (e: ETraceEvent) => {
+      const b = lastOf(frameStack)
 
-      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
-        }
+      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
+      }
 
-        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.`,
-          )
+      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
         }
-
-        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.`,
-          )
+        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
         }
 
-        profile.leaveFrame(topFrameInfo, ev.ts)
-        eventStack.pop()
-        break
+        default:
+          const _exhaustiveCheck: never = queueName
+          return _exhaustiveCheck
+      }
+    }
 
-      default:
-        const _exhaustiveCheck: never = ev
-        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]),
   }
 }
 


Test patch:
diff --git a/src/import/__snapshots__/trace-event.test.ts.snap b/src/import/__snapshots__/trace-event.test.ts.snap
index 96c9484..1cef24e 100644
--- a/src/import/__snapshots__/trace-event.test.ts.snap
+++ b/src/import/__snapshots__/trace-event.test.ts.snap
@@ -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 [
diff --git a/src/import/trace-event.test.ts b/src/import/trace-event.test.ts
index 3d2806c..457886d 100644
--- a/src/import/trace-event.test.ts
+++ b/src/import/trace-event.test.ts
@@ -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')
+})