Keep Nested Async Events

lib/common/utils.js

@@ -131,3 +131,8 @@ export const millisToHuman = function (milliseconds) {
 
   return builder.join(' ');
 };
+
+
+export const isFilledArray = arr => Array.isArray(arr) && arr.length > 0;
+
+export const isEveryEventAsync = events => events.every(event => event.type === 'async');

lib/constants.js

@@ -0,0 +1,13 @@
+export const EventType = {
+  ASYNC: 'async',
+  COMPLETE: 'complete',
+  COMPUTE: 'compute',
+  CUSTOM: 'custom',
+  DB: 'db',
+  EMAIL: 'email',
+  ERROR: 'error',
+  FS: 'fs',
+  HTTP: 'http',
+  START: 'start',
+  WAIT: 'wait',
+};

lib/tracer/tracer.js

@@ -1,7 +1,8 @@
 import { _ } from 'meteor/underscore';
-import { objectHasData } from '../common/utils';
 import { CreateUserStack, DefaultUniqueId } from '../utils';
+import { isEveryEventAsync, isFilledArray, objectHasData } from '../common/utils';
 import { Ntp } from '../ntp';
+import { EventType } from '../constants';
 
 
 let eventLogger = Npm.require('debug')('kadira:tracer');
@@ -164,9 +165,11 @@ 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 (Kadira.options.eventStackTrace && isFilledArray(event.nested) && [EventType.CUSTOM, EventType.ASYNC].includes(event.type)) {
+    return true;
+  }
+
+  return isFilledArray(event.nested) && !isEveryEventAsync(event.nested);
 };
 
 Tracer.prototype.buildEvent = function (event, depth = 0, trace) {
@@ -214,21 +217,50 @@ Tracer.prototype.buildEvent = function (event, depth = 0, trace) {
   return builtEvent;
 };
 
+Tracer.prototype._buildMetrics = function ({ events, traceInfo, metrics, onBuild }) {
+  if (!isFilledArray(events)) return;
+
+  for (let i = 0; i < events.length; i++) {
+    let prevEvent = i > 0 ? events[i - 1] : null;
+    let event = events[i];
+
+    if ([EventType.START, EventType.COMPLETE].includes(event.type)) continue;
+
+    if (!event.endAt) {
+      console.error('Monti APM: no end event for type: ', event.type);
+      continue;
+    }
+
+    const computeTime = prevEvent ? event.at - prevEvent.endAt : 0;
+
+    let builtEvent = this.buildEvent(event, 0, traceInfo);
+
+    if (onBuild) onBuild({ builtEvent, computeTime });
+
+    if (event.type === EventType.CUSTOM) {
+      this._buildMetrics({ events: event.nested, traceInfo, metrics });
+      return;
+    }
+
+    metrics[event.type] = metrics[event.type] || 0;
+    metrics[event.type] += builtEvent[1];
+  }
+};
+
 Tracer.prototype.buildTrace = function (traceInfo) {
   let firstEvent = traceInfo.events[0];
   let lastEvent = traceInfo.events[traceInfo.events.length - 1];
   let processedEvents = [];
 
-  if (firstEvent.type !== 'start') {
+  if (firstEvent.type !== EventType.START) {
     console.warn('Monti APM: trace has not started yet');
     return null;
-  } else if (lastEvent.type !== 'complete' && lastEvent.type !== 'error') {
-    // trace is not completed or errored yet
+  } else if (lastEvent.type !== EventType.COMPLETE && lastEvent.type !== EventType.ERROR) {
     console.warn('Monti APM: trace has not completed or errored yet');
     return null;
   }
-  // build the metrics
-  traceInfo.errored = lastEvent.type === 'error';
+
+  traceInfo.errored = lastEvent.type === EventType.ERROR;
   traceInfo.at = firstEvent.at;
 
   let metrics = {
@@ -237,46 +269,40 @@ Tracer.prototype.buildTrace = function (traceInfo) {
 
   let totalNonCompute = 0;
 
-  firstEvent = ['start', 0];
+  firstEvent = [EventType.START, 0];
+
   if (traceInfo.events[0].data) {
     firstEvent.push(traceInfo.events[0].data);
   }
-  processedEvents.push(firstEvent);
 
-  let computeTime;
+  processedEvents.push(firstEvent);
 
-  for (let lc = 1; lc < traceInfo.events.length - 1; lc += 1) {
-    let prevEvent = traceInfo.events[lc - 1];
-    let event = traceInfo.events[lc];
+  this._buildMetrics({ events: traceInfo.events,
+    traceInfo,
+    metrics,
+    onBuild: ({ builtEvent, computeTime }) => {
+      if (computeTime > 0) {
+        processedEvents.push([EventType.COMPUTE, computeTime]);
+      }
 
-    if (!event.endAt) {
-      console.error('Monti APM: no end event for type: ', event.type);
-      return null;
-    }
+      processedEvents.push(builtEvent);
 
-    computeTime = event.at - prevEvent.endAt;
-    if (computeTime > 0) {
-      processedEvents.push(['compute', computeTime]);
+      totalNonCompute += builtEvent[1];
     }
-    let builtEvent = this.buildEvent(event, 0, traceInfo);
-    processedEvents.push(builtEvent);
-
-    metrics[event.type] = metrics[event.type] || 0;
-    metrics[event.type] += builtEvent[1];
-    totalNonCompute += builtEvent[1];
-  }
-
+  });
 
-  computeTime = lastEvent.at - traceInfo.events[traceInfo.events.length - 2].endAt;
+  const computeTime = lastEvent.at - traceInfo.events[traceInfo.events.length - 2].endAt;
 
   if (computeTime > 0) {
-    processedEvents.push(['compute', computeTime]);
+    processedEvents.push([EventType.COMPUTE, computeTime]);
   }
 
   let lastEventData = [lastEvent.type, 0];
+
   if (lastEvent.data) {
     lastEventData.push(lastEvent.data);
   }
+
   processedEvents.push(lastEventData);
 
   if (processedEvents.length > MAX_TRACE_EVENTS) {

lib/utils.js

@@ -115,6 +115,10 @@ export function pick (obj, keys) {
   }, {});
 }
 
+export function cloneDeep (obj) {
+  return JSON.parse(JSON.stringify(obj));
+}
+
 export function calculateWaitedOnTime (messageQueue) {
   let waitedOnTime = 0;
 

package.json

@@ -17,6 +17,7 @@
   },
   "dependencies": {},
   "volta": {
-    "node": "14.21.2"
+    "node": "14.21.2",
+    "npm": "6.14.17"
   }
 }

tests/tracer/tracer.js

@@ -1,4 +1,6 @@
 import { _ } from 'meteor/underscore';
+import { cloneDeep } from '../../lib/utils';
+import { EventType } from '../../lib/constants';
 import { Tracer } from '../../lib/tracer/tracer';
 import { Wait } from '../_helpers/helpers';
 
@@ -295,7 +297,8 @@ Tinytest.add(
       ]
     };
     Kadira.tracer.buildTrace(traceInfo);
-    test.equal(traceInfo.metrics, undefined);
+    // Wait event is not ended, so it will be ignored but will not affect the metrics
+    test.equal(traceInfo.metrics, { total: 2500, db: 500, compute: 2000 });
   }
 );
 
@@ -447,6 +450,81 @@ Tinytest.add(
   }
 );
 
