feat: anchored clock

CHANGELOG.md

@@ -13,6 +13,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)
 
 ### :house: (Internal)

experimental/packages/opentelemetry-instrumentation-http/test/functionals/utils.test.ts

@@ -31,7 +31,7 @@ import * as url from 'url';
 import {IgnoreMatcher, ParsedRequestOptions} from '../../src/types';
 import * as utils from '../../src/utils';
 import { AttributeNames } from '../../src/enums/AttributeNames';
-import { RPCType, setRPCMetadata } from '@opentelemetry/core';
+import { AnchoredClock, otperformance, RPCType, setRPCMetadata } from '@opentelemetry/core';
 import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks';
 import {extractHostnameAndPort} from '../../src/utils';
 
@@ -251,7 +251,8 @@ describe('Utility', () => {
         ROOT_CONTEXT,
         'test',
         { spanId: '', traceId: '', traceFlags: TraceFlags.SAMPLED },
-        SpanKind.INTERNAL
+        SpanKind.INTERNAL,
+        new AnchoredClock(Date, otperformance),
       );
       /* tslint:disable-next-line:no-any */
       utils.setSpanWithError(span, new Error(errorMessage));
@@ -486,7 +487,8 @@ describe('Utility', () => {
         ROOT_CONTEXT,
         'test',
         { spanId: '', traceId: '', traceFlags: TraceFlags.SAMPLED },
-        SpanKind.INTERNAL
+        SpanKind.INTERNAL,
+        new AnchoredClock(Date, otperformance),
       );
     });
 

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

