From e84e38bcd1ab93a1b1b86cd071481276623e75ef Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Mon, 13 Nov 2023 16:24:09 -0600
Subject: [PATCH 01/14] Avoid mutating events when optimizing

---
 lib/tracer/tracer.js      | 14 ++------------
 tests/_helpers/helpers.js | 18 ++++++++++++++++++
 tests/tracer/tracer.js    | 27 +++++++++++++++++++++++++++
 3 files changed, 47 insertions(+), 12 deletions(-)

diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js
index 81c8fc4b..9d6f2a59 100644
--- a/lib/tracer/tracer.js
+++ b/lib/tracer/tracer.js
@@ -206,7 +206,6 @@ Tracer.prototype.eventEnd = function (trace, event, data) {
   }
 
   event.endAt = Ntp._now();
-  event.duration = event.endAt - event.at;
 
   if (data) {
     let info = { type: trace.type, name: trace.name };
@@ -259,7 +258,6 @@ Tracer.prototype.buildTrace = function (traceInfo) {
   let metrics = {
     compute: 0,
     async: 0,
-    totalNonCompute: 0,
   };
 
   let firstEvent = traceInfo.events[0];
@@ -281,10 +279,6 @@ Tracer.prototype.buildTrace = function (traceInfo) {
   traceInfo.endAt = lastEvent.endAt || lastEvent.at;
 
   metrics.total = traceInfo.endAt - firstEvent.at;
-  metrics.compute = metrics.total - metrics.totalNonCompute;
-
-  // Remove temporary fields
-  delete metrics.totalNonCompute;
 
   traceInfo.metrics = metrics;
   traceInfo.events = processedEvents;
@@ -311,8 +305,7 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) {
     return objectEvent;
   }
 
-
-  let {at, endAt, stack, nested = [], name, forcedEnd, type, data, level = 0} = objectEvent;
+  let { at, endAt, stack, nested = [], name, forcedEnd, type, data, level = 0 } = objectEvent;
 
   const optimizedNestedEvents = this._hasUsefulNested(objectEvent) ? this.optimizeEvents(nested, metrics) : undefined;
 
@@ -331,9 +324,7 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) {
       extraInfo.forcedEnd = true;
     }
 
-    objectEvent.duration = endAt - at;
-
-    const {duration} = objectEvent;
+    let duration = endAt - at;
 
     // We need this info as events are not always in order or in series.
     extraInfo.at = at;
@@ -343,7 +334,6 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) {
     if (metrics && duration > 0 && level === 0) {
       metrics[type] = metrics[type] || 0;
       metrics[type] += duration;
-      metrics.totalNonCompute += duration;
     }
 
     // Start and end events do not have duration.
diff --git a/tests/_helpers/helpers.js b/tests/_helpers/helpers.js
index a5d5dcd8..5ec5e7e8 100644
--- a/tests/_helpers/helpers.js
+++ b/tests/_helpers/helpers.js
@@ -382,6 +382,24 @@ export const dumpEvents = (events) => {
   console.log(JSON.stringify(events));
 };
 
+export function deepFreeze (obj) {
+  if (Array.isArray(obj)) {
+    obj.forEach(val => {
+      if (!Object.isFrozen(val)) {
+        deepFreeze(val);
+      }
+    });
+  } else {
+    Object.values(obj).forEach(val => {
+      if (!Object.isFrozen(val)) {
+        deepFreeze(val);
+      }
+    });
+  }
+
+  Object.freeze(obj);
+}
+
 export const TestHelpers = {
   methodStore: MethodStore,
   getLatestEventsFromMethodStore: () => MethodStore[MethodStore.length - 1].events,
diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js
index ede35197..b79710c4 100644
--- a/tests/tracer/tracer.js
+++ b/tests/tracer/tracer.js
@@ -5,6 +5,7 @@ import {
   callAsync,
   cleanBuiltEvents,
   cleanTrace,
+  deepFreeze,
   getLastMethodEvents,
   registerMethod,
   subscribeAndWait
@@ -723,6 +724,32 @@ addAsyncTest('Tracer - Build Trace - the correct number of async events are capt
   test.equal(asyncEvents.length,1);
 });
 
+addAsyncTest('Tracer - Optimize Events - no mutation', async (test) => {
+  let partialEvents;
+
+  const methodId = registerMethod(async function () {
+    const Email = Package['email'].Email;
+
+    await TestData.insertAsync({ _id: 'a', n: 1 });
+    await sleep(20);
+
+    await Email.sendAsync({ from: 'arunoda@meteorhacks.com', to: 'hello@meteor.com' });
+
+    let info = getInfo();
+    let events = info.trace.events.slice();
+    deepFreeze(events);
+
+    // testing this doesn't throw
+    partialEvents = Kadira.tracer.optimizeEvents(events);
+
+    info.trace.events = [Kadira.tracer.event(info.trace, 'start')];
+  });
+
+  await callAsync(methodId);
+
+  test.equal(Array.isArray(partialEvents), true);
+});
+
 function startTrace () {
   const ddpMessage = {
     id: 'the-id',

From 69c52384c67e7eba1f9b5900516c2509b43b9b44 Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Mon, 13 Nov 2023 16:26:44 -0600
Subject: [PATCH 02/14] Fix compute with force ended events

---
 lib/tracer/tracer.js   | 16 ++++++++++++----
 tests/tracer/tracer.js | 37 ++++++++++++++++++++++++++++++++++++-
 2 files changed, 48 insertions(+), 5 deletions(-)

diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js
index 9d6f2a59..e5441d47 100644
--- a/lib/tracer/tracer.js
+++ b/lib/tracer/tracer.js
@@ -320,6 +320,9 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) {
 
   if (![EventType.Complete, EventType.Start].includes(type)) {
     if (!endAt) {
+      // TODO: this might make the metrics a little off since it could be a
+      // couple ms since the trace ended. This should use the same timestamp
+      // as when the trace ended
       endAt = Ntp._now();
       extraInfo.forcedEnd = true;
     }
@@ -363,7 +366,7 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) {
 };
 
 Tracer.prototype.optimizeEvents = function (events, metrics) {
-  if (!events) {
+  if (!events || events.length === 0) {
     return [];
   }
 
@@ -373,17 +376,22 @@ Tracer.prototype.optimizeEvents = function (events, metrics) {
 
   processedEvents.push(this.optimizeEvent(events[0], metrics));
 
+  let previousEnd = events[0].at + (processedEvents[0][1] || 0);
+
   for (let i = 1; i < events.length; i += 1) {
-    let prevEvent = events[i - 1];
     let event = events[i];
 
-    computeTime = event.at - (prevEvent.endAt || prevEvent.at);
+    computeTime = event.at - previousEnd;
 
     if (computeTime > 0) {
       processedEvents.push([EventType.Compute, computeTime]);
+      metrics.compute += computeTime;
     }
 
-    processedEvents.push(this.optimizeEvent(event, metrics));
+    let processedEvent = this.optimizeEvent(event, metrics);
+    processedEvents.push(processedEvent);
+
+    previousEnd = event.at + (processedEvent[1] || 0);
   }
 
   if (processedEvents.length > MAX_TRACE_EVENTS) {
diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js
index b79710c4..38d1cc7c 100644
--- a/tests/tracer/tracer.js
+++ b/tests/tracer/tracer.js
@@ -330,6 +330,42 @@ addAsyncTest(
   }
 );
 
+addAsyncTest(
+  'Tracer - Build Trace - compute time with force end events',
+  async function (test) {
+    let now = Ntp._now();
+
+    // TODO: work around needed since optimizeEvent sets missing endAt as
+    // the current time
+    let oldNow = Ntp._now;
+    Ntp._now = () => now + 4500;
+
+    let traceInfo = {
+      events: [
+        {...eventDefaults, type: 'start', at: now, endAt: now},
+        {...eventDefaults, type: 'wait', at: now, endAt: now + 1000},
+        {...eventDefaults, type: 'db', at: now + 2000, endAt: undefined},
+        {type: EventType.Complete, at: now + 4500}
+      ]
+    };
+
+    Kadira.tracer.buildTrace(traceInfo);
+
+    Ntp._now = oldNow;
+
+    const expected = {
+      total: 4500,
+      wait: 1000,
+      db: 2500,
+      compute: 1000,
+      async: 0,
+    };
+
+    test.stableEqual(traceInfo.metrics, expected);
+    test.stableEqual(traceInfo.errored, false);
+  }
+);
+
 addAsyncTest(
   'Tracer - Build Trace - errored',
   function (test) {
@@ -410,7 +446,6 @@ addAsyncTest(
     const expected = [
       ['start'],
       ['wait', traceInfo.events[1][1], {}, { at: 0, endAt: traceInfo.events[1][3].endAt, forcedEnd: true }],
-      ['compute', 2000],
       ['db', 500, {}, { at: 2000, endAt: 2500}],
       ['complete']
     ];

From 98110d1e36b1403b2fc3229cba983789064b4db8 Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Mon, 13 Nov 2023 19:41:08 -0600
Subject: [PATCH 03/14] Add offset to efficiently store parallel events

---
 lib/tracer/tracer.js   | 38 ++++++++++++++++++++++++------------
 tests/hijack/base.js   |  4 ++--
 tests/hijack/db.js     | 14 +++++++-------
 tests/hijack/http.js   |  4 ++--
 tests/hijack/user.js   |  4 ++--
 tests/tracer/tracer.js | 44 ++++++++++++++++++++++++++++++++----------
 6 files changed, 73 insertions(+), 35 deletions(-)

diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js
index e5441d47..71ec5c49 100644
--- a/lib/tracer/tracer.js
+++ b/lib/tracer/tracer.js
@@ -287,6 +287,15 @@ Tracer.prototype.buildTrace = function (traceInfo) {
   return traceInfo;
 };
 
+function incrementMetric (metrics, name, value) {
+  if (!metrics || value === 0) {
+    return;
+  }
+
+  metrics[name] = metrics[name] || 0;
+  metrics[name] += value;
+}
+
 /**
  * There are two formats for traces. While the method/publication is running, the trace is in the object format.
  * This is easier to work with, but takes more space to store. After the trace is complete (either finished or errored),
@@ -299,7 +308,7 @@ Tracer.prototype.buildTrace = function (traceInfo) {
  * @param {Object} metrics A metrics object to be updated along the optimization process.
  * @returns {Array} Array notation of the event optimized for transport.
  */
-Tracer.prototype.optimizeEvent = function (objectEvent, metrics) {
+Tracer.prototype.optimizeEvent = function (objectEvent, prevEnded, metrics) {
   if (Array.isArray(objectEvent)) {
     // If it is an array, it is already optimized
     return objectEvent;
@@ -307,7 +316,6 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) {
 
   let { at, endAt, stack, nested = [], name, forcedEnd, type, data, level = 0 } = objectEvent;
 
-  const optimizedNestedEvents = this._hasUsefulNested(objectEvent) ? this.optimizeEvents(nested, metrics) : undefined;
 
   // Unused data is removed at the end
   const optimizedEvent = [type, 0, EMPTY_OBJECT, null];
@@ -318,6 +326,7 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) {
     forcedEnd,
   };
 
+  // Start and end events do not have duration or nested events.
   if (![EventType.Complete, EventType.Start].includes(type)) {
     if (!endAt) {
       // TODO: this might make the metrics a little off since it could be a
@@ -328,19 +337,23 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) {
     }
 
     let duration = endAt - at;
-
-    // We need this info as events are not always in order or in series.
-    extraInfo.at = at;
-    extraInfo.endAt = endAt;
-    extraInfo.nested = optimizedNestedEvents;
+    optimizedEvent[1] = duration;
 
     if (metrics && duration > 0 && level === 0) {
       metrics[type] = metrics[type] || 0;
       metrics[type] += duration;
     }
 
-    // Start and end events do not have duration.
-    optimizedEvent[1] = duration;
+    let offset = prevEnded - at;
+    if (offset < 0) {
+      throw new Error('Monti APM: unexpected gap between events');
+    } else if (offset > 0) {
+      extraInfo.offset = offset;
+    }
+
+    if (this._hasUsefulNested(nested)) {
+      extraInfo.nested = this.optimizeEvent(nested, metrics);
+    }
   }
 
   if (data) {
@@ -374,7 +387,7 @@ Tracer.prototype.optimizeEvents = function (events, metrics) {
 
   let computeTime;
 
-  processedEvents.push(this.optimizeEvent(events[0], metrics));
+  processedEvents.push(this.optimizeEvent(events[0], events[0].at, metrics));
 
   let previousEnd = events[0].at + (processedEvents[0][1] || 0);
 
@@ -385,10 +398,11 @@ Tracer.prototype.optimizeEvents = function (events, metrics) {
 
     if (computeTime > 0) {
       processedEvents.push([EventType.Compute, computeTime]);
-      metrics.compute += computeTime;
+      incrementMetric(metrics, 'compute', computeTime);
+      previousEnd += computeTime;
     }
 
-    let processedEvent = this.optimizeEvent(event, metrics);
+    let processedEvent = this.optimizeEvent(event, previousEnd, metrics);
     processedEvents.push(processedEvent);
 
     previousEnd = event.at + (processedEvent[1] || 0);
diff --git a/tests/hijack/base.js b/tests/hijack/base.js
index 94732122..7b56d1d3 100644
--- a/tests/hijack/base.js
+++ b/tests/hijack/base.js
@@ -15,8 +15,8 @@ addAsyncTest(
 
     let expected = [
       ['start',{userId: null,params: '[10,"abc"]'}],
-      ['wait',{waitOn: []},{at: 1,endAt: 1}],
-      ['db',{coll: 'tinytest-data',func: 'insertAsync'},{at: 1,endAt: 1}],
+      ['wait',{waitOn: []}],
+      ['db',{coll: 'tinytest-data',func: 'insertAsync'}],
       ['complete']
     ];
 
diff --git a/tests/hijack/db.js b/tests/hijack/db.js
index 20704d59..1d394c00 100644
--- a/tests/hijack/db.js
+++ b/tests/hijack/db.js
@@ -23,7 +23,7 @@ addAsyncTest(
 
     dumpEvents(events);
 
-    let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []},{at: 1,endAt: 1}],['db',{coll: 'tinytest-data',func: 'insertAsync'},{at: 1,endAt: 1}],['complete']];
+    let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []}],['db',{coll: 'tinytest-data',func: 'insertAsync'}],['complete']];
 
     test.stableEqual(events, expected);
   }
@@ -44,7 +44,7 @@ addAsyncTest(
 
     let events = getLastMethodEvents([0, 2, 3]);
 
-    let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []},{at: 1,endAt: 1}],['db',{coll: 'tinytest-data',func: 'insertAsync'},{at: 1,endAt: 1}],['db',{coll: 'tinytest-data',func: 'insertAsync',err: 'E11000'},{at: 1,endAt: 1}],['complete']];
+    let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []}],['db',{coll: 'tinytest-data',func: 'insertAsync'}],['db',{coll: 'tinytest-data',func: 'insertAsync',err: 'E11000'}],['complete']];
 
     test.stableEqual(events, expected);
   }
@@ -64,7 +64,7 @@ addAsyncTest(
 
     let events = getLastMethodEvents([0, 2, 3]);
 
-    let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []},{at: 1,endAt: 1}],['db',{coll: 'tinytest-data',func: 'updateAsync',selector: '{"_id":"aa"}',updatedDocs: 1},{at: 1,endAt: 1}],['complete']];
+    let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []}],['db',{coll: 'tinytest-data',func: 'updateAsync',selector: '{"_id":"aa"}',updatedDocs: 1}],['complete']];
 
     test.stableEqual(events, expected);
   }