+Tinytest.add(
+  'Tracer - should keep nested events',
+  function (test) {
+    let now = new Date().getTime();
+
+    const oldOptions = cloneDeep(Kadira.options);
+
+    Kadira.options.eventStackTrace = true;
+
+    let traceInfo = {
+      events: [
+        {...eventDefaults, type: EventType.START, at: now, endAt: now},
+        {...eventDefaults, type: EventType.WAIT, at: now, endAt: now + 1000, nested: [{ type: EventType.DB, endAt: null }]},
+        {...eventDefaults, type: EventType.ASYNC, at: now + 1000, endAt: now + 2500, nested: [{ type: EventType.ASYNC, endAt: null }]},
+        {...eventDefaults, type: EventType.DB, at: now + 2500, endAt: now + 3500, nested: [{ type: EventType.ASYNC, endAt: null }]},
+        {type: EventType.COMPLETE, at: now + 3500}
+      ]
+    };
+
+    Kadira.tracer.buildTrace(traceInfo);
+
+    test.equal(traceInfo.events[2][3].nested.length, 1);
+    test.equal(traceInfo.events[3][3], undefined);
+
+    test.equal(traceInfo.metrics, {
+      total: 3500,
+      wait: 1000,
+      async: 1500,
+      db: 1000,
+      compute: 0,
+    });
+
+    test.equal(traceInfo.errored, false);
+
+    Kadira.options = oldOptions;
+  }
+);
+
+
+Tinytest.add(
+  'Tracer - should account nested custom events as if they were in the root level',
+  function (test) {
+    let now = new Date().getTime();
+
+    const oldOptions = cloneDeep(Kadira.options);
+
+    Kadira.options.eventStackTrace = true;
+
+    let traceInfo = {
+      events: [
+        {...eventDefaults, type: EventType.START, at: now, endAt: now},
+        {...eventDefaults, type: EventType.CUSTOM, at: now + 1000, endAt: now + 2500, nested: [{ type: 'async', at: now + 200, endAt: now + 300 }, { type: 'db', at: now + 200, endAt: now + 300 }]},
+        {type: EventType.COMPLETE, at: now + 2500}
+      ]
+    };
+
+    Kadira.tracer.buildTrace(traceInfo);
+
+    test.equal(traceInfo.events.length, 4);
+    test.equal(traceInfo.events[2][3].nested.length, 2);
+    test.equal(traceInfo.events[3][3], undefined);
+
+    test.equal(traceInfo.metrics, {
+      total: 2500,
+      compute: 1000,
+      async: 100,
+      db: 100,
+    });
+
+    test.equal(traceInfo.errored, false);
+
+    Kadira.options = oldOptions;
+  }
+);
+
 function startTrace () {
   let ddpMessage = {
     id: 'the-id',

types.d.ts

@@ -23,7 +23,7 @@ export type TraceInfo = {
     name: string
 }
 
-export type EventType = 'start' | 'end' | 'email' | 'db' | 'http' | 'fs' | 'compute' | 'custom'
+export type EventType = 'start' | 'end' | 'email' | 'db' | 'http' | 'fs' | 'compute' | 'custom' | 'async' | 'error' | 'wait'
 
 export namespace Tracer {
     function addFilter(filterFunction: (eventType: EventType, data: Record<string, any>, info: TraceInfo) => any): void