feat: anchored clock (#3134)

Co-authored-by: Marc Pichler <[email protected]>
Co-authored-by: Gerhard Stöbich <[email protected]>

Author: 3 people

CHANGELOG.md

@@ -10,6 +10,9 @@ All notable changes to this project will be documented in this file.
 
 ### :bug: (Bug Fix)
 
+* fix(sdk-trace-base): make span start times resistant to hrtime clock drift
+  [#3129](https://github.com/open-telemetry/opentelemetry-js/issues/3129)
+
 ### :books: (Refine Doc)
 
 * docs(metrics): add missing metrics packages to SDK reference documentation [#3239](https://github.com/open-telemetry/opentelemetry-js/pull/3239) @dyladan

packages/opentelemetry-core/src/common/anchored-clock.ts

@@ -0,0 +1,67 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+export interface Clock {
+  /**
+   * Return the current time in milliseconds from some epoch such as the Unix epoch or process start
+   */
+  now(): number;
+}
+
+
+/**
+ * A utility for returning wall times anchored to a given point in time. Wall time measurements will
+ * not be taken from the system, but instead are computed by adding a monotonic clock time
+ * to the anchor point.
+ *
+ * This is needed because the system time can change and result in unexpected situations like
+ * spans ending before they are started. Creating an anchored clock for each local root span
+ * ensures that span timings and durations are accurate while preventing span times from drifting
+ * too far from the system clock.
+ *
+ * Only creating an anchored clock once per local trace ensures span times are correct relative
+ * to each other. For example, a child span will never have a start time before its parent even
+ * if the system clock is corrected during the local trace.
+ *
+ * Heavily inspired by the OTel Java anchored clock
+ * https://github.com/open-telemetry/opentelemetry-java/blob/main/sdk/trace/src/main/java/io/opentelemetry/sdk/trace/AnchoredClock.java
+ */
+export class AnchoredClock implements Clock {
+  private _monotonicClock: Clock;
+  private _epochMillis: number;
+  private _performanceMillis: number;
+
+  /**
+   * Create a new AnchoredClock anchored to the current time returned by systemClock.
+   *
+   * @param systemClock should be a clock that returns the number of milliseconds since January 1 1970 such as Date
+   * @param monotonicClock should be a clock that counts milliseconds monotonically such as window.performance or perf_hooks.performance
+   */
+  public constructor(systemClock: Clock, monotonicClock: Clock) {
+    this._monotonicClock = monotonicClock;
+    this._epochMillis = systemClock.now();
+    this._performanceMillis = monotonicClock.now();
+  }
+
+  /**
+   * Returns the current time by adding the number of milliseconds since the
+   * AnchoredClock was created to the creation epoch time
+   */
+  public now(): number {
+    const delta = this._monotonicClock.now() - this._performanceMillis;
+    return this._epochMillis + delta;
+  }
+}

packages/opentelemetry-core/src/index.ts

@@ -15,6 +15,7 @@
  */
 
 export * from './baggage/propagation/W3CBaggagePropagator';
+export * from './common/anchored-clock';
 export * from './common/attributes';
 export * from './common/global-error-handler';
 export * from './common/logging-error-handler';

packages/opentelemetry-core/test/common/anchored-clock.test.ts

@@ -0,0 +1,29 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+import assert = require('assert');
+import { AnchoredClock, otperformance } from '../../src';
+
+describe('AnchoredClock', () => {
+  it('should keep time', done => {
+    const clock = new AnchoredClock(Date, otperformance);
+    setTimeout(() => {
+      // after about 100ms, the clocks are within 10ms of each other
+      assert.ok(Math.abs(Date.now() - clock.now()) < 10);
+      done();
+    }, 100);
+  });
+});

packages/opentelemetry-sdk-trace-base/src/Span.ts

@@ -15,24 +15,25 @@
  */
 
 import * as api from '@opentelemetry/api';
+import { Context, SpanAttributeValue } from '@opentelemetry/api';
 import {
-  isAttributeValue,
-  hrTime,
+  Clock,
   hrTimeDuration,
   InstrumentationLibrary,
+  isAttributeValue,
   isTimeInput,
-  timeInputToHrTime,
+  otperformance,
   sanitizeAttributes,
+  timeInputToHrTime
 } from '@opentelemetry/core';
 import { Resource } from '@opentelemetry/resources';
 import { SemanticAttributes } from '@opentelemetry/semantic-conventions';
+import { ExceptionEventName } from './enums';
 import { ReadableSpan } from './export/ReadableSpan';
+import { SpanProcessor } from './SpanProcessor';
 import { TimedEvent } from './TimedEvent';
 import { Tracer } from './Tracer';
-import { SpanProcessor } from './SpanProcessor';
 import { SpanLimits } from './types';
-import { SpanAttributeValue, Context } from '@opentelemetry/api';
-import { ExceptionEventName } from './enums';
 
 /**
  * This class represents a span.
@@ -59,8 +60,13 @@ export class Span implements api.Span, ReadableSpan {
   private readonly _spanProcessor: SpanProcessor;
   private readonly _spanLimits: SpanLimits;
   private readonly _attributeValueLengthLimit: number;
+  private readonly _clock: Clock;
 
-  /** Constructs a new Span instance. */
+  /**
+   * Constructs a new Span instance.
+   *
+   * @deprecated calling Span constructor directly is not supported. Please use tracer.startSpan.
+   * */
   constructor(
     parentTracer: Tracer,
     context: Context,
@@ -69,14 +75,16 @@ export class Span implements api.Span, ReadableSpan {
     kind: api.SpanKind,
     parentSpanId?: string,
     links: api.Link[] = [],
-    startTime: api.TimeInput = hrTime()
+    startTime?: api.TimeInput,
+    clock: Clock = otperformance,
   ) {
+    this._clock = clock;
     this.name = spanName;
     this._spanContext = spanContext;
     this.parentSpanId = parentSpanId;
     this.kind = kind;
     this.links = links;
-    this.startTime = timeInputToHrTime(startTime);
+    this.startTime = timeInputToHrTime(startTime ?? clock.now());
     this.resource = parentTracer.resource;
     this.instrumentationLibrary = parentTracer.instrumentationLibrary;
     this._spanLimits = parentTracer.getSpanLimits();
@@ -103,7 +111,7 @@ export class Span implements api.Span, ReadableSpan {
 
     if (
       Object.keys(this.attributes).length >=
-        this._spanLimits.attributeCountLimit! &&
+      this._spanLimits.attributeCountLimit! &&
       !Object.prototype.hasOwnProperty.call(this.attributes, key)
     ) {
       return this;
@@ -147,7 +155,7 @@ export class Span implements api.Span, ReadableSpan {
       attributesOrStartTime = undefined;
     }
     if (typeof startTime === 'undefined') {
-      startTime = hrTime();
+      startTime = this._clock.now();
     }
 
     const attributes = sanitizeAttributes(attributesOrStartTime);
@@ -171,15 +179,16 @@ export class Span implements api.Span, ReadableSpan {
     return this;
   }
 
-  end(endTime: api.TimeInput = hrTime()): void {
+  end(endTime?: api.TimeInput): void {
     if (this._isSpanEnded()) {
       api.diag.error('You can only call end() on a span once.');
       return;
     }
     this._ended = true;
-    this.endTime = timeInputToHrTime(endTime);
 
+    this.endTime = timeInputToHrTime(endTime ?? this._clock.now());
     this._duration = hrTimeDuration(this.startTime, this.endTime);
+
     if (this._duration[0] < 0) {
       api.diag.warn(
         'Inconsistent start and end time, startTime > endTime',
@@ -195,7 +204,7 @@ export class Span implements api.Span, ReadableSpan {
     return this._ended === false;
   }
 
-  recordException(exception: api.Exception, time: api.TimeInput = hrTime()): void {
+  recordException(exception: api.Exception, time: api.TimeInput = this._clock.now()): void {
     const attributes: api.SpanAttributes = {};
     if (typeof exception === 'string') {
       attributes[SemanticAttributes.EXCEPTION_MESSAGE] = exception;

packages/opentelemetry-sdk-trace-base/src/Tracer.ts

@@ -19,6 +19,8 @@ import {
   InstrumentationLibrary,
   sanitizeAttributes,
   isTracingSuppressed,
+  AnchoredClock,
+  otperformance,
 } from '@opentelemetry/core';
 import { Resource } from '@opentelemetry/resources';
 import { BasicTracerProvider } from './BasicTracerProvider';
@@ -67,17 +69,31 @@ export class Tracer implements api.Tracer {
     options: api.SpanOptions = {},
     context = api.context.active()
   ): api.Span {
-    if (isTracingSuppressed(context)) {
-      api.diag.debug('Instrumentation suppressed, returning Noop Span');
-      return api.trace.wrapSpanContext(api.INVALID_SPAN_CONTEXT);
-    }
-
     // remove span from context in case a root span is requested via options
     if (options.root) {
       context = api.trace.deleteSpan(context);
     }
+    const parentSpan = api.trace.getSpan(context);
+    let clock: AnchoredClock | undefined;
+    if (parentSpan) {
+      clock = (parentSpan as any)['_clock'];
+    }
+
+    if (!clock) {
+      clock = new AnchoredClock(Date, otperformance);
+      if (parentSpan) {
+        (parentSpan as any)['_clock'] = clock;
+      }
+    }
+
+    if (isTracingSuppressed(context)) {
+      api.diag.debug('Instrumentation suppressed, returning Noop Span');
+      const nonRecordingSpan = api.trace.wrapSpanContext(api.INVALID_SPAN_CONTEXT);
+      (nonRecordingSpan as any)['_clock'] = clock;
+      return nonRecordingSpan;
+    }
 
-    const parentSpanContext = api.trace.getSpanContext(context);
+    const parentSpanContext = parentSpan?.spanContext();
     const spanId = this._idGenerator.generateSpanId();
     let traceId;
     let traceState;
@@ -117,7 +133,9 @@ export class Tracer implements api.Tracer {
     const spanContext = { traceId, spanId, traceFlags, traceState };
     if (samplingResult.decision === api.SamplingDecision.NOT_RECORD) {
       api.diag.debug('Recording is off, propagating context in a non-recording span');
-      return api.trace.wrapSpanContext(spanContext);
+      const nonRecordingSpan = api.trace.wrapSpanContext(spanContext);
+      (nonRecordingSpan as any)['_clock'] = clock;
+      return nonRecordingSpan;
     }
 
     const span = new Span(
@@ -128,7 +146,8 @@ export class Tracer implements api.Tracer {
       spanKind,
       parentSpanId,
       links,
-      options.startTime
+      options.startTime,
+      clock,
     );
     // Set initial span attributes. The attributes object may have been mutated
     // by the sampler, so we sanitize the merged attributes before setting them.