@@ -84,7 +84,7 @@ addAsyncTest(
 
     let events = getLastMethodEvents([0, 2, 3]);
 
-    let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []},{at: 1,endAt: 1}],['db',{coll: 'tinytest-data',func: 'removeAsync',selector: '{"_id":"aa"}',removedDocs: 1},{at: 1,endAt: 1}],['complete']];
+    let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []}],['db',{coll: 'tinytest-data',func: 'removeAsync',selector: '{"_id":"aa"}',removedDocs: 1}],['complete']];
 
     test.stableEqual(events, expected);
   }
@@ -103,7 +103,7 @@ addAsyncTest(
 
     let events = getLastMethodEvents([0, 2, 3]);
 
-    let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []},{at: 1,endAt: 1}],['db',{coll: 'tinytest-data',selector: '{"_id":"aa"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1},{at: 1,endAt: 1}],['complete']];
+    let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []}],['db',{coll: 'tinytest-data',selector: '{"_id":"aa"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1}],['complete']];
 
     test.equal(result, {_id: 'aa', dd: 10});
 
@@ -129,7 +129,7 @@ addAsyncTest(
 
     test.equal(result, {_id: 'aa', dd: 10});
 
-    const expected = [['start',0,{userId: null,params: '[]'}],['wait',0,{waitOn: []},{at: 1,endAt: 1}],['db',0,{coll: 'tinytest-data',selector: '{"_id":"aa"}',func: 'fetch',cursor: true,projection: '{"dd":1}',sort: '{"dd":-1}',limit: 1,docsFetched: 1,docSize: 1},{at: 1,endAt: 1}],['complete']];
+    const expected = [['start',0,{userId: null,params: '[]'}],['wait',0,{waitOn: []}],['db',0,{coll: 'tinytest-data',selector: '{"_id":"aa"}',func: 'fetch',cursor: true,projection: '{"dd":1}',sort: '{"dd":-1}',limit: 1,docsFetched: 1,docSize: 1}],['complete']];
 
     test.stableEqual(events, expected);
   }
@@ -148,7 +148,7 @@ addAsyncTest(
 
     let events = getLastMethodEvents([0, 2, 3]);
 
-    let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []},{at: 1,endAt: 1}],['db',{coll: 'tinytest-data',func: 'upsert',selector: '{"_id":"aa"}',updatedDocs: 1,insertedId: 'aa'},{at: 1,endAt: 1}],['db',{coll: 'tinytest-data',func: 'upsert',selector: '{"_id":"aa"}',updatedDocs: 1},{at: 1,endAt: 1}],['complete']];
+    let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []}],['db',{coll: 'tinytest-data',func: 'upsert',selector: '{"_id":"aa"}',updatedDocs: 1,insertedId: 'aa'}],['db',{coll: 'tinytest-data',func: 'upsert',selector: '{"_id":"aa"}',updatedDocs: 1}],['complete']];
 
     test.stableEqual(events, expected);
   }
