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

Author: HazAT

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

packages/apm/src/integrations/tracing.ts

@@ -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
  */
@@ -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];

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<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(
@@ -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({

packages/apm/test/tracing.test.ts

@@ -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