From 1be9b739fee8caf8a5c08f47af83f60b51056cb9 Mon Sep 17 00:00:00 2001 From: Daniel Griesser Date: Wed, 11 Mar 2020 08:36:47 +0100 Subject: [PATCH] ref(apm): Always use monotonic clock for time calculations (#2485) * ref(apm): Always use monotonic clock for time calculations Also remove offset time calculations since everything is based on timeOrigin * ref: Changelog * doc: Document trimming of transaction end time * doc(apm): Document argument to Span.finish inline Document the argument using the same format used in microsoft/TypeScript code base. * Update packages/apm/src/span.ts Co-Authored-By: Rodolfo Carvalho * ref: Remove empty blocking test * Remove logging for discarded entries We may reintroduce this later on-demand. For now, reduce noise. Co-authored-by: Rodolfo Carvalho Co-authored-by: Rodolfo Carvalho --- CHANGELOG.md | 1 + packages/apm/src/integrations/tracing.ts | 58 ++++++-------------- packages/apm/src/span.ts | 67 +++++++----------------- packages/apm/test/tracing.test.ts | 61 --------------------- packages/utils/src/misc.ts | 45 +++++++++++++++- 5 files changed, 77 insertions(+), 155 deletions(-) delete mode 100644 packages/apm/test/tracing.test.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index 7580c5984251..20d8f8e6d37a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,7 @@ - [apm] feat: Add a simple heartbeat check, if activities don't change in 3 beats, finish the transaction (#2478) - [apm] feat: Make use of the `performance` browser API to provide better instrumentation (#2474) - [browser] ref: Move global error handler + unhandled promise rejection to instrument (#2475) +- [apm] ref: Always use monotonic clock for time calculations (#2485) - [apm] fix: Add trace context to all events (#2486) ## 5.13.2 diff --git a/packages/apm/src/integrations/tracing.ts b/packages/apm/src/integrations/tracing.ts index a0f8c077e006..34b2eb685868 100644 --- a/packages/apm/src/integrations/tracing.ts +++ b/packages/apm/src/integrations/tracing.ts @@ -95,19 +95,6 @@ interface Activity { const global = getGlobalObject(); const defaultTracingOrigins = ['localhost', /^\//]; -if (global.performance) { - // Polyfill for performance.timeOrigin. - // - // While performance.timing.navigationStart is deprecated in favor of performance.timeOrigin, performance.timeOrigin - // is not as widely supported. Namely, performance.timeOrigin is undefined in Safari as of writing. - // tslint:disable-next-line:strict-type-predicates - if (performance.timeOrigin === undefined) { - // @ts-ignore - // tslint:disable-next-line:deprecation - performance.timeOrigin = performance.timing.navigationStart; - } -} - /** * Tracing Integration */ @@ -297,13 +284,20 @@ export class Tracing implements Integration { document.addEventListener('visibilitychange', () => { if (document.hidden && Tracing._activeTransaction) { logger.log('[Tracing] Discarded active transaction incl. activities since tab moved to the background'); - Tracing._activeTransaction = undefined; - Tracing._activities = {}; + Tracing._resetActiveTransaction(); } }); } } + /** + * Unsets the current active transaction + activities + */ + private static _resetActiveTransaction(): void { + Tracing._activeTransaction = undefined; + Tracing._activities = {}; + } + /** * Registers to History API to detect navigation changes */ @@ -415,7 +409,6 @@ export class Tracing implements Integration { ); Tracing._activeTransaction = span; - Tracing._addOffsetToSpan(span as SpanClass); // We need to do this workaround here and not use configureScope // Reason being at the time we start the inital transaction we do not have a client bound on the hub yet @@ -458,8 +451,8 @@ export class Tracing implements Integration { if (active) { Tracing._addPerformanceEntries(active); logger.log('[Tracing] finishIdleTransaction', active.transaction); - // true = use timestamp of last span - active.finish(true); + active.finish(/*trimEnd*/ true); + Tracing._resetActiveTransaction(); } } @@ -542,6 +535,10 @@ export class Tracing implements Integration { const startTime = Tracing._msToSec(entry.startTime as number); const duration = Tracing._msToSec(entry.duration as number); + if (transactionSpan.op === 'navigation' && timeOrigin + startTime < transactionSpan.startTimestamp) { + return; + } + switch (entry.entryType) { case 'navigation': addPerformanceNavigationTiming(transactionSpan, entry, 'unloadEvent'); @@ -630,18 +627,6 @@ export class Tracing implements Integration { } } - /** - * Adds offset to the span - * - * @param measureName name of the performance measure - * @param span Span to add data.offset to - */ - private static _addOffsetToSpan(span: SpanClass): void { - if (global.performance) { - span.setData('offset', Tracing._msToSec(performance.now())); - } - } - /** * Converts from milliseconds to seconds * @param time time in ms @@ -681,7 +666,6 @@ export class Tracing implements Integration { const hub = _getCurrentHub(); if (hub) { const span = hub.startSpan(spanContext); - Tracing._addOffsetToSpan(span as SpanClass); Tracing._activities[Tracing._currentIndex] = { name, span, @@ -738,18 +722,6 @@ export class Tracing implements Integration { }); } span.finish(); - // If there is an offset in data, update timestamps accordingly - if ( - global.performance && - span.data && - typeof span.data.offset === 'number' && - typeof span.timestamp === 'number' - ) { - const timeOrigin = Tracing._msToSec(performance.timeOrigin); - const duration = span.timestamp - span.startTimestamp; - span.startTimestamp = timeOrigin + span.data.offset; - span.timestamp = timeOrigin + duration; - } } // tslint:disable-next-line: no-dynamic-delete delete Tracing._activities[id]; diff --git a/packages/apm/src/span.ts b/packages/apm/src/span.ts index 08da86bac3fc..9f328a15e2d6 100644 --- a/packages/apm/src/span.ts +++ b/packages/apm/src/span.ts @@ -2,36 +2,7 @@ import { getCurrentHub, Hub } from '@sentry/hub'; import { Span as SpanInterface, SpanContext, SpanStatus } from '@sentry/types'; -import { - dropUndefinedKeys, - dynamicRequire, - getGlobalObject, - isInstanceOf, - isNodeEnv, - logger, - timestampWithMs, - uuid4, -} from '@sentry/utils'; - -const INITIAL_TIME = Date.now(); - -const performanceFallback: Pick = { - now(): number { - return INITIAL_TIME - Date.now(); - }, -}; - -const crossPlatformPerformance: Pick = (() => { - if (isNodeEnv()) { - try { - const perfHooks = dynamicRequire(module, 'perf_hooks') as { performance: Performance }; - return perfHooks.performance; - } catch (_) { - return performanceFallback; - } - } - return getGlobalObject().performance || performanceFallback; -})(); +import { dropUndefinedKeys, isInstanceOf, logger, timestampWithMs, uuid4 } from '@sentry/utils'; // TODO: Should this be exported? export const TRACEPARENT_REGEXP = new RegExp( @@ -106,23 +77,12 @@ export class Span implements SpanInterface, SpanContext { public sampled?: boolean; /** - * Timestamp when the span was created. + * Timestamp in seconds when the span was created. */ public startTimestamp: number = timestampWithMs(); /** - * Internal start time tracked with a monotonic clock. - * - * Works with mostly any browser version released since 2012. - * https://caniuse.com/#search=performance.now - * - * Works with Node.js v8.5.0 or higher. - * https://nodejs.org/api/perf_hooks.html#perf_hooks_performance_now - */ - private readonly _startTimestampMonotonic: number = crossPlatformPerformance.now(); - - /** - * Finish timestamp of the span. + * Timestamp in seconds when the span ended. */ public timestamp?: number; @@ -293,16 +253,19 @@ export class Span implements SpanInterface, SpanContext { } /** - * Sets the finish timestamp on the current span + * Sets the finish timestamp on the current span. + * @param trimEnd If true, sets the end timestamp of the transaction to the highest timestamp of child spans, trimming + * the duration of the transaction span. This is useful to discard extra time in the transaction span that is not + * accounted for in child spans, like what happens in the idle transaction Tracing integration, where we finish the + * transaction after a given "idle time" and we don't want this "idle time" to be part of the transaction. */ - public finish(useLastSpanTimestamp: boolean = false): string | undefined { + public finish(trimEnd: boolean = false): string | undefined { // This transaction is already finished, so we should not flush it again. if (this.timestamp !== undefined) { return undefined; } - const durationSeconds = (crossPlatformPerformance.now() - this._startTimestampMonotonic) / 1000; - this.timestamp = this.startTimestamp + durationSeconds; + this.timestamp = timestampWithMs(); if (this.spanRecorder === undefined) { return undefined; @@ -324,10 +287,16 @@ export class Span implements SpanInterface, SpanContext { logger.warn('Discarding transaction Span without sampling decision'); return undefined; } + const finishedSpans = this.spanRecorder ? this.spanRecorder.finishedSpans.filter(s => s !== this) : []; - if (useLastSpanTimestamp && finishedSpans.length > 0) { - this.timestamp = finishedSpans[finishedSpans.length - 1].timestamp; + if (trimEnd && finishedSpans.length > 0) { + this.timestamp = finishedSpans.reduce((prev: Span, current: Span) => { + if (prev.timestamp && current.timestamp) { + return prev.timestamp > current.timestamp ? prev : current; + } + return prev; + }).timestamp; } return this._hub.captureEvent({ diff --git a/packages/apm/test/tracing.test.ts b/packages/apm/test/tracing.test.ts deleted file mode 100644 index 82a7bd92f6f3..000000000000 --- a/packages/apm/test/tracing.test.ts +++ /dev/null @@ -1,61 +0,0 @@ -import { Tracing } from '../src/integrations/tracing'; - -const tracing: Tracing = new Tracing(); - -const configureScope = jest.fn(); -const startSpan = jest.fn(); - -const getCurrentHubMock: any = () => ({ - configureScope, - startSpan, -}); - -tracing.setupOnce(jest.fn(), getCurrentHubMock); - -describe('TransactionActivity', () => { - afterEach(() => { - jest.resetAllMocks(); - (Tracing as any)._activities = {}; - (Tracing as any)._currentIndex = 0; - (Tracing as any)._activeTransaction = undefined; - }); - - test('startSpan with transaction', () => { - // Tracing.startIdleTransaction('test'); - // expect(startSpan).toBeCalledWith({ transaction: 'test' }); - expect(true); - }); - - // test('track activity', () => { - // jest.useFakeTimers(); - // const spy = jest.spyOn(TransactionActivity as any, '_watchActivity'); - - // TransactionActivity.pushActivity('xhr'); - // expect(spy).toBeCalledTimes(1); - // jest.runOnlyPendingTimers(); - // expect(spy).toBeCalledTimes(2); - // jest.runOnlyPendingTimers(); - // expect(spy).toBeCalledTimes(3); - // }); - - // test('multiple activities ', () => { - // Tracing.pushActivity('xhr'); - // const a = Tracing.pushActivity('xhr2'); - // Tracing.popActivity(a); - // Tracing.pushActivity('xhr3'); - // expect(Object.keys((Tracing as any)._activities)).toHaveLength(2); - // }); - - // test('finishing a transaction after debounce', () => { - // jest.useFakeTimers(); - // const spy = jest.spyOn(TransactionActivity as any, '_watchActivity'); - // TransactionActivity.startIdleTransaction('test'); - // const a = TransactionActivity.pushActivity('xhr'); - // expect(spy).toBeCalledTimes(1); - // expect(Object.keys((TransactionActivity as any)._activities)).toHaveLength(1); - // TransactionActivity.popActivity(a); - // expect(Object.keys((TransactionActivity as any)._activities)).toHaveLength(0); - // jest.runOnlyPendingTimers(); - // expect(spy).toBeCalledTimes(2); - // }); -}); diff --git a/packages/utils/src/misc.ts b/packages/utils/src/misc.ts index 8d86acb3c91c..b5912b63c6fd 100644 --- a/packages/utils/src/misc.ts +++ b/packages/utils/src/misc.ts @@ -346,11 +346,52 @@ function _htmlElementAsString(el: unknown): string { return out.join(''); } +const INITIAL_TIME = Date.now(); +let prevNow = 0; + +const performanceFallback: Pick = { + now(): number { + let now = Date.now() - INITIAL_TIME; + if (now < prevNow) { + now = prevNow; + } + prevNow = now; + return now; + }, + timeOrigin: INITIAL_TIME, +}; + +export const crossPlatformPerformance: Pick = (() => { + if (isNodeEnv()) { + try { + const perfHooks = dynamicRequire(module, 'perf_hooks') as { performance: Performance }; + return perfHooks.performance; + } catch (_) { + return performanceFallback; + } + } + + if (getGlobalObject().performance) { + // Polyfill for performance.timeOrigin. + // + // While performance.timing.navigationStart is deprecated in favor of performance.timeOrigin, performance.timeOrigin + // is not as widely supported. Namely, performance.timeOrigin is undefined in Safari as of writing. + // tslint:disable-next-line:strict-type-predicates + if (performance.timeOrigin === undefined) { + // @ts-ignore + // tslint:disable-next-line:deprecation + performance.timeOrigin = performance.timing.navigationStart; + } + } + + return getGlobalObject().performance || performanceFallback; +})(); + /** - * Returns a timestamp in seconds with milliseconds precision. + * Returns a timestamp in seconds with milliseconds precision since the UNIX epoch calculated with the monotonic clock. */ export function timestampWithMs(): number { - return Date.now() / 1000; + return (crossPlatformPerformance.timeOrigin + crossPlatformPerformance.now()) / 1000; } // https://semver.org/#is-there-a-suggested-regular-expression-regex-to-check-a-semver-string