diff --git a/tests/hijack/http.js b/tests/hijack/http.js
index be7d227f..2021307a 100644
--- a/tests/hijack/http.js
+++ b/tests/hijack/http.js
@@ -16,8 +16,8 @@ addAsyncTest('HTTP - meteor/http - call a server', async function (test) {
 
   const expected = [
     ['start',{userId: null,params: '[]'}],
-    ['wait',{waitOn: []},{at: 1,endAt: 1}],
-    ['http',{method: 'GET',url: 'http://localhost:3301',library: 'meteor/http',statusCode: 1,async: true},{at: 1,endAt: 1}],
+    ['wait',{waitOn: []}],
+    ['http',{method: 'GET',url: 'http://localhost:3301',library: 'meteor/http',statusCode: 1,async: true}],
     ['complete']
   ];
 
diff --git a/tests/hijack/user.js b/tests/hijack/user.js
index cd789f93..593bfe21 100644
--- a/tests/hijack/user.js
+++ b/tests/hijack/user.js
@@ -16,8 +16,8 @@ addAsyncTest(
 
     let expected = [
       ['start',{userId: null,params: '[]'}],
-      ['wait',{waitOn: []},{at: 1,endAt: 1}],
-      ['db',{coll: 'tinytest-data',func: 'insertAsync'},{at: 1,endAt: 1}],
+      ['wait',{waitOn: []}],
+      ['db',{coll: 'tinytest-data',func: 'insertAsync'}],
       ['complete']
     ];
 
diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js
index 38d1cc7c..38cd0b76 100644
--- a/tests/tracer/tracer.js
+++ b/tests/tracer/tracer.js
@@ -645,20 +645,20 @@ addAsyncTest('Tracer - Build Trace - custom with nested parallel events', async
 
   const expected = [
     ['start',{userId: null,params: '[]'}],
-    ['wait',{waitOn: []},{at: 1,endAt: 1}],
+    ['wait',{waitOn: []}],
     ['custom', {}, {name: 'test',
       at: 1,
       endAt: 1,
       nested: [
-        ['db',{coll: 'tinytest-data',func: 'insertAsync'},{at: 1,endAt: 1}],
-        ['db',{coll: 'tinytest-data',func: 'insertAsync'},{at: 1,endAt: 1}],
-        ['db',{coll: 'tinytest-data',func: 'insertAsync'},{at: 1,endAt: 1}],
-        ['email',{from: 'arunoda@meteorhacks.com',to: 'hello@meteor.com', func: 'emailAsync'},{at: 1,endAt: 1}],
-        ['db',{coll: 'tinytest-data',selector: '{"_id":"a"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1},{at: 1,endAt: 1}],
-        ['db',{coll: 'tinytest-data',selector: '{"_id":"b"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1},{at: 1,endAt: 1}],
-        ['db',{coll: 'tinytest-data',selector: '{"_id":"c"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1},{at: 1,endAt: 1}],
-        ['db',{coll: 'tinytest-data',selector: '{"_id":"a1"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 0,docSize: 0},{at: 1,endAt: 1}],
-        ['db',{coll: 'tinytest-data',selector: '{"_id":"a2"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 0,docSize: 0},{at: 1,endAt: 1}]
+        ['db',{coll: 'tinytest-data',func: 'insertAsync'}],
+        ['db',{coll: 'tinytest-data',func: 'insertAsync'}],
+        ['db',{coll: 'tinytest-data',func: 'insertAsync'}],
+        ['email',{from: 'arunoda@meteorhacks.com',to: 'hello@meteor.com', func: 'emailAsync'}],
+        ['db',{coll: 'tinytest-data',selector: '{"_id":"a"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1}],
+        ['db',{coll: 'tinytest-data',selector: '{"_id":"b"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1}],
+        ['db',{coll: 'tinytest-data',selector: '{"_id":"c"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1}],
+        ['db',{coll: 'tinytest-data',selector: '{"_id":"a1"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 0,docSize: 0}],
+        ['db',{coll: 'tinytest-data',selector: '{"_id":"a2"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 0,docSize: 0}]
       ]}
     ],
     ['complete']
@@ -785,6 +785,30 @@ addAsyncTest('Tracer - Optimize Events - no mutation', async (test) => {
   test.equal(Array.isArray(partialEvents), true);
 });
 
+addAsyncTest('Tracer - Optimize Events - without metrics', async (test) => {
+  let now = Ntp._now();
+
+  let events = [
+    { ...eventDefaults, type: 'start', at: now, endAt: now },
+    { ...eventDefaults, type: 'wait', at: now, endAt: now + 1000 },
+    { ...eventDefaults, type: 'db', at: now + 2000, endAt: now + 2500 },
+    { type: EventType.Complete, at: now + 4500 }
+  ];
+
+  let expected = [
+    ['start'],
+    ['wait', 1000],
+    ['compute', 1000],
+    ['db', 500],
+    ['compute', 2000],
+    ['complete']
+  ];
+
+  let optimized = Kadira.tracer.optimizeEvents(events);
+
+  test.stableEqual(optimized, expected);
+});
+
 function startTrace () {
   const ddpMessage = {
     id: 'the-id',

From 13890f0ae3778ae05ffe1f075c0ad742bd5de3d9 Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Mon, 13 Nov 2023 19:55:02 -0600
Subject: [PATCH 04/14] Remove unused parentEvent

---
 lib/tracer/tracer.js | 4 ----
 1 file changed, 4 deletions(-)

diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js
index 71ec5c49..dee1a982 100644
--- a/lib/tracer/tracer.js
+++ b/lib/tracer/tracer.js
@@ -175,10 +175,6 @@ Tracer.prototype.asyncEvent = function (type, data, meta, fn) {
 
   const event = this.event(info.trace, type, data, meta);
 
-  if (event) {
-    event.parentEvent = getActiveEvent();
-  }
-
   let reset = this.setActiveEvent(event);
   let result;
 

From 1b1b438fa285943177122d7a901692f90cb8e67e Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Mon, 13 Nov 2023 19:56:38 -0600
Subject: [PATCH 05/14] Call fn directly in asyncEvent

---
 lib/tracer/tracer.js | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js
index dee1a982..12cd8f7d 100644
--- a/lib/tracer/tracer.js
+++ b/lib/tracer/tracer.js
@@ -170,7 +170,7 @@ Tracer.prototype.asyncEvent = function (type, data, meta, fn) {
   const { info } = getStore();
 
   if (!info) {
-    return Reflect.apply(fn, this, [false]);
+    return fn(false);
   }
 
   const event = this.event(info.trace, type, data, meta);
@@ -179,7 +179,7 @@ Tracer.prototype.asyncEvent = function (type, data, meta, fn) {
   let result;
 
   try {
-    result = Reflect.apply(fn, this, [event]);
+    result = fn(event);
   } catch (err) {
     this.eventEnd(info.trace, event, { err: err.message });
     throw err;

From f2003d36773687569ab8721cad55d18873c53cb3 Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Mon, 13 Nov 2023 20:46:29 -0600
Subject: [PATCH 06/14] Fix tests

---
 lib/tracer/tracer.js   |  4 ++--
 tests/tracer/tracer.js | 20 +++++++++-----------
 2 files changed, 11 insertions(+), 13 deletions(-)

diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js
index 12cd8f7d..10c91ce3 100644
--- a/lib/tracer/tracer.js
+++ b/lib/tracer/tracer.js
@@ -347,8 +347,8 @@ Tracer.prototype.optimizeEvent = function (objectEvent, prevEnded, metrics) {
       extraInfo.offset = offset;
     }
 
-    if (this._hasUsefulNested(nested)) {
-      extraInfo.nested = this.optimizeEvent(nested, metrics);
+    if (this._hasUsefulNested(objectEvent)) {
+      extraInfo.nested = this.optimizeEvents(nested, metrics);
     }
   }
 
diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js
index 38cd0b76..7663e7e8 100644
--- a/tests/tracer/tracer.js
+++ b/tests/tracer/tracer.js
@@ -445,8 +445,8 @@ addAsyncTest(
 
     const expected = [
       ['start'],
-      ['wait', traceInfo.events[1][1], {}, { at: 0, endAt: traceInfo.events[1][3].endAt, forcedEnd: true }],
-      ['db', 500, {}, { at: 2000, endAt: 2500}],
+      ['wait', traceInfo.events[1][1], {}, { forcedEnd: true }],
+      ['db', 500, {}, { offset: traceInfo.events[2][3].offset }],
       ['complete']
     ];
 
@@ -647,16 +647,14 @@ addAsyncTest('Tracer - Build Trace - custom with nested parallel events', async
     ['start',{userId: null,params: '[]'}],
     ['wait',{waitOn: []}],
     ['custom', {}, {name: 'test',
-      at: 1,
-      endAt: 1,
       nested: [
         ['db',{coll: 'tinytest-data',func: 'insertAsync'}],
         ['db',{coll: 'tinytest-data',func: 'insertAsync'}],
         ['db',{coll: 'tinytest-data',func: 'insertAsync'}],
-        ['email',{from: 'arunoda@meteorhacks.com',to: 'hello@meteor.com', func: 'emailAsync'}],
+        ['email',{from: 'arunoda@meteorhacks.com',to: 'hello@meteor.com', func: 'emailAsync'}, { offset: 1 }],
         ['db',{coll: 'tinytest-data',selector: '{"_id":"a"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1}],
-        ['db',{coll: 'tinytest-data',selector: '{"_id":"b"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1}],
-        ['db',{coll: 'tinytest-data',selector: '{"_id":"c"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1}],
+        ['db',{coll: 'tinytest-data',selector: '{"_id":"b"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1}, { offset: 1 }],
+        ['db',{coll: 'tinytest-data',selector: '{"_id":"c"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 1,docSize: 1}, { offset: 1 }],
         ['db',{coll: 'tinytest-data',selector: '{"_id":"a1"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 0,docSize: 0}],
         ['db',{coll: 'tinytest-data',selector: '{"_id":"a2"}',func: 'fetch',cursor: true,limit: 1,docsFetched: 0,docSize: 0}]
       ]}
@@ -683,7 +681,7 @@ addAsyncTest('Tracer - Build Trace - should end custom event', async (test) => {
 
   const expected = [
     ['start', 0, { userId: null, params: '[]' }],
-    ['wait', 0, { waitOn: []}, {}],
+    ['wait', 0, { waitOn: []}],
     ['custom', 0, { async: false }, {
       name: 'test',
       nested: [
@@ -695,7 +693,7 @@ addAsyncTest('Tracer - Build Trace - should end custom event', async (test) => {
   ];
   let actual = cleanBuiltEvents(info.trace.events);
 
-  test.equal(actual, expected);
+  test.stableEqual(actual, expected);
 });
 
 addAsyncTest('Tracer - Build Trace - should end async events', async (test) => {
@@ -711,13 +709,13 @@ addAsyncTest('Tracer - Build Trace - should end async events', async (test) => {
 
   const expected = [
     ['start', 0, { userId: null, params: '[]' }],
-    ['wait', 0, { waitOn: [] }, {}],
+    ['wait', 0, { waitOn: [] }],
     ['async', 20],
     ['complete']
   ];
   let actual = cleanBuiltEvents(info.trace.events);
 
-  test.equal(actual, expected);
+  test.stableEqual(actual, expected);
 });
 
 addAsyncTest('Tracer - Build Trace - the correct number of async events are captured for methods', async (test) => {

From 40762857664cff98f54800e267dfe9c4551d3728 Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Mon, 13 Nov 2023 21:19:02 -0600
Subject: [PATCH 07/14] Track compute at beginning of nested events

---
 lib/tracer/tracer.js      |  6 +++++
 tests/_helpers/helpers.js | 11 ++++-----
 tests/tracer/tracer.js    | 48 +++++++++++++++++++++++++++++++++++++++
 3 files changed, 59 insertions(+), 6 deletions(-)

diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js
index 10c91ce3..fe17c3f0 100644
--- a/lib/tracer/tracer.js
+++ b/lib/tracer/tracer.js
@@ -348,7 +348,13 @@ Tracer.prototype.optimizeEvent = function (objectEvent, prevEnded, metrics) {
     }
 
     if (this._hasUsefulNested(objectEvent)) {
+      let nestedStartedAt = nested[0].at;
+      let beginningCompute = nestedStartedAt - at;
       extraInfo.nested = this.optimizeEvents(nested, metrics);
+
+      if (beginningCompute > 0) {
+        extraInfo.nested.unshift(['compute', beginningCompute]);
+      }
     }
   }
 
diff --git a/tests/_helpers/helpers.js b/tests/_helpers/helpers.js
index 5ec5e7e8..d83dbbd3 100644
--- a/tests/_helpers/helpers.js
+++ b/tests/_helpers/helpers.js
@@ -121,12 +121,7 @@ export function getLastMethodEvents (indices = [0], keysToPreserve = []) {
   }
 
   function filterFields (event) {
-    let filteredEvent = [];
-
-    indices.forEach((index) => {
-      filteredEvent.push(clean(event[index]));
-    });
-
+    let filteredEvent = indices.map((index) => clean(event[index]));
     cleanTrailingNilValues(filteredEvent);
 
     return filteredEvent;
@@ -372,6 +367,10 @@ export function cleanBuiltEvents (events) {
         // We only care about the properties that survive being stringified
         // (are not undefined)
         event[3] = JSON.parse(JSON.stringify(details));
+        if (event[3].offset) {
+          // round down to nearest 10
+          event[3].offset = Math.floor(event[3].offset / 10) * 10;
+        }
       }
 
       return event;
diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js
index 7663e7e8..c03ecec2 100644
--- a/tests/tracer/tracer.js
+++ b/tests/tracer/tracer.js
@@ -366,6 +366,47 @@ addAsyncTest(
   }
 );
 
+addAsyncTest(
+  'Tracer - Build Trace - compute time at beginning of nested events',
+  async function (test) {
+    let info;
+
+    const methodId = registerMethod(async function () {
+      doCompute(20);
+      await Kadira.event('test', async () => {
+        doCompute(50);
+        await TestData.insertAsync({});
+      });
+      doCompute(10);
+      info = getInfo();
+    });
+
+    await callAsync(methodId);
+
+    const expected = [
+      ['start', 0, { userId: null, params: '[]' }],
+      ['wait', 0, { waitOn: [] }],
+      ['compute', 20],
+      ['custom', 50, {}, {
+        name: 'test',
+        nested: [
+          ['compute', 50],
+          ['db', 0, { coll: 'tinytest-data', func: 'insertAsync' }],
+          ['async', 0, {}, { offset: 0 }],
+          ['async', 0, {}, { offset: 0 }]
+        ]
+      }],
+      ['async', 0, {}, { offset: 0 }],
+      ['async', 0, {}, { offset: 0 }],
+      ['compute', 10],
+      ['complete']
+    ];
+    let actual = cleanBuiltEvents(info.trace.events);
+
+    test.stableEqual(actual, expected);
+  }
+);
+
 addAsyncTest(
   'Tracer - Build Trace - errored',
   function (test) {
@@ -818,3 +859,10 @@ function startTrace () {
 
   return Kadira.tracer.start(info, ddpMessage);
 }
+
+function doCompute(ms) {
+  let start = Date.now();
+  while (Date.now() - start < ms) {
+    // do work...
+  }
+}

From cd9eda56b2bf707051af7fdb58b18a1c92eaddc9 Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Mon, 13 Nov 2023 21:21:09 -0600
Subject: [PATCH 08/14] Adjust flaky tests

---
 tests/client/models/errors.js       |  4 ++--
 tests/hijack/mongo_driver_events.js | 14 +++++++-------
 tests/tracer/tracer.js              |  2 +-
 3 files changed, 10 insertions(+), 10 deletions(-)

diff --git a/tests/client/models/errors.js b/tests/client/models/errors.js
index 7b8689f0..363260cd 100644
--- a/tests/client/models/errors.js
+++ b/tests/client/models/errors.js
@@ -119,7 +119,7 @@ Tinytest.addAsync(
   function (test, done) {
     let em = new ErrorModel({
       maxErrorsPerInterval: 2,
-      intervalInMillis: 200
+      intervalInMillis: 100
     });
 
     em.sendError({name: 'hoo'});
@@ -130,7 +130,7 @@ Tinytest.addAsync(
       test.equal(em.canSendErrors(), true);
       em.close();
       done();
-    }, 250);
+    }, 200);
   }
 );
 
diff --git a/tests/hijack/mongo_driver_events.js b/tests/hijack/mongo_driver_events.js
index ee5bd042..ef66176d 100644
--- a/tests/hijack/mongo_driver_events.js
+++ b/tests/hijack/mongo_driver_events.js
@@ -2,7 +2,7 @@ import { getMongoDriverStats, resetMongoDriverStats } from '../../lib/hijack/mon
 import { addAsyncTest } from '../_helpers/helpers';
 import { TestData } from '../_helpers/globals';
 
-function checkRange (value, disabledValue, min, max) {
+function checkRange (value, min, max) {
   if (typeof value !== 'number') {
     throw new Error(`${value} is not a number`);
   }
@@ -33,15 +33,15 @@ addAsyncTest(
 
     const stats = getMongoDriverStats();
 
-    checkRange(stats.poolSize, 0, 10, 100);
+    checkRange(stats.poolSize, 10, 100);
     test.equal(stats.primaryCheckouts, 200);
     test.equal(stats.otherCheckouts, 0);
     // TODO: these maximum numbers seem too high
-    checkRange(stats.checkoutTime, 0, 100, 40000);
-    checkRange(stats.maxCheckoutTime, 0, 10, 300);
-    checkRange(stats.pending, 0, 0, 200);
-    checkRange(stats.checkedOut, 0, 0, 15);
-    checkRange(stats.created, 0, 1, 100);
+    checkRange(stats.checkoutTime, 100, 40000);
+    checkRange(stats.maxCheckoutTime, 10, 300);
+    checkRange(stats.pending, 0, 200);
+    checkRange(stats.checkedOut, 0, 20);
+    checkRange(stats.created, 1, 100);
   }
 );
 
diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js
index c03ecec2..eeb096b4 100644
--- a/tests/tracer/tracer.js
+++ b/tests/tracer/tracer.js
@@ -741,7 +741,7 @@ addAsyncTest('Tracer - Build Trace - should end async events', async (test) => {
   let info;
 
   const methodId = registerMethod(async function () {
-    await sleep(20);
+    await sleep(21);
 
     info = getInfo();
   });

From 7e223ecc7b76da0e9b132db803031e06255f2e3e Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Tue, 14 Nov 2023 10:39:37 -0600
Subject: [PATCH 09/14] Add test for offset accuracy

---
 tests/tracer/tracer.js | 93 +++++++++++++++++++++++++++++++++++++++++-
 1 file changed, 92 insertions(+), 1 deletion(-)

diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js
index eeb096b4..22c80bc0 100644
--- a/tests/tracer/tracer.js
+++ b/tests/tracer/tracer.js
@@ -706,6 +706,97 @@ addAsyncTest('Tracer - Build Trace - custom with nested parallel events', async
   test.stableEqual(events, expected);
 });
 
+addAsyncTest('Tracer - Build Trace - offset is reversible', async function (test) {
+  const Email = Package['email'].Email;
+
+  let origEvents;
+  let info;
+  let methodId = registerMethod(async function () {
+    let backgroundPromise;
+    // Compute
+    await sleep(30);
+
+    await Kadira.event('test', async (event) => {
+      await TestData.insertAsync({ _id: 'a', n: 1 });
+      await TestData.insertAsync({ _id: 'b', n: 2 });
+      await TestData.insertAsync({ _id: 'c', n: 3 });
+
+      backgroundPromise = Promise.resolve().then(async () => {
+        // Email
+        Email.sendAsync({ from: 'arunoda@meteorhacks.com', to: 'hello@meteor.com' });
+      });
+
+      // Compute
+      await sleep(30);
+
+      const ids = ['a', 'b', 'c'];
+
+      // DB
+      await Promise.all(ids.map(_id => TestData.findOneAsync({ _id })));
+
+      await TestData.findOneAsync({ _id: 'a1' }).then(() =>
+        // Is this nested under the previous findOneAsync or is it a sibling?
+        TestData.findOneAsync({ _id: 'a2' })
+      );
+
+      Kadira.endEvent(event);
+    });
+
+    origEvents = getInfo().trace.events;
+    info = getInfo();
+
+    return backgroundPromise;
+  });
+
+  await callAsync(methodId);
+
+  let origTimestamps = origEvents.reduce((timestamps, event) => {
+    if (event.type !== 'async') {
+      timestamps.push(event.at);
+    }
+    if (event.nested && event.type === 'custom') {
+      event.nested.forEach(nestedEvent => {
+        if (nestedEvent.type !== 'async') {
+          timestamps.push(nestedEvent.at);
+        }
+      });
+    }
+
+    return timestamps;
+  }, []);
+
+  let calculatedTimestamps = [];
+  let total = info.trace.at;
+  info.trace.events.forEach((event) => {
+    let [type, duration = 0, , details = {}] = event;
+    let offset = details.offset || 0;
+
+    total -= offset;
+    if (type !== 'async' && type !== 'compute') {
+      calculatedTimestamps.push(total);
+    }
+
+    if (details.nested && type === 'custom') {
+      let nestedTotal = total;
+      details.nested.forEach(nestedEvent => {
+        if (nestedEvent[3] && nestedEvent[3].offset) {
+          nestedTotal -= nestedEvent[3].offset;
+        }
+
+        if (nestedEvent[0] !== 'async' && nestedEvent[0] !== 'compute') {
+          calculatedTimestamps.push(nestedTotal);
+        }
+
+        nestedTotal += nestedEvent[1] || 0;
+      });
+    }
+
+    total += duration;
+  });
+
+  test.stableEqual(calculatedTimestamps, origTimestamps);
+});
+
 addAsyncTest('Tracer - Build Trace - should end custom event', async (test) => {
   let info;
 
@@ -860,7 +951,7 @@ function startTrace () {
   return Kadira.tracer.start(info, ddpMessage);
 }
 
-function doCompute(ms) {
+function doCompute (ms) {
   let start = Date.now();
   while (Date.now() - start < ms) {
     // do work...

From 5e8a1d4379c8d04de1ed7a3ed4a985583cd1cb31 Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Tue, 14 Nov 2023 11:11:52 -0600
Subject: [PATCH 10/14] Only count each ms once

---
 lib/tracer/tracer.js   | 23 ++++++++++++++++---
 tests/tracer/tracer.js | 50 ++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 70 insertions(+), 3 deletions(-)

diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js
index fe17c3f0..25367c2c 100644
--- a/lib/tracer/tracer.js
+++ b/lib/tracer/tracer.js
@@ -4,6 +4,7 @@ import { CreateUserStack, DefaultUniqueId, isPromise, last } from '../utils';
 import { Ntp } from '../ntp';
 import { EventType, MaxAsyncLevel } from '../constants';
 import { getActiveEvent, getInfo, getStore, MontiAsyncStorage } from '../async/als';
+import assert from 'assert';
 
 let eventLogger = require('debug')('kadira:tracer');
 
@@ -301,6 +302,7 @@ function incrementMetric (metrics, name, value) {
  *
  * @param {Object} objectEvent Expanded object event.
  *
+ * @param {Number}  prevEnded The timestamp the previous event ended
  * @param {Object} metrics A metrics object to be updated along the optimization process.
  * @returns {Array} Array notation of the event optimized for transport.
  */
@@ -392,6 +394,7 @@ Tracer.prototype.optimizeEvents = function (events, metrics) {
   processedEvents.push(this.optimizeEvent(events[0], events[0].at, metrics));
 
   let previousEnd = events[0].at + (processedEvents[0][1] || 0);
+  let countedUntil = previousEnd;
 
   for (let i = 1; i < events.length; i += 1) {
     let event = events[i];
@@ -400,14 +403,28 @@ Tracer.prototype.optimizeEvents = function (events, metrics) {
 
     if (computeTime > 0) {
       processedEvents.push([EventType.Compute, computeTime]);
-      incrementMetric(metrics, 'compute', computeTime);
       previousEnd += computeTime;
+
+      if (previousEnd > countedUntil) {
+        let diff = Math.min(computeTime, previousEnd - countedUntil);
+        incrementMetric(metrics, 'compute', diff);
+        countedUntil = previousEnd;
+      }
     }
 
-    let processedEvent = this.optimizeEvent(event, previousEnd, metrics);
+    let processedEvent = this.optimizeEvent(event, previousEnd);
     processedEvents.push(processedEvent);
 
-    previousEnd = event.at + (processedEvent[1] || 0);
+    let duration = processedEvent[1] || 0;
+    previousEnd = event.at + duration;
+
+    if (duration > 0 && previousEnd > countedUntil) {
+      let count = previousEnd - countedUntil;
+      assert(count <= duration, 'unexpected gap in countedUntil');
+      incrementMetric(metrics, processedEvent[0], count);
+
+      countedUntil = previousEnd;
+    }
   }
 
   if (processedEvents.length > MAX_TRACE_EVENTS) {
diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js
index 22c80bc0..4f69bfb5 100644
--- a/tests/tracer/tracer.js
+++ b/tests/tracer/tracer.js
@@ -643,6 +643,56 @@ Tinytest.add(
   }
 );
 
+addAsyncTest('Tracer - Build Trace - each ms counted once with parallel events', async function (test) {
+  const Email = Package['email'].Email;
+  let info;
+
+  let methodId = registerMethod(async function () {
+    let backgroundPromise;
+    // Compute
+    await sleep(30);
+
+    await TestData.insertAsync({ _id: 'a', n: 1 });
+    await TestData.insertAsync({ _id: 'b', n: 2 });
+    await TestData.insertAsync({ _id: 'c', n: 3 });
+
+    backgroundPromise = Promise.resolve().then(async () => {
+      // Email
+      Email.sendAsync({ from: 'arunoda@meteorhacks.com', to: 'hello@meteor.com' });
+    });
+
+    // Compute
+    await sleep(30);
+
+    const ids = ['a', 'b', 'c'];
+
+    // DB
+    await Promise.all(ids.map(_id => TestData.findOneAsync({ _id })));
+
+    await TestData.findOneAsync({ _id: 'a1' }).then(() =>
+      // Is this nested under the previous findOneAsync or is it a sibling?
+      TestData.findOneAsync({ _id: 'a2' })
+    );
+
+    info = getInfo();
+
+    return backgroundPromise;
+  });
+
+  await callAsync(methodId);
+
+  let metrics = info.trace.metrics;
+  let total = metrics.total;
+  let sum = 0;
+  Object.keys(metrics).forEach(key => {
+    if (key !== 'total') {
+      sum += metrics[key];
+    }
+  });
+
+  test.equal(sum, total);
+});
+
 addAsyncTest('Tracer - Build Trace - custom with nested parallel events', async function (test) {
   const Email = Package['email'].Email;
 

From 8f2d57e6850ed0bfc83e7e3a9ca287a2fa7579e5 Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Tue, 14 Nov 2023 14:11:08 -0600
Subject: [PATCH 11/14] Use nested events for metrics in place of custom event

---
 lib/tracer/tracer.js      | 59 ++++++++++++++++--------
 tests/_helpers/helpers.js |  8 ++--
 tests/tracer/tracer.js    | 95 +++++++++++++++++++++++++++++++++++++++
 3 files changed, 140 insertions(+), 22 deletions(-)

diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js
index 25367c2c..fb83fd75 100644
--- a/lib/tracer/tracer.js
+++ b/lib/tracer/tracer.js
@@ -246,9 +246,12 @@ Tracer.prototype.endLastEvent = function (traceInfo) {
 // which is not helpful. This returns true if
 // there are nested events other than async.
 Tracer.prototype._hasUsefulNested = function (event) {
-  return event.nested &&
-    event.nested.length &&
-    !event.nested.every(e => e.type === 'async');
+  if (!event.nested || event.nested.length === 0) {
+    return false;
+  }
+
+  return event.type === Event.Custom ||
+    event.nested.some(e => e.type !== 'async');
 };
 
 Tracer.prototype.buildTrace = function (traceInfo) {
@@ -294,26 +297,29 @@ function incrementMetric (metrics, name, value) {
 }
 
 /**
- * There are two formats for traces. While the method/publication is running, the trace is in the object format.
- * This is easier to work with, but takes more space to store. After the trace is complete (either finished or errored),
+ * There are two formats for traces. While the method/publication is running,
+ * the trace is in the object format. This is easier to work with, but takes more
+ * space to store. After the trace is complete (either finished or errored),
  * it is built which among other things converts the events to the array format.
  *
- * The key difference of `optimizeEvent` and `optimizeEvents` is that they do not mutate the original events.
+ * optimizeEvent does not mutate the events, so it can safely be called
+ * multiple times for the same trace
  *
  * @param {Object} objectEvent Expanded object event.
  *
  * @param {Number}  prevEnded The timestamp the previous event ended
- * @param {Object} metrics A metrics object to be updated along the optimization process.
+ * @param {Object} nestedMetrics A metrics object to be updated for nested events
+ *                 Only include if the nested events should affect metrics
  * @returns {Array} Array notation of the event optimized for transport.
  */
-Tracer.prototype.optimizeEvent = function (objectEvent, prevEnded, metrics) {
+Tracer.prototype.optimizeEvent = function (objectEvent, prevEnded, nestedMetrics) {
   if (Array.isArray(objectEvent)) {
     // If it is an array, it is already optimized
     return objectEvent;
   }
 
-  let { at, endAt, stack, nested = [], name, forcedEnd, type, data, level = 0 } = objectEvent;
-
+  let { at, endAt, stack, nested = [], name, forcedEnd, type, data } = objectEvent;
+  let isCustom = type === EventType.Custom;
 
   // Unused data is removed at the end
   const optimizedEvent = [type, 0, EMPTY_OBJECT, null];
@@ -337,11 +343,6 @@ Tracer.prototype.optimizeEvent = function (objectEvent, prevEnded, metrics) {
     let duration = endAt - at;
     optimizedEvent[1] = duration;
 
-    if (metrics && duration > 0 && level === 0) {
-      metrics[type] = metrics[type] || 0;
-      metrics[type] += duration;
-    }
-
     let offset = prevEnded - at;
     if (offset < 0) {
       throw new Error('Monti APM: unexpected gap between events');
@@ -352,11 +353,24 @@ Tracer.prototype.optimizeEvent = function (objectEvent, prevEnded, metrics) {
     if (this._hasUsefulNested(objectEvent)) {
       let nestedStartedAt = nested[0].at;
       let beginningCompute = nestedStartedAt - at;
-      extraInfo.nested = this.optimizeEvents(nested, metrics);
+      extraInfo.nested = this.optimizeEvents(nested, nestedMetrics);
 
       if (beginningCompute > 0) {
         extraInfo.nested.unshift(['compute', beginningCompute]);
+        incrementMetric(nestedMetrics, 'compute', beginningCompute);
       }
+
+      let lastEvent = last(nested);
+      let lastEndedAt = lastEvent.at + (last(extraInfo.nested)[1] || 0);
+      let endComputeTime = endAt - lastEndedAt;
+      if (endComputeTime > 0) {
+        extraInfo.nested.push(['compute', endComputeTime]);
+        incrementMetric(nestedMetrics, 'compute', endComputeTime);
+      }
+    } else if (isCustom) {
+      // If there are no nested events, record everything as compute time
+      extraInfo.nested = [['compute', duration]];
+      incrementMetric(nestedMetrics, 'compute', duration);
     }
   }
 
@@ -398,6 +412,7 @@ Tracer.prototype.optimizeEvents = function (events, metrics) {
 
   for (let i = 1; i < events.length; i += 1) {
     let event = events[i];
+    let isCustomEvent = event.type === EventType.Custom;
 
     computeTime = event.at - previousEnd;
 
@@ -412,7 +427,11 @@ Tracer.prototype.optimizeEvents = function (events, metrics) {
       }
     }
 
-    let processedEvent = this.optimizeEvent(event, previousEnd);
+    let processedEvent = this.optimizeEvent(
+      event,
+      previousEnd,
+      isCustomEvent ? metrics : undefined
+    );
     processedEvents.push(processedEvent);
 
     let duration = processedEvent[1] || 0;
@@ -421,7 +440,11 @@ Tracer.prototype.optimizeEvents = function (events, metrics) {
     if (duration > 0 && previousEnd > countedUntil) {
       let count = previousEnd - countedUntil;
       assert(count <= duration, 'unexpected gap in countedUntil');
-      incrementMetric(metrics, processedEvent[0], count);
+
+      // The nested events are used instead
+      if (!isCustomEvent) {
+        incrementMetric(metrics, processedEvent[0], count);
+      }
 
       countedUntil = previousEnd;
     }
diff --git a/tests/_helpers/helpers.js b/tests/_helpers/helpers.js
index d83dbbd3..a3557c2b 100644
--- a/tests/_helpers/helpers.js
+++ b/tests/_helpers/helpers.js
@@ -347,21 +347,21 @@ export function cleanEvents (events) {
   });
 }
 
-export function cleanBuiltEvents (events) {
+export function cleanBuiltEvents (events, roundTo = 10) {
   return events
     .filter(event => event[0] !== 'compute' || event[1] > 5)
     .map(event => {
       let [, duration, , details] = event;
       if (typeof duration === 'number') {
         // round down to nearest 10
-        event[1] = Math.floor(duration / 10) * 10;
+        event[1] = Math.floor(duration / roundTo) * roundTo;
       }
 
       if (details) {
         delete details.at;
         delete details.endAt;
         if (details.nested) {
-          details.nested = cleanBuiltEvents(details.nested);
+          details.nested = cleanBuiltEvents(details.nested, roundTo);
         }
 
         // We only care about the properties that survive being stringified
@@ -369,7 +369,7 @@ export function cleanBuiltEvents (events) {
         event[3] = JSON.parse(JSON.stringify(details));
         if (event[3].offset) {
           // round down to nearest 10
-          event[3].offset = Math.floor(event[3].offset / 10) * 10;
+          event[3].offset = Math.floor(event[3].offset / roundTo) * roundTo;
         }
       }
 
diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js
index 4f69bfb5..b56c106f 100644
--- a/tests/tracer/tracer.js
+++ b/tests/tracer/tracer.js
@@ -407,6 +407,101 @@ addAsyncTest(
   }
 );
 
+addAsyncTest(
+  'Tracer - Build Trace - compute time at end of nested events',
+  async function (test) {
+    let info;
+
+    const methodId = registerMethod(async function () {
+      doCompute(20);
+      await Kadira.event('test', async () => {
+        await TestData.insertAsync({});
+        await TestData.insertAsync({});
+        doCompute(41);
+      });
+      doCompute(20);
+      info = getInfo();
+    });
+
+    await callAsync(methodId);
+
+    const expected = [
+      ['start', 0, { userId: null, params: '[]' }],
+      ['wait', 0, { waitOn: [] }],
+      ['compute', 20],
+      ['custom', 40, {}, {
+        name: 'test',
+        nested: [
+          ['db', 0, { coll: 'tinytest-data', func: 'insertAsync' }],
+          ['async', 0, {}, { offset: 0 }],
+          ['async', 0, {}, { offset: 0 }],
+          ['db', 0, { coll: 'tinytest-data', func: 'insertAsync' }],
+          ['async', 0, {}, { offset: 0 }],
+          ['async', 0, {}, { offset: 0 }],
+          ['compute', 40],
+        ]
+      }],
+      ['async', 40, {}, { offset: 40 }],
+      ['async', 40, {}, { offset: 40 }],
+      ['compute', 20],
+      ['complete']
+    ];
+
+    let actual = cleanBuiltEvents(info.trace.events, 20);
+
+    test.stableEqual(actual, expected);
+
+    console.log('metrics -- 2', info.trace.metrics);
+
+    test.equal(info.trace.metrics.compute >= 70, true);
+    test.equal(info.trace.metrics.db > 0, true);
+    test.equal(info.trace.metrics.async < 5, true);
+    test.equal(info.trace.metrics.custom, undefined);
+  }
+);
+
+addAsyncTest(
+  'Tracer - Build Trace - use events nested under custom for metrics',
+  async function (test) {
+    let info;
+
+    const methodId = registerMethod(async function () {
+      await Kadira.event('test', async () => {
+        doCompute(50);
+        await TestData.insertAsync({});
+        await TestData.insertAsync({});
+        await sleep(11);
+      });
+      info = getInfo();
+    });
+
+    await callAsync(methodId);
+    console.log('metrics --', info.trace.metrics);
+    test.equal(info.trace.metrics.compute >= 50, true);
+    test.equal(info.trace.metrics.db > 0, true);
+    test.equal(info.trace.metrics.async > 10, true);
+    test.equal(info.trace.metrics.custom, undefined);
+  }
+);
+
+addAsyncTest(
+  'Tracer - Build Trace - compute time for custom event without nested events',
+  async function (test) {
+    let info;
+
+    const methodId = registerMethod(async function () {
+      Kadira.event('test', async () => {
+        doCompute(50);
+      });
+      info = getInfo();
+    });
+
+    await callAsync(methodId);
+    test.equal(info.trace.metrics.compute > 40, true);
+    test.equal(info.trace.metrics.custom, undefined);
+  }
+);
+
 addAsyncTest(
   'Tracer - Build Trace - errored',
   function (test) {

From 443e228125d3ff33cfd06588a6ea79f3ec47eb4b Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Tue, 14 Nov 2023 14:12:06 -0600
Subject: [PATCH 12/14] Improve flaky test

---
 tests/tracer/tracer.js | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js
index b56c106f..efc72355 100644
--- a/tests/tracer/tracer.js
+++ b/tests/tracer/tracer.js
@@ -387,10 +387,10 @@ addAsyncTest(
       ['start', 0, { userId: null, params: '[]' }],
       ['wait', 0, { waitOn: [] }],
       ['compute', 20],
-      ['custom', 50, {}, {
+      ['custom', 40, {}, {
         name: 'test',
         nested: [
-          ['compute', 50],
+          ['compute', 40],
           ['db', 0, { coll: 'tinytest-data', func: 'insertAsync' }],
           ['async', 0, {}, { offset: 0 }],
           ['async', 0, {}, { offset: 0 }]
@@ -398,10 +398,10 @@ addAsyncTest(
       }],
       ['async', 0, {}, { offset: 0 }],
       ['async', 0, {}, { offset: 0 }],
-      ['compute', 10],
+      ['compute', 0],
       ['complete']
     ];
-    let actual = cleanBuiltEvents(info.trace.events);
+    let actual = cleanBuiltEvents(info.trace.events, 20);
 
     test.stableEqual(actual, expected);
   }
@@ -962,10 +962,10 @@ addAsyncTest('Tracer - Build Trace - should end custom event', async (test) => {
     ['custom', 0, { async: false }, {
       name: 'test',
       nested: [
-        ['custom', 0, { value: true }, { name: 'test2' }],
+        ['custom', 0, { value: true }, { name: 'test2', nested: []}],
       ]
     }],
-    ['custom', 0, {}, { name: 'test3' }],
+    ['custom', 0, {}, { name: 'test3', nested: [] }],
     ['complete']
   ];
   let actual = cleanBuiltEvents(info.trace.events);

From f0fe6f0012bbbfb3dc7f49bfbe0040edc9eb39ea Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Tue, 14 Nov 2023 14:12:44 -0600
Subject: [PATCH 13/14] Speed up test

---
 tests/tracer/tracer.js | 8 ++++----
 1 file changed, 4 insertions(+), 4 deletions(-)

diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js
index efc72355..164af66c 100644
--- a/tests/tracer/tracer.js
+++ b/tests/tracer/tracer.js
@@ -999,17 +999,17 @@ addAsyncTest('Tracer - Build Trace - the correct number of async events are capt
   let info;
 
   const methodId = registerMethod(async function () {
-    await sleep(100);
-    await sleep(200);
+    await sleep(60);
+    await sleep(70);
 
     info = getInfo();
 
-    return await sleep(300);
+    return await sleep(80);
   });
 
   await callAsync(methodId);
 
-  const asyncEvents = info.trace.events.filter(([type, duration]) => type === EventType.Async && duration >= 100);
+  const asyncEvents = info.trace.events.filter(([type, duration]) => type === EventType.Async && duration >= 50);
 
   test.equal(asyncEvents.length, 3);
 });

From edc33ff487f80873a603a6e394c772e9c6abc007 Mon Sep 17 00:00:00 2001
From: zodern <zodern@users.noreply.github.com>
Date: Tue, 14 Nov 2023 14:36:31 -0600
Subject: [PATCH 14/14] Ignore unhelpful async events

---
 lib/tracer/tracer.js   | 11 +++++++++++
 tests/tracer/tracer.js | 21 +++------------------
 2 files changed, 14 insertions(+), 18 deletions(-)

diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js
index fb83fd75..d9892124 100644
--- a/lib/tracer/tracer.js
+++ b/lib/tracer/tracer.js
@@ -414,6 +414,17 @@ Tracer.prototype.optimizeEvents = function (events, metrics) {
     let event = events[i];
     let isCustomEvent = event.type === EventType.Custom;
 
+    // There are sometimes extra async events related to the previous event.
+    // Ignore new async events that end before last event.
+    // These events don't contribute anything to the metrics or compute events.
+    if (
+      event.type === EventType.Async &&
+      event.endAt &&
+      event.endAt <= previousEnd
+    ) {
+      continue;
+    }
+
     computeTime = event.at - previousEnd;
 
     if (computeTime > 0) {
diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js
index 164af66c..f140b591 100644
--- a/tests/tracer/tracer.js
+++ b/tests/tracer/tracer.js
@@ -291,7 +291,7 @@ addAsyncTest(
       'custom',
       0,
       data,
-      { name: 'test' }
+      { name: 'test', nested: [] }
     ];
     let actualEvent = cleanBuiltEvents(info.trace.events)
       .find(event => event[0] === 'custom');
@@ -392,12 +392,8 @@ addAsyncTest(
         nested: [
           ['compute', 40],
           ['db', 0, { coll: 'tinytest-data', func: 'insertAsync' }],
-          ['async', 0, {}, { offset: 0 }],
-          ['async', 0, {}, { offset: 0 }]
         ]
       }],
-      ['async', 0, {}, { offset: 0 }],
-      ['async', 0, {}, { offset: 0 }],
       ['compute', 0],
       ['complete']
     ];
@@ -415,7 +411,6 @@ addAsyncTest(
     const methodId = registerMethod(async function () {
       doCompute(20);
       await Kadira.event('test', async () => {
-        await TestData.insertAsync({});
         await TestData.insertAsync({});
         doCompute(41);
       });
@@ -433,16 +428,9 @@ addAsyncTest(
         name: 'test',
         nested: [
           ['db', 0, { coll: 'tinytest-data', func: 'insertAsync' }],
-          ['async', 0, {}, { offset: 0 }],
-          ['async', 0, {}, { offset: 0 }],
-          ['db', 0, { coll: 'tinytest-data', func: 'insertAsync' }],
-          ['async', 0, {}, { offset: 0 }],
-          ['async', 0, {}, { offset: 0 }],
           ['compute', 40],
         ]
       }],
-      ['async', 40, {}, { offset: 40 }],
-      ['async', 40, {}, { offset: 40 }],
       ['compute', 20],
       ['complete']
     ];
@@ -451,10 +439,7 @@ addAsyncTest(
 
     test.stableEqual(actual, expected);
 
-    console.log('metrics -- 2', info.trace.metrics);
-
     test.equal(info.trace.metrics.compute >= 70, true);
-    test.equal(info.trace.metrics.db > 0, true);
     test.equal(info.trace.metrics.async < 5, true);
     test.equal(info.trace.metrics.custom, undefined);
   }
@@ -476,10 +461,10 @@ addAsyncTest(
     });
 
     await callAsync(methodId);
-    console.log('metrics --', info.trace.metrics);
+
     test.equal(info.trace.metrics.compute >= 50, true);
     test.equal(info.trace.metrics.db > 0, true);
-    test.equal(info.trace.metrics.async > 10, true);
+    test.equal(info.trace.metrics.async >= 10, true);
     test.equal(info.trace.metrics.custom, undefined);
   }
 );