@@ -0,0 +1,66 @@
+/*
+ * 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 we minimize the performance
+ * impact of accessing the system clock.
+ *
+ * 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/common/time.ts

@@ -121,6 +121,18 @@ export function hrTimeDuration(
   return [seconds, nanos];
 }
 
+/**
+ * Add an HrTime duration to an HrTime
+ */
+export function addHrTime(time: api.HrTime, duration: api.HrTime): api.HrTime {
+  const out: api.HrTime = [time[0] + duration[0], time[1] + duration[1]];
+  if (out[1] >= 1e9) {
+    out[1] -= 1e9;
+    out[0] += 1;
+  }
+  return out;
+}
+
 /**
  * Convert hrTime to timestamp, for example "2019-05-14T17:00:00.000123456Z"
  * @param time

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/time.test.ts

@@ -27,6 +27,7 @@ import {
   hrTimeToMicroseconds,
   hrTimeToTimeStamp,
   isTimeInput,
+  addHrTime,
 } from '../../src/common/time';
 
 describe('time', () => {
@@ -151,6 +152,23 @@ describe('time', () => {
     });
   });
 
+  describe('#addHrTime', () => {
+    it('should add two HrTimes', () => {
+      const startTime: api.HrTime = [22, 400000000];
+      const endTime: api.HrTime = [32, 200000000];
+
+      const output = addHrTime(startTime, endTime);
+      assert.deepStrictEqual(output, [54, 600000000]);
+    });
+    it('should overflow nanoseconds', () => {
+      const startTime: api.HrTime = [22, 600000000];
+      const endTime: api.HrTime = [32, 700000000];
+
+      const output = addHrTime(startTime, endTime);
+      assert.deepStrictEqual(output, [55, 300000000]);
+    });
+  });
+
   describe('#hrTimeToTimeStamp', () => {
     it('should return timestamp', () => {
       const time: api.HrTime = [1573513121, 123456];

packages/opentelemetry-exporter-zipkin/test/common/transform.test.ts

@@ -16,8 +16,10 @@
 
 import * as api from '@opentelemetry/api';
 import {
+  AnchoredClock,
   hrTimeDuration,
   hrTimeToMicroseconds,
+  otperformance,
   VERSION,
 } from '@opentelemetry/core';
 import { Resource } from '@opentelemetry/resources';
@@ -66,6 +68,7 @@ describe('transform', () => {
         'my-span',
         spanContext,
         api.SpanKind.SERVER,
+        new AnchoredClock(Date, otperformance),
         parentId
       );
       span.setAttributes({
@@ -116,7 +119,8 @@ describe('transform', () => {
         api.ROOT_CONTEXT,
         'my-span',
         spanContext,
-        api.SpanKind.SERVER
+        api.SpanKind.SERVER,
+        new AnchoredClock(Date, otperformance)
       );
       span.end();
 
@@ -164,7 +168,8 @@ describe('transform', () => {
           api.ROOT_CONTEXT,
           'my-span',
           spanContext,
-          item.ot
+          item.ot,
+          new AnchoredClock(Date, otperformance)
         );
         span.end();
 
@@ -207,6 +212,7 @@ describe('transform', () => {
         'my-span',
         spanContext,
         api.SpanKind.SERVER,
+        new AnchoredClock(Date, otperformance),
         parentId
       );
       span.setAttributes({
@@ -237,6 +243,7 @@ describe('transform', () => {
         'my-span',
         spanContext,
         api.SpanKind.SERVER,
+        new AnchoredClock(Date, otperformance),
         parentId
       );
       const status: api.SpanStatus = {
@@ -273,6 +280,7 @@ describe('transform', () => {
         'my-span',
         spanContext,
         api.SpanKind.SERVER,
+        new AnchoredClock(Date, otperformance),
         parentId
       );
       const status: api.SpanStatus = {
@@ -314,6 +322,7 @@ describe('transform', () => {
         'my-span',
         spanContext,
         api.SpanKind.SERVER,
+        new AnchoredClock(Date, otperformance),
         parentId
       );
       span.addEvent('my-event1');

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

@@ -17,12 +17,12 @@
 import * as api from '@opentelemetry/api';
 import {
   isAttributeValue,
-  hrTime,
-  hrTimeDuration,
   InstrumentationLibrary,
   isTimeInput,
-  timeInputToHrTime,
   sanitizeAttributes,
+  AnchoredClock,
+  timeInputToHrTime,
+  hrTimeDuration,
 } from '@opentelemetry/core';
 import { Resource } from '@opentelemetry/resources';
 import { SemanticAttributes } from '@opentelemetry/semantic-conventions';
@@ -59,6 +59,7 @@ export class Span implements api.Span, ReadableSpan {
   private readonly _spanProcessor: SpanProcessor;
   private readonly _spanLimits: SpanLimits;
   private readonly _attributeValueLengthLimit: number;
+  private readonly _clock: AnchoredClock;
 
   /** Constructs a new Span instance. */
   constructor(
@@ -67,16 +68,18 @@ export class Span implements api.Span, ReadableSpan {
     spanName: string,
     spanContext: api.SpanContext,
     kind: api.SpanKind,
+    clock: AnchoredClock,
     parentSpanId?: string,
     links: api.Link[] = [],
-    startTime: api.TimeInput = hrTime()
+    startTime?: api.TimeInput,
   ) {
+    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 +106,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 +150,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 +174,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 +199,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';
@@ -77,7 +79,8 @@ export class Tracer implements api.Tracer {
       context = api.trace.deleteSpan(context);
     }
 
-    const parentSpanContext = api.trace.getSpanContext(context);
+    const parentSpan = api.trace.getSpan(context);
+    const parentSpanContext = parentSpan?.spanContext();
     const spanId = this._idGenerator.generateSpanId();
     let traceId;
     let traceState;
@@ -120,15 +123,28 @@ export class Tracer implements api.Tracer {
       return api.trace.wrapSpanContext(spanContext);
     }
 
+    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;
+      }
+    }
+
     const span = new Span(
       this,
       context,
       name,
       spanContext,
       spanKind,
+      clock,
       parentSpanId,
       links,
-      options.startTime
+      options.startTime,
     );
     // Set initial span attributes. The attributes object may have been mutated
     // by the sampler, so we sanitize the merged attributes before setting them.