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',