From f8cd976349225e16230242cdf6343d3ffdc1bbbc Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Mon, 30 Oct 2023 10:30:18 -0400 Subject: [PATCH 01/17] add async event capture using await detector --- lib/async/als.js | 21 +++++++++- lib/async/async-hook.js | 80 +++++++++++++++++++------------------- lib/hijack/wrap_session.js | 13 ++++++- lib/hijack/wrap_webapp.js | 4 +- lib/tracer/tracer.js | 5 ++- tests/tracer/tracer.js | 56 +++++++++++++++++++++++++- 6 files changed, 133 insertions(+), 46 deletions(-) diff --git a/lib/async/als.js b/lib/async/als.js index 05f40519..fa59f058 100644 --- a/lib/async/als.js +++ b/lib/async/als.js @@ -2,6 +2,7 @@ import fs from 'fs'; import util from 'util'; import { AsyncLocalStorage } from 'node:async_hooks'; import crypto from 'crypto'; +import { awaitDetector } from './async-hook'; export const getId = () => crypto.randomUUID(); @@ -16,7 +17,7 @@ export const runWithALS = ( store.info = info; } - return MontiAsyncStorage.run(store, () => fn.apply(this, args)); + return awaitDetector.detect(() => MontiAsyncStorage.run(store, () => fn.apply(this, args))); }; export const MontiEnvironmentVariable = new AsyncLocalStorage(); @@ -29,6 +30,24 @@ export const getStore = () => MontiAsyncStorage.getStore() ?? {}; export const getInfo = () => MontiAsyncStorage.getStore()?.info; +export const startTrackingAsync = () => { + const info = getInfo(); + + if (!info) return; + + info.trackAsync = true; +}; + +export const incrementIgnoreOffset = (offset = 1) => { + const info = getInfo(); + + if (!info) return; + + if (!info.ignoreOffset) info.ignoreOffset = 0; + + info.ignoreOffset += offset; +}; + export const setActiveEvent = (event, store = MontiAsyncStorage.getStore()) => { if (!store) return; diff --git a/lib/async/async-hook.js b/lib/async/async-hook.js index 45dd2da8..9cc7f64e 100644 --- a/lib/async/async-hook.js +++ b/lib/async/async-hook.js @@ -1,8 +1,10 @@ import asyncHooks from 'async_hooks'; -import { getActiveEvent, getInfo } from './als'; -import { MaxAsyncLevel } from '../constants'; +import { getActiveEvent, getInfo, MontiAsyncStorage } from './als'; +import { EventType, MaxAsyncLevel } from '../constants'; import { Ntp } from '../ntp'; -import { stackTrace } from '../utils'; +import { pick, stackTrace } from '../utils'; +import { AwaitDetector } from '@monti-apm/core/dist/await-detector'; + export const AsyncMetrics = { totalAsyncCount: 0, @@ -29,34 +31,12 @@ export const getResource = (asyncId) => { return resources?.get(asyncId); }; -const captureEnd = (type) => (asyncId) => { - AsyncMetrics.activeAsyncCount--; - - const resource = getResource(asyncId); - - if (!resource) return; - - resource.end = Ntp._now(); - resource.duration = resource.end - resource.start; - resource.hooks = { ...resource.hooks, [type]: true }; -}; - -export const AsyncResourceType = { - PROMISE: 'PROMISE', -}; - -// @todo Keep nested async events for all events, except `db`. -// @todo Generate metrics for nested events as if they are root when nested in `custom` events. -const hook = asyncHooks.createHook({ - init (asyncId, type, triggerAsyncId) { - // We don't want to capture anything other than promise resources. - if (type !== AsyncResourceType.PROMISE) return; - - AsyncMetrics.totalAsyncCount++; - AsyncMetrics.activeAsyncCount++; - +export const awaitDetector = new AwaitDetector({ + onAwaitStart (asyncId, triggerAsyncId) { const info = getInfo(); + if (!info?.trackAsync) return; + const activeEvent = getActiveEvent(); if (activeEvent?.level > MaxAsyncLevel) return; @@ -69,25 +49,29 @@ const hook = asyncHooks.createHook({ const trigger = info.resources.get(triggerAsyncId); - const executionAsyncId = asyncHooks.executionAsyncId(); + const oldStore = MontiAsyncStorage.getStore(); - const executionChanged = trigger?.executionAsyncId !== executionAsyncId; + const executionAsyncId = asyncHooks.executionAsyncId(); const res = { asyncId, triggerAsyncId, executionAsyncId, - type, start: Ntp._now(), end: null, + startTime: Ntp._now(), + endTime: null, + oldStore, activeEvent, - executionChanged, }; if (Kadira.options.enableAsyncStackTraces || process.env.ENABLE_ASYNC_STACK_TRACES) { res.stack = stackTrace(); } + res.event = Kadira.tracer.event(info.trace, EventType.Async, pick(res, ['shouldBeSibling', 'asyncId', 'stack', 'asyncId', 'triggerAsyncId', 'executionAsyncId'])); + MontiAsyncStorage.enterWith(Object.assign({}, oldStore, { activeEvent: res.event })); + info.resources.set(asyncId, res); if (trigger) { @@ -95,13 +79,29 @@ const hook = asyncHooks.createHook({ trigger.children.push(asyncId); } }, - // @todo Perhaps we need to handle rejected promises. - // All promises call `promiseResolve` at the end, except when they are rejected. - promiseResolve: captureEnd('promiseResolve'), -}); + onAwaitEnd (asyncId) { + const resource = getResource(asyncId); + + if (!resource) return; + + + resource.end = Ntp._now(); + resource.duration = resource.end - resource.start; + + console.log({ resource }); -hook.enable(); + const info = getInfo(); + + if (!info) return; + + MontiAsyncStorage.enterWith(resource.oldStore); + + // Some events finish after the trace is already processed. + if (info.trace.isEventsProcessed) return; -process.once('beforeExit', function () { - hook.disable(); + Kadira.tracer.eventEnd(info.trace, resource.event); + } }); + +// @todo Keep nested async events for all events, except `db`. +// @todo Generate metrics for nested events as if they are root when nested in `custom` events. diff --git a/lib/hijack/wrap_session.js b/lib/hijack/wrap_session.js index 5e368fad..288d11cf 100644 --- a/lib/hijack/wrap_session.js +++ b/lib/hijack/wrap_session.js @@ -2,8 +2,9 @@ import { Meteor } from 'meteor/meteor'; import { _ } from 'meteor/underscore'; import { MeteorDebugIgnore } from './error'; import { TimeoutManager } from './timeout_manager'; -import { runWithALS } from '../async/als'; +import { incrementIgnoreOffset, runWithALS, startTrackingAsync } from '../async/als'; import { EventType } from '../constants'; +import util from 'util'; const MAX_PARAMS_LENGTH = 4000; @@ -105,6 +106,10 @@ export function wrapSession (sessionProto) { unblock = Kadira.waitTimeBuilder.trackWaitTime(this, msg, unblock); + startTrackingAsync(); + + incrementIgnoreOffset(2); + response = orginalSubHandler.call(self, msg, unblock); unblock(); } else { @@ -188,6 +193,12 @@ Meteor.methods = function (methodMap) { function wrapMethodHandlerForErrors (name, originalHandler, methodMap) { methodMap[name] = function () { try { + startTrackingAsync(); + + if (util.types.isAsyncFunction(originalHandler)) { + incrementIgnoreOffset(); + } + return originalHandler.apply(this, arguments); } catch (ex) { if (ex && Kadira._getInfo()) { diff --git a/lib/hijack/wrap_webapp.js b/lib/hijack/wrap_webapp.js index 0287715c..de9b7ea0 100644 --- a/lib/hijack/wrap_webapp.js +++ b/lib/hijack/wrap_webapp.js @@ -1,5 +1,5 @@ import { WebApp, WebAppInternals } from 'meteor/webapp'; -import { runWithALS } from '../async/als'; +import { runWithALS, startTrackingAsync } from '../async/als'; import { EventType } from '../constants'; // Maximum content-length size @@ -137,6 +137,8 @@ export async function wrapWebApp () { let potentialPromise; + startTrackingAsync(); + if (errorHandler) { potentialPromise = handler.call(this, error, req, res, next); } else { diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js index c6769302..7f8ccee7 100644 --- a/lib/tracer/tracer.js +++ b/lib/tracer/tracer.js @@ -115,7 +115,6 @@ Tracer.prototype.event = function (trace, type, data, meta) { eventLogger('%s %s', type, trace._id); if (activeEvent) { - event.parentEvent = activeEvent; activeEvent.nested.push(event); return event; } @@ -157,6 +156,10 @@ Tracer.prototype.asyncEvent = function (type, data, meta, fn) { const event = this.event(info.trace, type, data, meta); + if (event) { + event.parentEvent = getActiveEvent(); + } + let callback = () => { try { let result = Reflect.apply(fn, this, [event]); diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js index 6a79a061..38bcc3fe 100644 --- a/tests/tracer/tracer.js +++ b/tests/tracer/tracer.js @@ -1,12 +1,21 @@ import { _ } from 'meteor/underscore'; import { Tracer } from '../../lib/tracer/tracer'; -import { addAsyncTest, callAsync, cleanTrace, getLastMethodEvents, registerMethod } from '../_helpers/helpers'; +import { + addAsyncTest, + callAsync, + cleanTrace, + getLastMethodEvents, + registerMethod, + subscribeAndWait +} from '../_helpers/helpers'; import { sleep } from '../../lib/utils'; import { TestData } from '../_helpers/globals'; +import { getInfo } from '../../lib/async/als'; import { mergeIntervals, subtractIntervals } from '../../lib/utils/time'; -import { diffObjects } from '../_helpers/pretty-log'; +import { diffObjects, prettyLog } from '../_helpers/pretty-log'; import { EventType } from '../../lib/constants'; import { Meteor } from 'meteor/meteor'; +import { Random } from 'meteor/random'; let eventDefaults = { endAt: 0, @@ -522,6 +531,7 @@ addAsyncTest('Tracer - Build Trace - custom with nested parallel events', async let methodId = registerMethod(async function () { let backgroundPromise; + // Compute await sleep(30); await Kadira.event('test', async (event) => { @@ -564,6 +574,48 @@ addAsyncTest('Tracer - Build Trace - custom with nested parallel events', async test.stableEqual(events, expected); }); +addAsyncTest.only('Tracer - Build Trace - the correct number of async events are captured for methods', async (test) => { + let info; + + const methodId = registerMethod(async function () { + await sleep(100); + await sleep(200); + + info = getInfo(); + + return sleep(300); + }); + + await callAsync(methodId); + + const asyncEvents = info.trace.events.filter(([type, duration]) => type === EventType.Async && duration >= 100); + + prettyLog(info.trace.events); + + test.equal(asyncEvents.length, 3); +}); + +addAsyncTest('Tracer - Build Trace - the correct number of async events are captured for pubsub', async (test, client) => { + const subName = `sub_${Random.id()}`; + + let info; + + Meteor.publish(subName, async function () { + await sleep(100); + + info = getInfo(); + + return []; + }); + + await subscribeAndWait(client, subName); + + prettyLog(info.trace.events); + + const asyncEvents = info.trace.events.filter(([type, duration]) => type === EventType.Async && duration >= 100); + + test.equal(asyncEvents.length,1); +}); addAsyncTest('Tracer - Time - Subtract Intervals', async function (test) { function testSubtractIntervals (arr1, arr2, expected) { From 1929a29bac74dd4800914e96a0453ba6bb608d81 Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Tue, 31 Oct 2023 10:21:31 -0400 Subject: [PATCH 02/17] push wip --- lib/async/als.js | 27 +-------------------------- lib/async/async-hook.js | 12 ++++++------ lib/hijack/wrap_session.js | 20 ++++---------------- lib/hijack/wrap_webapp.js | 4 +--- lib/tracer/tracer.js | 7 ++++--- package.js | 2 +- tests/tracer/tracer.js | 2 +- 7 files changed, 18 insertions(+), 56 deletions(-) diff --git a/lib/async/als.js b/lib/async/als.js index fa59f058..f67bebfb 100644 --- a/lib/async/als.js +++ b/lib/async/als.js @@ -2,7 +2,6 @@ import fs from 'fs'; import util from 'util'; import { AsyncLocalStorage } from 'node:async_hooks'; import crypto from 'crypto'; -import { awaitDetector } from './async-hook'; export const getId = () => crypto.randomUUID(); @@ -17,7 +16,7 @@ export const runWithALS = ( store.info = info; } - return awaitDetector.detect(() => MontiAsyncStorage.run(store, () => fn.apply(this, args))); + return MontiAsyncStorage.run(store, () => fn.apply(this, args)); }; export const MontiEnvironmentVariable = new AsyncLocalStorage(); @@ -30,30 +29,6 @@ export const getStore = () => MontiAsyncStorage.getStore() ?? {}; export const getInfo = () => MontiAsyncStorage.getStore()?.info; -export const startTrackingAsync = () => { - const info = getInfo(); - - if (!info) return; - - info.trackAsync = true; -}; - -export const incrementIgnoreOffset = (offset = 1) => { - const info = getInfo(); - - if (!info) return; - - if (!info.ignoreOffset) info.ignoreOffset = 0; - - info.ignoreOffset += offset; -}; - -export const setActiveEvent = (event, store = MontiAsyncStorage.getStore()) => { - if (!store) return; - - MontiAsyncStorage.enterWith({ ...store, activeEvent: event }); -}; - export const getActiveEvent = (store = MontiAsyncStorage.getStore()) => store?.activeEvent; export const debug = label => (...args) => { diff --git a/lib/async/async-hook.js b/lib/async/async-hook.js index 9cc7f64e..be5b0a73 100644 --- a/lib/async/async-hook.js +++ b/lib/async/async-hook.js @@ -32,11 +32,10 @@ export const getResource = (asyncId) => { }; export const awaitDetector = new AwaitDetector({ + logging: true, onAwaitStart (asyncId, triggerAsyncId) { const info = getInfo(); - if (!info?.trackAsync) return; - const activeEvent = getActiveEvent(); if (activeEvent?.level > MaxAsyncLevel) return; @@ -45,6 +44,8 @@ export const awaitDetector = new AwaitDetector({ if (!trace) return; + console.log('start', asyncId); + info.resources = info.resources || new Map(); const trigger = info.resources.get(triggerAsyncId); @@ -69,7 +70,7 @@ export const awaitDetector = new AwaitDetector({ res.stack = stackTrace(); } - res.event = Kadira.tracer.event(info.trace, EventType.Async, pick(res, ['shouldBeSibling', 'asyncId', 'stack', 'asyncId', 'triggerAsyncId', 'executionAsyncId'])); + res.event = Kadira.tracer.event(info.trace, EventType.Async, pick(res, ['asyncId', 'stack', 'asyncId', 'triggerAsyncId', 'executionAsyncId'])); MontiAsyncStorage.enterWith(Object.assign({}, oldStore, { activeEvent: res.event })); info.resources.set(asyncId, res); @@ -82,14 +83,13 @@ export const awaitDetector = new AwaitDetector({ onAwaitEnd (asyncId) { const resource = getResource(asyncId); - if (!resource) return; + console.log('end', asyncId, !!resource); + if (!resource) return; resource.end = Ntp._now(); resource.duration = resource.end - resource.start; - console.log({ resource }); - const info = getInfo(); if (!info) return; diff --git a/lib/hijack/wrap_session.js b/lib/hijack/wrap_session.js index 288d11cf..b787beca 100644 --- a/lib/hijack/wrap_session.js +++ b/lib/hijack/wrap_session.js @@ -2,9 +2,9 @@ import { Meteor } from 'meteor/meteor'; import { _ } from 'meteor/underscore'; import { MeteorDebugIgnore } from './error'; import { TimeoutManager } from './timeout_manager'; -import { incrementIgnoreOffset, runWithALS, startTrackingAsync } from '../async/als'; +import { runWithALS } from '../async/als'; import { EventType } from '../constants'; -import util from 'util'; +import { awaitDetector } from '../async/async-hook'; const MAX_PARAMS_LENGTH = 4000; @@ -72,10 +72,7 @@ export function wrapSession (sessionProto) { unblock = Kadira.waitTimeBuilder.trackWaitTime(this, msg, unblock); - - const promise = originalMethodHandler.call(self, msg, unblock); - - response = await promise; + response = await awaitDetector.detect(() => originalMethodHandler.call(self, msg, unblock)); unblock(); } else { @@ -106,10 +103,6 @@ export function wrapSession (sessionProto) { unblock = Kadira.waitTimeBuilder.trackWaitTime(this, msg, unblock); - startTrackingAsync(); - - incrementIgnoreOffset(2); - response = orginalSubHandler.call(self, msg, unblock); unblock(); } else { @@ -160,6 +153,7 @@ export function wrapSession (sessionProto) { } // processing the message + console.log('Processing message', msg); let trace = Kadira.tracer.buildTrace(kadiraInfo.trace); Kadira.EventBus.emit('method', 'methodCompleted', trace, this); Kadira.models.methods.processMethod(trace); @@ -193,12 +187,6 @@ Meteor.methods = function (methodMap) { function wrapMethodHandlerForErrors (name, originalHandler, methodMap) { methodMap[name] = function () { try { - startTrackingAsync(); - - if (util.types.isAsyncFunction(originalHandler)) { - incrementIgnoreOffset(); - } - return originalHandler.apply(this, arguments); } catch (ex) { if (ex && Kadira._getInfo()) { diff --git a/lib/hijack/wrap_webapp.js b/lib/hijack/wrap_webapp.js index de9b7ea0..0287715c 100644 --- a/lib/hijack/wrap_webapp.js +++ b/lib/hijack/wrap_webapp.js @@ -1,5 +1,5 @@ import { WebApp, WebAppInternals } from 'meteor/webapp'; -import { runWithALS, startTrackingAsync } from '../async/als'; +import { runWithALS } from '../async/als'; import { EventType } from '../constants'; // Maximum content-length size @@ -137,8 +137,6 @@ export async function wrapWebApp () { let potentialPromise; - startTrackingAsync(); - if (errorHandler) { potentialPromise = handler.call(this, error, req, res, next); } else { diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js index 7f8ccee7..cc3ed0ac 100644 --- a/lib/tracer/tracer.js +++ b/lib/tracer/tracer.js @@ -354,13 +354,14 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) { if (![EventType.Complete, EventType.Start].includes(type)) { setEventDuration(objectEvent); - const {duration} = objectEvent; - if (!endAt) { - endAt = at; + endAt = Ntp._now(); + objectEvent.duration = endAt - at; extraInfo.forcedEnd = true; } + const {duration} = objectEvent; + // We need this info as events are not always in order or in series. extraInfo.at = at; extraInfo.endAt = endAt; diff --git a/package.js b/package.js index 88eed798..ac8e9dd0 100644 --- a/package.js +++ b/package.js @@ -9,7 +9,7 @@ Package.describe({ let npmModules = { debug: '0.8.1', - '@monti-apm/core': '2.0.0-beta.1', + '@monti-apm/core': 'file:///Users/leonardo/Repositories/monti-apm/monti-apm-core', 'lru-cache': '5.1.1', 'json-stringify-safe': '5.0.1', 'monti-apm-sketches-js': '0.0.3', diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js index 38bcc3fe..ec87bc97 100644 --- a/tests/tracer/tracer.js +++ b/tests/tracer/tracer.js @@ -583,7 +583,7 @@ addAsyncTest.only('Tracer - Build Trace - the correct number of async events are info = getInfo(); - return sleep(300); + return await sleep(300); }); await callAsync(methodId); From c4a6016a95fc7c3176ead4008e9d6afe977224c3 Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Tue, 31 Oct 2023 10:22:26 -0400 Subject: [PATCH 03/17] not this one --- package.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/package.js b/package.js index ac8e9dd0..88eed798 100644 --- a/package.js +++ b/package.js @@ -9,7 +9,7 @@ Package.describe({ let npmModules = { debug: '0.8.1', - '@monti-apm/core': 'file:///Users/leonardo/Repositories/monti-apm/monti-apm-core', + '@monti-apm/core': '2.0.0-beta.1', 'lru-cache': '5.1.1', 'json-stringify-safe': '5.0.1', 'monti-apm-sketches-js': '0.0.3', From 57a8b5544e911062eeb309debea5af037810eaa2 Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Thu, 2 Nov 2023 10:12:07 -0400 Subject: [PATCH 04/17] fix endAt test --- tests/tracer/tracer.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js index ec87bc97..f4831e1e 100644 --- a/tests/tracer/tracer.js +++ b/tests/tracer/tracer.js @@ -368,7 +368,7 @@ addAsyncTest( const expected = [ ['start'], - ['wait', 0, null, { at: 0, endAt: 0, forcedEnd: true }], + ['wait', traceInfo.events[1][1], null, { at: 0, endAt: traceInfo.events[1][3].endAt, forcedEnd: true }], ['db', 500, null, { at: 2000, endAt: 2500}], ['complete'] ]; @@ -574,7 +574,7 @@ addAsyncTest('Tracer - Build Trace - custom with nested parallel events', async test.stableEqual(events, expected); }); -addAsyncTest.only('Tracer - Build Trace - the correct number of async events are captured for methods', async (test) => { +addAsyncTest('Tracer - Build Trace - the correct number of async events are captured for methods', async (test) => { let info; const methodId = registerMethod(async function () { From fcf1f67d50c832615f212734448a99077752ffba Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Thu, 2 Nov 2023 10:12:33 -0400 Subject: [PATCH 05/17] fix undefined error --- lib/tracer/tracer.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js index cc3ed0ac..e3ff5228 100644 --- a/lib/tracer/tracer.js +++ b/lib/tracer/tracer.js @@ -373,7 +373,7 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) { extraInfo.stack = objectEvent.stack; } - if (duration > 0) { + if (metrics && duration > 0) { const isAsyncAndRootOrOther = type === EventType.Async && level === 0 || type !== EventType.Async; if (isAsyncAndRootOrOther) { From 851dddde912abaf9af48b75a1e75e1db0af8c320 Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Thu, 2 Nov 2023 15:50:19 -0400 Subject: [PATCH 06/17] add proxy interceptor --- lib/hijack/wrap_session.js | 40 ++++++++++++++++++++++++++++++++++---- 1 file changed, 36 insertions(+), 4 deletions(-) diff --git a/lib/hijack/wrap_session.js b/lib/hijack/wrap_session.js index b787beca..652b7fc0 100644 --- a/lib/hijack/wrap_session.js +++ b/lib/hijack/wrap_session.js @@ -72,7 +72,7 @@ export function wrapSession (sessionProto) { unblock = Kadira.waitTimeBuilder.trackWaitTime(this, msg, unblock); - response = await awaitDetector.detect(() => originalMethodHandler.call(self, msg, unblock)); + response = await originalMethodHandler.call(self, msg, unblock); unblock(); } else { @@ -84,7 +84,7 @@ export function wrapSession (sessionProto) { // to capture the currently processing message let orginalSubHandler = sessionProto.protocol_handlers.sub; - sessionProto.protocol_handlers.sub = runWithALS(function (msg, unblock) { + sessionProto.protocol_handlers.sub = runWithALS(async function (msg, unblock) { let self = this; // add context let kadiraInfo = msg.__kadiraInfo; @@ -99,14 +99,16 @@ export function wrapSession (sessionProto) { // end wait event let waitList = Kadira.waitTimeBuilder.build(this, msg.id); + Kadira.tracer.eventEnd(kadiraInfo.trace, msg._waitEventId, {waitOn: waitList}); unblock = Kadira.waitTimeBuilder.trackWaitTime(this, msg, unblock); - response = orginalSubHandler.call(self, msg, unblock); + response = await orginalSubHandler.call(self, msg, unblock); + unblock(); } else { - response = orginalSubHandler.call(self, msg, unblock); + response = await orginalSubHandler.call(self, msg, unblock); } return response; @@ -169,6 +171,36 @@ export function wrapSession (sessionProto) { }; } +// eslint-disable-next-line camelcase +Meteor.server.method_handlers = new Proxy(Meteor.server.method_handlers, { + get (target, propKey) { + const origMethod = target[propKey]; + + if (typeof origMethod !== 'function') { + return origMethod; + } + + return function (...args) { + return awaitDetector.detect(() => origMethod.apply(this, args)); + }; + } +}); + +// eslint-disable-next-line camelcase +Meteor.server.publish_handlers = new Proxy(Meteor.server.publish_handlers, { + get (target, propKey) { + const origMethod = target[propKey]; + + if (typeof origMethod !== 'function') { + return origMethod; + } + + return function (...args) { + return awaitDetector.detect(() => origMethod.apply(this, args)); + }; + } +}); + // wrap existing method handlers for capturing errors _.each(Meteor.server.method_handlers, function (handler, name) { wrapMethodHandlerForErrors(name, handler, Meteor.server.method_handlers); From 47cae27c333a407d95f1c22e1a64f6989646dbe1 Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Thu, 2 Nov 2023 15:50:44 -0400 Subject: [PATCH 07/17] wrap bind environment to ignore async events from it --- lib/async/als.js | 10 ++++++++++ lib/async/async-hook.js | 18 +++++------------- 2 files changed, 15 insertions(+), 13 deletions(-) diff --git a/lib/async/als.js b/lib/async/als.js index f67bebfb..888b6134 100644 --- a/lib/async/als.js +++ b/lib/async/als.js @@ -6,6 +6,16 @@ import crypto from 'crypto'; export const getId = () => crypto.randomUUID(); export const MontiAsyncStorage = new AsyncLocalStorage(); +export const MontiAsyncIgnoreStorage = new AsyncLocalStorage(); + +const oldBindEnv = Meteor.bindEnvironment; + +Meteor.bindEnvironment = function (...args) { + const func = oldBindEnv.apply(this, args); + return function () { + return MontiAsyncIgnoreStorage.run(true, () => func.apply(this, arguments)); + }; +}; export const runWithALS = ( fn, diff --git a/lib/async/async-hook.js b/lib/async/async-hook.js index be5b0a73..090eb6dd 100644 --- a/lib/async/async-hook.js +++ b/lib/async/async-hook.js @@ -1,5 +1,5 @@ import asyncHooks from 'async_hooks'; -import { getActiveEvent, getInfo, MontiAsyncStorage } from './als'; +import { getActiveEvent, getInfo, MontiAsyncIgnoreStorage } from './als'; import { EventType, MaxAsyncLevel } from '../constants'; import { Ntp } from '../ntp'; import { pick, stackTrace } from '../utils'; @@ -32,10 +32,13 @@ export const getResource = (asyncId) => { }; export const awaitDetector = new AwaitDetector({ - logging: true, onAwaitStart (asyncId, triggerAsyncId) { const info = getInfo(); + if (!info) return; + + if (MontiAsyncIgnoreStorage.getStore()) return; + const activeEvent = getActiveEvent(); if (activeEvent?.level > MaxAsyncLevel) return; @@ -44,14 +47,10 @@ export const awaitDetector = new AwaitDetector({ if (!trace) return; - console.log('start', asyncId); - info.resources = info.resources || new Map(); const trigger = info.resources.get(triggerAsyncId); - const oldStore = MontiAsyncStorage.getStore(); - const executionAsyncId = asyncHooks.executionAsyncId(); const res = { @@ -62,7 +61,6 @@ export const awaitDetector = new AwaitDetector({ end: null, startTime: Ntp._now(), endTime: null, - oldStore, activeEvent, }; @@ -71,8 +69,6 @@ export const awaitDetector = new AwaitDetector({ } res.event = Kadira.tracer.event(info.trace, EventType.Async, pick(res, ['asyncId', 'stack', 'asyncId', 'triggerAsyncId', 'executionAsyncId'])); - MontiAsyncStorage.enterWith(Object.assign({}, oldStore, { activeEvent: res.event })); - info.resources.set(asyncId, res); if (trigger) { @@ -83,8 +79,6 @@ export const awaitDetector = new AwaitDetector({ onAwaitEnd (asyncId) { const resource = getResource(asyncId); - console.log('end', asyncId, !!resource); - if (!resource) return; resource.end = Ntp._now(); @@ -94,8 +88,6 @@ export const awaitDetector = new AwaitDetector({ if (!info) return; - MontiAsyncStorage.enterWith(resource.oldStore); - // Some events finish after the trace is already processed. if (info.trace.isEventsProcessed) return; From d5ec7460de96ac9959f89eb6495557c17928ee0a Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Thu, 2 Nov 2023 15:52:49 -0400 Subject: [PATCH 08/17] remove log --- lib/hijack/wrap_session.js | 1 - 1 file changed, 1 deletion(-) diff --git a/lib/hijack/wrap_session.js b/lib/hijack/wrap_session.js index 652b7fc0..9d114ccf 100644 --- a/lib/hijack/wrap_session.js +++ b/lib/hijack/wrap_session.js @@ -155,7 +155,6 @@ export function wrapSession (sessionProto) { } // processing the message - console.log('Processing message', msg); let trace = Kadira.tracer.buildTrace(kadiraInfo.trace); Kadira.EventBus.emit('method', 'methodCompleted', trace, this); Kadira.models.methods.processMethod(trace); From 44359a305d2dc9abb7dc0b2c7621f204b5b526a8 Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Thu, 2 Nov 2023 15:54:08 -0400 Subject: [PATCH 09/17] we are not nesting for now --- lib/async/async-hook.js | 3 --- 1 file changed, 3 deletions(-) diff --git a/lib/async/async-hook.js b/lib/async/async-hook.js index 090eb6dd..b27ab3da 100644 --- a/lib/async/async-hook.js +++ b/lib/async/async-hook.js @@ -94,6 +94,3 @@ export const awaitDetector = new AwaitDetector({ Kadira.tracer.eventEnd(info.trace, resource.event); } }); - -// @todo Keep nested async events for all events, except `db`. -// @todo Generate metrics for nested events as if they are root when nested in `custom` events. From e8a6bce12c92e0473035080caf6902bb230e706c Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Mon, 6 Nov 2023 07:44:28 -0400 Subject: [PATCH 10/17] revert gh workflow changes --- .github/workflows/test.yml | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 2ef36fba..b2aa177d 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -12,7 +12,8 @@ jobs: fail-fast: false matrix: meteorRelease: - - 3.0-alpha.16 + # Meteor 3 Alpha + - '--release 3.0-alpha.16' steps: - name: Checkout code uses: actions/checkout@v2 @@ -25,12 +26,11 @@ jobs: - name: Install Dependencies run: | curl https://install.meteor.com | /bin/sh + npm i -g @zodern/mtest - name: Run Tests run: | # Fix using old versions of Meteor - export NODE_TLS_REJECT_UNAUTHORIZED=0 - export NODE_OPTIONS="--trace-warnings --trace-uncaught" - export FORCE_COLOR=true + export NODE_TLS_REJECT_UNAUTHORIZED=0 - meteor test-packages ./ --raw-logs --exclude-archs="web.browser.legacy,web.cordova" --driver-package=test-in-console --release=${{ matrix.meteorRelease }} + mtest --package ./ --once ${{ matrix.meteorRelease }} From 4c88ab8e7b857dd1bf0ceff2e18a0ad7b5921317 Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Mon, 6 Nov 2023 18:00:16 -0400 Subject: [PATCH 11/17] no need in using resources for calculating async and compute metrics --- lib/async/async-hook.js | 17 ----------------- lib/tracer/tracer.js | 7 +++---- 2 files changed, 3 insertions(+), 21 deletions(-) diff --git a/lib/async/async-hook.js b/lib/async/async-hook.js index b27ab3da..f68edc9f 100644 --- a/lib/async/async-hook.js +++ b/lib/async/async-hook.js @@ -17,12 +17,6 @@ export function getResources () { return info?.resources; } -export function getResourcesAsArray () { - const resources = getResources(); - - return resources ? Array.from(resources.values()) : []; -} - export const getResource = (asyncId) => { if (!asyncId) return; @@ -49,8 +43,6 @@ export const awaitDetector = new AwaitDetector({ info.resources = info.resources || new Map(); - const trigger = info.resources.get(triggerAsyncId); - const executionAsyncId = asyncHooks.executionAsyncId(); const res = { @@ -69,21 +61,12 @@ export const awaitDetector = new AwaitDetector({ } res.event = Kadira.tracer.event(info.trace, EventType.Async, pick(res, ['asyncId', 'stack', 'asyncId', 'triggerAsyncId', 'executionAsyncId'])); - info.resources.set(asyncId, res); - - if (trigger) { - trigger.children = trigger.children || []; - trigger.children.push(asyncId); - } }, onAwaitEnd (asyncId) { const resource = getResource(asyncId); if (!resource) return; - resource.end = Ntp._now(); - resource.duration = resource.end - resource.start; - const info = getInfo(); if (!info) return; diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js index e3ff5228..74d86461 100644 --- a/lib/tracer/tracer.js +++ b/lib/tracer/tracer.js @@ -7,7 +7,6 @@ import { getTotalDuration, mergeIntervals, setEventDuration, subtractIntervals } import { getActiveEvent, getInfo, getStore, MontiAsyncStorage } from '../async/als'; import { executionAsyncId, triggerAsyncId } from 'async_hooks'; import util from 'util'; -import { getResourcesAsArray } from '../async/async-hook'; let eventLogger = require('debug')('kadira:tracer'); @@ -284,9 +283,9 @@ Tracer.prototype.buildTrace = function (traceInfo) { traceInfo.at = firstEvent.at; traceInfo.endAt = lastEvent.endAt || lastEvent.at; - const resources = getResourcesAsArray(); - - const asyncIntervals = resources.map(({ start, end }) => [start, end ?? traceInfo.endAt]); + const asyncIntervals = traceInfo.events + .filter(({ type }) => type === EventType.Async) + .map(({ at, end }) => [at, end ?? traceInfo.endAt]); let metrics = { total: traceInfo.endAt - firstEvent.at, From 51ee531c3496d24b3719f741f7cc5f43794115ed Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Tue, 7 Nov 2023 09:33:10 -0400 Subject: [PATCH 12/17] remove logs --- lib/kadira.js | 2 -- tests/_helpers/helpers.js | 1 - tests/hijack/db.js | 3 --- tests/tracer/tracer.js | 7 ------- 4 files changed, 13 deletions(-) diff --git a/lib/kadira.js b/lib/kadira.js index bd84170e..df6d0db1 100644 --- a/lib/kadira.js +++ b/lib/kadira.js @@ -329,8 +329,6 @@ Kadira._sendPayload = function () { // WARNNING: returned info object is the reference object. // Changing it might cause issues when building traces. So use with care Kadira._getInfo = function () { - // prettyLog(`Getting Info ${new Error().stack.split('\n')[2]?.trim()}`, MontiAsyncStorage.getStore()); - return MontiAsyncStorage.getStore()?.info; }; diff --git a/tests/_helpers/helpers.js b/tests/_helpers/helpers.js index b1aa4162..dda6a74e 100644 --- a/tests/_helpers/helpers.js +++ b/tests/_helpers/helpers.js @@ -214,7 +214,6 @@ export const closeClient = function (client) { let sessionId = client._lastSessionId; Object.entries(client._subscriptions).forEach(([subId, sub]) => { - console.log('closing sub', subId); sub?.stop(); }); diff --git a/tests/hijack/db.js b/tests/hijack/db.js index a500bbfb..7b48a8b5 100644 --- a/tests/hijack/db.js +++ b/tests/hijack/db.js @@ -8,7 +8,6 @@ import { RegisterMethod } from '../_helpers/helpers'; import assert from 'assert'; -import { diffObjects } from '../_helpers/pretty-log'; addAsyncTest( 'Database - insert', @@ -26,8 +25,6 @@ addAsyncTest( let expected = [['start',{userId: null,params: '[]'}],['wait',{waitOn: []},{at: 1,endAt: 1}],['db',{coll: 'tinytest-data',func: 'insertAsync'},{at: 1,endAt: 1}],['complete']]; - diffObjects(events, expected); - test.stableEqual(events, expected); } ); diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js index f4831e1e..f4bba114 100644 --- a/tests/tracer/tracer.js +++ b/tests/tracer/tracer.js @@ -12,7 +12,6 @@ import { sleep } from '../../lib/utils'; import { TestData } from '../_helpers/globals'; import { getInfo } from '../../lib/async/als'; import { mergeIntervals, subtractIntervals } from '../../lib/utils/time'; -import { diffObjects, prettyLog } from '../_helpers/pretty-log'; import { EventType } from '../../lib/constants'; import { Meteor } from 'meteor/meteor'; import { Random } from 'meteor/random'; @@ -51,8 +50,6 @@ addAsyncTest( ] }; - diffObjects(traceInfo, expected); - test.equal(traceInfo, expected); } ); @@ -590,8 +587,6 @@ addAsyncTest('Tracer - Build Trace - the correct number of async events are capt const asyncEvents = info.trace.events.filter(([type, duration]) => type === EventType.Async && duration >= 100); - prettyLog(info.trace.events); - test.equal(asyncEvents.length, 3); }); @@ -610,8 +605,6 @@ addAsyncTest('Tracer - Build Trace - the correct number of async events are capt await subscribeAndWait(client, subName); - prettyLog(info.trace.events); - const asyncEvents = info.trace.events.filter(([type, duration]) => type === EventType.Async && duration >= 100); test.equal(asyncEvents.length,1); From ab37fdbc07bb403842e12b1d03602c9cebf79ea8 Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Wed, 8 Nov 2023 13:04:58 -0400 Subject: [PATCH 13/17] use detector ignore --- lib/async/als.js | 10 ---------- lib/async/async-hook.js | 13 ++++++++++--- 2 files changed, 10 insertions(+), 13 deletions(-) diff --git a/lib/async/als.js b/lib/async/als.js index 888b6134..f67bebfb 100644 --- a/lib/async/als.js +++ b/lib/async/als.js @@ -6,16 +6,6 @@ import crypto from 'crypto'; export const getId = () => crypto.randomUUID(); export const MontiAsyncStorage = new AsyncLocalStorage(); -export const MontiAsyncIgnoreStorage = new AsyncLocalStorage(); - -const oldBindEnv = Meteor.bindEnvironment; - -Meteor.bindEnvironment = function (...args) { - const func = oldBindEnv.apply(this, args); - return function () { - return MontiAsyncIgnoreStorage.run(true, () => func.apply(this, arguments)); - }; -}; export const runWithALS = ( fn, diff --git a/lib/async/async-hook.js b/lib/async/async-hook.js index f68edc9f..8ee5d673 100644 --- a/lib/async/async-hook.js +++ b/lib/async/async-hook.js @@ -1,5 +1,5 @@ import asyncHooks from 'async_hooks'; -import { getActiveEvent, getInfo, MontiAsyncIgnoreStorage } from './als'; +import { getActiveEvent, getInfo } from './als'; import { EventType, MaxAsyncLevel } from '../constants'; import { Ntp } from '../ntp'; import { pick, stackTrace } from '../utils'; @@ -31,8 +31,6 @@ export const awaitDetector = new AwaitDetector({ if (!info) return; - if (MontiAsyncIgnoreStorage.getStore()) return; - const activeEvent = getActiveEvent(); if (activeEvent?.level > MaxAsyncLevel) return; @@ -77,3 +75,12 @@ export const awaitDetector = new AwaitDetector({ Kadira.tracer.eventEnd(info.trace, resource.event); } }); + +const oldBindEnv = Meteor.bindEnvironment; + +Meteor.bindEnvironment = function (...args) { + const func = oldBindEnv.apply(this, args); + return function () { + return awaitDetector.ignore(() => func.apply(this, arguments)); + }; +}; From 29e6ca90d1b63b8f4fab2e7682031b2b2d1b5a7f Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Wed, 8 Nov 2023 14:03:23 -0400 Subject: [PATCH 14/17] fix lint --- tests/_helpers/helpers.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/_helpers/helpers.js b/tests/_helpers/helpers.js index dda6a74e..c8438186 100644 --- a/tests/_helpers/helpers.js +++ b/tests/_helpers/helpers.js @@ -213,7 +213,7 @@ export const closeClient = function (client) { return new Promise((resolve) => { let sessionId = client._lastSessionId; - Object.entries(client._subscriptions).forEach(([subId, sub]) => { + Object.entries(client._subscriptions).forEach(([, sub]) => { sub?.stop(); }); From a35245520b25b7edf6a2ba9d2b2536ba6a079d9d Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Wed, 8 Nov 2023 15:48:44 -0400 Subject: [PATCH 15/17] add comment --- lib/async/async-hook.js | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/lib/async/async-hook.js b/lib/async/async-hook.js index 8ee5d673..1b5d074a 100644 --- a/lib/async/async-hook.js +++ b/lib/async/async-hook.js @@ -78,6 +78,12 @@ export const awaitDetector = new AwaitDetector({ const oldBindEnv = Meteor.bindEnvironment; +/** + * We ignore `bindEnvironment` awaits because they pollute the traces with Meteor internals. + * + * To reproduce, go to the test "Tracer - Build Trace - the correct number of async events are captured for methods" + * and remove the awaitDetector.ignore() call below to see the difference. + */ Meteor.bindEnvironment = function (...args) { const func = oldBindEnv.apply(this, args); return function () { From 24e90bd9c77fc8407e11d08166612b53f2e3f313 Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Thu, 9 Nov 2023 15:23:38 -0400 Subject: [PATCH 16/17] simplify compute and async metric calculation --- lib/tracer/tracer.js | 73 ++++++++-------------------------- lib/utils/time.js | 80 ------------------------------------- tests/models/methods.js | 24 +++++------ tests/tracer/tracer.js | 88 +---------------------------------------- 4 files changed, 31 insertions(+), 234 deletions(-) delete mode 100644 lib/utils/time.js diff --git a/lib/tracer/tracer.js b/lib/tracer/tracer.js index 74d86461..51ad7671 100644 --- a/lib/tracer/tracer.js +++ b/lib/tracer/tracer.js @@ -3,7 +3,6 @@ import { objectHasData } from '../common/utils'; import { cleanTrailingNilValues, CreateUserStack, DefaultUniqueId, last, pick } from '../utils'; import { Ntp } from '../ntp'; import { EventType, MaxAsyncLevel } from '../constants'; -import { getTotalDuration, mergeIntervals, setEventDuration, subtractIntervals } from '../utils/time'; import { getActiveEvent, getInfo, getStore, MontiAsyncStorage } from '../async/als'; import { executionAsyncId, triggerAsyncId } from 'async_hooks'; import util from 'util'; @@ -250,23 +249,13 @@ Tracer.prototype._hasUsefulNested = function (event) { !event.nested.every(e => e.type === 'async'); }; -Tracer.prototype.calculateAsync = function (traceInfo, metrics) { - const withoutWork = subtractIntervals(metrics.asyncIntervalsMerged, metrics.workIntervalsMerged); - - return getTotalDuration(withoutWork); -}; - -Tracer.prototype.calculateCompute = function (traceInfo, metrics) { - const total = [[traceInfo.at, traceInfo.endAt]]; - - const withoutWork = subtractIntervals(total, metrics.workIntervalsMerged); - - const withoutAsync = subtractIntervals(withoutWork, metrics.asyncIntervalsMerged); - - return getTotalDuration(withoutAsync); -}; - Tracer.prototype.buildTrace = function (traceInfo) { + let metrics = { + compute: 0, + async: 0, + totalNonCompute: 0, + }; + let firstEvent = traceInfo.events[0]; let lastEvent = last(traceInfo.events); @@ -278,38 +267,18 @@ Tracer.prototype.buildTrace = function (traceInfo) { return null; } + const processedEvents = this.optimizeEvents(traceInfo.events, metrics); + // build the metrics traceInfo.errored = lastEvent.type === EventType.Error; traceInfo.at = firstEvent.at; traceInfo.endAt = lastEvent.endAt || lastEvent.at; - const asyncIntervals = traceInfo.events - .filter(({ type }) => type === EventType.Async) - .map(({ at, end }) => [at, end ?? traceInfo.endAt]); - - let metrics = { - total: traceInfo.endAt - firstEvent.at, - compute: 0, - async: 0, - workIntervals: [], - asyncIntervals, - workIntervalsMerged: [], - asyncIntervalsMerged: [], - }; - - const processedEvents = this.optimizeEvents(traceInfo.events, metrics); - - metrics.workIntervalsMerged = mergeIntervals(metrics.workIntervals); - metrics.asyncIntervalsMerged = mergeIntervals(metrics.asyncIntervals); - - metrics.async = this.calculateAsync(traceInfo, metrics); - metrics.compute = this.calculateCompute(traceInfo, metrics); + metrics.total = traceInfo.endAt - firstEvent.at; + metrics.compute = metrics.total - metrics.totalNonCompute; // Remove temporary fields - delete metrics.workIntervals; - delete metrics.workIntervalsMerged; - delete metrics.asyncIntervals; - delete metrics.asyncIntervalsMerged; + delete metrics.totalNonCompute; traceInfo.metrics = metrics; traceInfo.events = processedEvents; @@ -351,14 +320,13 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) { }; if (![EventType.Complete, EventType.Start].includes(type)) { - setEventDuration(objectEvent); - if (!endAt) { endAt = Ntp._now(); - objectEvent.duration = endAt - at; extraInfo.forcedEnd = true; } + objectEvent.duration = endAt - at; + const {duration} = objectEvent; // We need this info as events are not always in order or in series. @@ -372,17 +340,10 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) { extraInfo.stack = objectEvent.stack; } - if (metrics && duration > 0) { - const isAsyncAndRootOrOther = type === EventType.Async && level === 0 || type !== EventType.Async; - - if (isAsyncAndRootOrOther) { - metrics[type] = metrics[type] || 0; - metrics[type] += duration; - } - - if (level === 0) { - metrics.workIntervals.push([at, endAt]); - } + 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/lib/utils/time.js b/lib/utils/time.js deleted file mode 100644 index a4029f73..00000000 --- a/lib/utils/time.js +++ /dev/null @@ -1,80 +0,0 @@ -import { isNumber } from '../common/utils'; - -export function mergeIntervals (intervals) { - if (!intervals?.length) return intervals; - - intervals.sort((a, b) => a[0] - b[0]); - - const mergedIntervals = []; - let currentInterval = intervals[0]; - - for (let i = 1; i < intervals.length; i++) { - const interval = intervals[i]; - - if (currentInterval[1] >= interval[0]) { - currentInterval[1] = Math.max(currentInterval[1], interval[1]); - } else { - mergedIntervals.push(currentInterval); - currentInterval = interval; - } - } - - mergedIntervals.push(currentInterval); - - return mergedIntervals; -} - - -/** - * Subtract intervals from `arr1` by intervals from `arr2.` - * - * @param arr1 - * @param arr2 - * @returns {*[]} - */ -export function subtractIntervals (arr1, arr2) { - arr1.sort((a, b) => a[0] - b[0]); - arr2.sort((a, b) => a[0] - b[0]); - - let result = []; - let j = 0; - - for (let i = 0; i < arr1.length; i++) { - let [start1, end1] = arr1[i]; - while (j < arr2.length) { - let [start2, end2] = arr2[j]; - if (end2 < start1) { - j++; - } else if (start2 > end1) { - break; - } else { - if (start2 > start1) { - result.push([start1, start2]); - } - start1 = end2; - if (start1 >= end1) { - break; - } - j++; - } - } - if (j >= arr2.length && start1 < end1) { - result.push([start1, end1]); - } - } - return result; -} - -export function getTotalDuration (arr) { - return arr.reduce((acc, [start, end]) => acc + (end - start), 0); -} - -export function setEventDuration (event) { - if (isNumber(event.duration)) { - return; - } - - const {at, endAt} = event; - - event.duration = isNumber(at) && isNumber(endAt) ? endAt - at : 0; -} diff --git a/tests/models/methods.js b/tests/models/methods.js index 583ce754..a3f05c58 100644 --- a/tests/models/methods.js +++ b/tests/models/methods.js @@ -1,8 +1,8 @@ -import { EJSON } from 'meteor/ejson'; import { MethodsModel } from '../../lib/models/methods'; import { TestData } from '../_helpers/globals'; import { addAsyncTest, callAsync, clientCallAsync, registerMethod, withDocCacheGetSize } from '../_helpers/helpers'; import { sleep } from '../../lib/utils'; +import { Ntp } from '../../lib/ntp'; addAsyncTest( 'Models - Method - buildPayload simple', @@ -48,11 +48,9 @@ addAsyncTest( methodRequests: [] }; - let startTime = expected.methodMetrics[0].startTime; - expected.methodMetrics[0].startTime = Kadira.syncedDate.syncTime(startTime); + expected.methodMetrics[0].startTime = payload.methodMetrics[0].startTime; - // TODO comparing without parsing and stringifing fails - test.equal(EJSON.parse(EJSON.stringify(payload)), EJSON.parse(EJSON.stringify(expected))); + test.stableEqual(payload, expected); } ); @@ -91,9 +89,8 @@ addAsyncTest( } } }]; - // TODO comparing without stringify fails - expected[0].startTime = Kadira.syncedDate.syncTime(expected[0].startTime); - test.equal(EJSON.parse(EJSON.stringify(payload.methodMetrics)), EJSON.parse(EJSON.stringify(expected))); + expected[0].startTime = payload.methodMetrics[0].startTime; + test.stableEqual(payload.methodMetrics,expected); } ); @@ -191,8 +188,8 @@ export const model = new MethodsModel(); function createMethodCompleted (sessionName, methodName, methodId, startTime, methodDelay) { methodDelay = methodDelay || 5; let method = {session: sessionName, name: methodName, id: methodId, events: []}; - method.events.push({type: 'start', at: startTime}); - method.events.push({type: 'complete', at: startTime + methodDelay}); + method.events.push({type: 'start', at: Ntp._now() - startTime}); + method.events.push({type: 'complete', at: Ntp._now() - startTime + methodDelay}); method = Kadira.tracer.buildTrace(method); model.processMethod(method); } @@ -200,8 +197,11 @@ function createMethodCompleted (sessionName, methodName, methodId, startTime, me function createMethodErrored (sessionName, methodName, methodId, errorMessage, startTime, methodDelay) { methodDelay = methodDelay || 5; let method = {session: sessionName, name: methodName, id: methodId, events: []}; - method.events.push({type: 'start', at: startTime}); - method.events.push({type: 'error', at: startTime + methodDelay, data: {error: errorMessage}}); + method.events.push({type: 'start', at: Ntp._now() - startTime}); + method.events.push({type: 'error', + at: Ntp._now() - startTime + methodDelay, + endAt: Ntp._now() - startTime + methodDelay, + data: {error: errorMessage}}); method = Kadira.tracer.buildTrace(method); model.processMethod(method); } diff --git a/tests/tracer/tracer.js b/tests/tracer/tracer.js index 27925ac5..6d7fa037 100644 --- a/tests/tracer/tracer.js +++ b/tests/tracer/tracer.js @@ -11,10 +11,10 @@ import { import { sleep } from '../../lib/utils'; import { TestData } from '../_helpers/globals'; import { getInfo } from '../../lib/async/als'; -import { mergeIntervals, subtractIntervals } from '../../lib/utils/time'; import { EventType } from '../../lib/constants'; import { Meteor } from 'meteor/meteor'; import { Random } from 'meteor/random'; +import { Ntp } from '../../lib/ntp'; let eventDefaults = { endAt: 0, @@ -260,7 +260,7 @@ addAsyncTest( addAsyncTest( 'Tracer - Build Trace - simple', async function (test) { - let now = new Date().getTime(); + let now = Ntp._now(); let traceInfo = { events: [ @@ -629,90 +629,6 @@ addAsyncTest('Tracer - Build Trace - the correct number of async events are capt test.equal(asyncEvents.length,1); }); -addAsyncTest('Tracer - Time - Subtract Intervals', async function (test) { - function testSubtractIntervals (arr1, arr2, expected) { - const result = subtractIntervals(arr1, arr2); - test.stableEqual(result, expected); - } - - testSubtractIntervals([ - [0, 10], - [20, 30], - [40, 50], - ],[ - [5, 15], - [25, 35], - [35, 45], - ],[ - [0, 5], - [20, 25], - [45, 50], - ]); - - testSubtractIntervals( - [ - [0, 10], - [20, 30], - [40, 50], - ], - [[0, 50]], - [] - ); - - testSubtractIntervals( - [ - [0, 100], - ], - [ - [0, 50], - ], - [ - [50, 100], - ] - ); -}); - -addAsyncTest('Tracer- Time - Merge Parallel Intervals', async function (test) { - function testMergeParallelIntervals (arr, expected) { - const result = mergeIntervals(arr); - test.stableEqual(result, expected); - } - - testMergeParallelIntervals([ - [0, 10], - [20, 30], - [40, 50], - ],[ - [0, 10], - [20, 30], - [40, 50], - ]); - - testMergeParallelIntervals([ - [0, 10], - [5, 15], - [20, 30], - [25, 35], - [40, 50], - [35, 45], - ],[ - [0, 15], - [20, 50], - ]); - - testMergeParallelIntervals([ - [0, 10], - [5, 15], - [20, 30], - [25, 35], - [40, 50], - [35, 45], - [0, 50], - ],[ - [0, 50], - ]); -}); - function startTrace () { const ddpMessage = { id: 'the-id', From e463f9f9468cff78bc6f43a7b86d039a5f45a87e Mon Sep 17 00:00:00 2001 From: Leonardo Venturini Date: Thu, 9 Nov 2023 15:25:17 -0400 Subject: [PATCH 17/17] upgrade core --- lib/kadira.js | 2 +- package.js | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/kadira.js b/lib/kadira.js index df6d0db1..60b43011 100644 --- a/lib/kadira.js +++ b/lib/kadira.js @@ -20,7 +20,7 @@ import { EventType } from './constants'; const hostname = require('os').hostname(); const logger = require('debug')('kadira:apm'); -const KadiraCore = require('@monti-apm/core').Kadira; +const KadiraCore = require('@monti-apm/core').Monti; const DEBUG_PAYLOAD_SIZE = process.env.MONTI_DEBUG_PAYLOAD_SIZE === 'true'; diff --git a/package.js b/package.js index 24d0afde..677f32a8 100644 --- a/package.js +++ b/package.js @@ -9,7 +9,7 @@ Package.describe({ let npmModules = { debug: '0.8.1', - '@monti-apm/core': '2.0.0-beta.1', + '@monti-apm/core': '2.0.0-beta.2', 'lru-cache': '5.1.1', 'json-stringify-safe': '5.0.1', 'monti-apm-sketches-js': '0.0.3',