Skip to content

Commit

Permalink
Merge pull request #106 from monti-apm/feature/fiberless-trace-adjust…
Browse files Browse the repository at this point in the history 
…ments

Tracer adjustments part 2
  • Loading branch information
@leonardoventurini
leonardoventurini authored Nov 16, 2023
2 parents 53972f4 + edc33ff commit 5ac8019
Show file tree
Hide file tree
Showing 9 changed files with 535 additions and 100 deletions.
149 changes: 107 additions & 42 deletions lib/tracer/tracer.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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');

Expand Down Expand Up @@ -170,20 +171,16 @@ Tracer.prototype.asyncEvent = function (type, data, fn) {
const { info } = getStore();

if (!info) {
return Reflect.apply(fn, this, [false]);
return fn(false);
}

const event = this.event(info.trace, type, data);

if (event) {
event.parentEvent = getActiveEvent();
}

let reset = this.setActiveEvent(event);
let result;

try {
result = Reflect.apply(fn, this, [event]);
result = fn(event);
} catch (err) {
this.eventEnd(info.trace, event, { err: err.message });
throw err;
Expand All @@ -206,7 +203,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 };
Expand Down Expand Up @@ -250,16 +246,18 @@ 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) {
let metrics = {
compute: 0,
async: 0,
totalNonCompute: 0,
};

let firstEvent = traceInfo.events[0];
Expand All @@ -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;
Expand All @@ -293,28 +287,39 @@ 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),
* 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 {Object} metrics A metrics object to be updated along the optimization process.
* @param {Number} prevEnded The timestamp the previous event ended
* @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, 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;

const optimizedNestedEvents = this._hasUsefulNested(objectEvent) ? this.optimizeEvents(nested, metrics) : undefined;
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];
Expand All @@ -325,29 +330,48 @@ 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
// couple ms since the trace ended. This should use the same timestamp
// as when the trace ended
endAt = Ntp._now();
extraInfo.forcedEnd = true;
}

objectEvent.duration = endAt - at;
let duration = endAt - at;
optimizedEvent[1] = duration;

const {duration} = objectEvent;
let offset = prevEnded - at;
if (offset < 0) {
throw new Error('Monti APM: unexpected gap between events');
} else if (offset > 0) {
extraInfo.offset = offset;
}

// We need this info as events are not always in order or in series.
extraInfo.at = at;
extraInfo.endAt = endAt;
extraInfo.nested = optimizedNestedEvents;
if (this._hasUsefulNested(objectEvent)) {
let nestedStartedAt = nested[0].at;
let beginningCompute = nestedStartedAt - at;
extraInfo.nested = this.optimizeEvents(nested, nestedMetrics);

if (metrics && duration > 0 && level === 0) {
metrics[type] = metrics[type] || 0;
metrics[type] += duration;
metrics.totalNonCompute += duration;
}
if (beginningCompute > 0) {
extraInfo.nested.unshift(['compute', beginningCompute]);
incrementMetric(nestedMetrics, 'compute', beginningCompute);
}

// Start and end events do not have duration.
optimizedEvent[1] = duration;
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);
}
}

if (data) {
Expand All @@ -373,27 +397,68 @@ Tracer.prototype.optimizeEvent = function (objectEvent, metrics) {
};

Tracer.prototype.optimizeEvents = function (events, metrics) {
if (!events) {
if (!events || events.length === 0) {
return [];
}

let processedEvents = [];

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);
let countedUntil = previousEnd;

for (let i = 1; i < events.length; i += 1) {
let prevEvent = events[i - 1];
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 - (prevEvent.endAt || prevEvent.at);
computeTime = event.at - previousEnd;

if (computeTime > 0) {
processedEvents.push([EventType.Compute, computeTime]);
previousEnd += computeTime;

if (previousEnd > countedUntil) {
let diff = Math.min(computeTime, previousEnd - countedUntil);
incrementMetric(metrics, 'compute', diff);
countedUntil = previousEnd;
}
}

processedEvents.push(this.optimizeEvent(event, metrics));
let processedEvent = this.optimizeEvent(
event,
previousEnd,
isCustomEvent ? metrics : undefined
);
processedEvents.push(processedEvent);

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');

// The nested events are used instead
if (!isCustomEvent) {
incrementMetric(metrics, processedEvent[0], count);
}

countedUntil = previousEnd;
}
}

if (processedEvents.length > MAX_TRACE_EVENTS) {
Expand Down
35 changes: 26 additions & 9 deletions tests/_helpers/helpers.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -352,26 +347,30 @@ 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
// (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 / roundTo) * roundTo;
}
}

return event;
Expand All @@ -382,6 +381,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,
Expand Down
4 changes: 2 additions & 2 deletions tests/client/models/errors.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -119,7 +119,7 @@ Tinytest.addAsync(
function (test, done) {
let em = new ErrorModel({
maxErrorsPerInterval: 2,
intervalInMillis: 200
intervalInMillis: 100
});

em.sendError({name: 'hoo'});
Expand All @@ -130,7 +130,7 @@ Tinytest.addAsync(
test.equal(em.canSendErrors(), true);
em.close();
done();
}, 250);
}, 200);
}
);

Expand Down
4 changes: 2 additions & 2 deletions tests/hijack/base.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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']
];

Expand Down
Loading

0 comments on commit 5ac8019

Please sign in to comment.