Skip to content

Commit

Permalink
ref(apm): Always use monotonic clock for time calculations (#2485)
Browse files Browse the repository at this point in the history 
* 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 <rodolfo.carvalho@sentry.io>

* 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 <rhcarvalho@gmail.com>
Co-authored-by: Rodolfo Carvalho <rodolfo.carvalho@sentry.io>
  • Loading branch information
@HazAT @rhcarvalho
3 people committed Mar 11, 2020
1 parent 57fe8c6 commit 1be9b73
Show file tree
Hide file tree
Showing 5 changed files with 77 additions and 155 deletions.
1 change: 1 addition & 0 deletions CHANGELOG.md
View file
Expand Up @@ -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
Expand Down
58 changes: 15 additions & 43 deletions packages/apm/src/integrations/tracing.ts
View file
Expand Up @@ -95,19 +95,6 @@ interface Activity {
const global = getGlobalObject<Window>();
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
*/
Expand Down Expand Up @@ -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
*/
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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();
}
}

Expand Down Expand Up @@ -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');
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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];
Expand Down
67 changes: 18 additions & 49 deletions packages/apm/src/span.ts
View file
Expand Up @@ -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<Performance, 'now'> = {
now(): number {
return INITIAL_TIME - Date.now();
},
};

const crossPlatformPerformance: Pick<Performance, 'now'> = (() => {
if (isNodeEnv()) {
try {
const perfHooks = dynamicRequire(module, 'perf_hooks') as { performance: Performance };
return perfHooks.performance;
} catch (_) {
return performanceFallback;
}
}
return getGlobalObject<Window>().performance || performanceFallback;
})();
import { dropUndefinedKeys, isInstanceOf, logger, timestampWithMs, uuid4 } from '@sentry/utils';

// TODO: Should this be exported?
export const TRACEPARENT_REGEXP = new RegExp(
Expand Down Expand Up @@ -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;

Expand Down Expand Up @@ -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;
Expand All @@ -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({
Expand Down
61 changes: 0 additions & 61 deletions packages/apm/test/tracing.test.ts
View file

This file was deleted.

45 changes: 43 additions & 2 deletions packages/utils/src/misc.ts
View file
Expand Up @@ -346,11 +346,52 @@ function _htmlElementAsString(el: unknown): string {
return out.join('');
}

const INITIAL_TIME = Date.now();
let prevNow = 0;

const performanceFallback: Pick<Performance, 'now' | 'timeOrigin'> = {
now(): number {
let now = Date.now() - INITIAL_TIME;
if (now < prevNow) {
now = prevNow;
}
prevNow = now;
return now;
},
timeOrigin: INITIAL_TIME,
};

export const crossPlatformPerformance: Pick<Performance, 'now' | 'timeOrigin'> = (() => {
if (isNodeEnv()) {
try {
const perfHooks = dynamicRequire(module, 'perf_hooks') as { performance: Performance };
return perfHooks.performance;
} catch (_) {
return performanceFallback;
}
}

if (getGlobalObject<Window>().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<Window>().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
Expand Down

0 comments on commit 1be9b73

Please sign in to comment.