fix(tracing): make spans resilient to performance clock drift

CHANGELOG.md

@@ -21,6 +21,7 @@ For experimental package changes, see the [experimental CHANGELOG](experimental/
     * `telemetry.sdk.name`
     * `telemetry.sdk.language`
     * `telemetry.sdk.version`
+* fix(sdk-trace): make spans resilient to clock drift [#3434](https://github.com/open-telemetry/opentelemetry-js/pull/3434) @dyladan
 
 ### :books: (Refine Doc)
 

packages/opentelemetry-core/src/common/time.ts

@@ -33,7 +33,7 @@ const SECOND_TO_NANOSECONDS = Math.pow(10, NANOSECOND_DIGITS);
  * This is represented in HrTime format as [1609504210, 150000000].
  * @param epochMillis
  */
-function numberToHrtime(epochMillis: number): api.HrTime {
+export function epochMillisToHrTime(epochMillis: number): api.HrTime {
   const epochSeconds = epochMillis / 1000;
   // Decimals only.
   const seconds = Math.trunc(epochSeconds);
@@ -58,21 +58,12 @@ function getTimeOrigin(): number {
  * @param performanceNow
  */
 export function hrTime(performanceNow?: number): api.HrTime {
-  const timeOrigin = numberToHrtime(getTimeOrigin());
-  const now = numberToHrtime(
+  const timeOrigin = epochMillisToHrTime(getTimeOrigin());
+  const now = epochMillisToHrTime(
     typeof performanceNow === 'number' ? performanceNow : performance.now()
   );
 
-  let seconds = timeOrigin[0] + now[0];
-  let nanos = timeOrigin[1] + now[1];
-
-  // Nanoseconds
-  if (nanos > SECOND_TO_NANOSECONDS) {
-    nanos -= SECOND_TO_NANOSECONDS;
-    seconds += 1;
-  }
-
-  return [seconds, nanos];
+  return addHrTimes(timeOrigin, now);
 }
 
 /**
@@ -90,10 +81,10 @@ export function timeInputToHrTime(time: api.TimeInput): api.HrTime {
       return hrTime(time);
     } else {
       // epoch milliseconds or performance.timeOrigin
-      return numberToHrtime(time);
+      return epochMillisToHrTime(time);
     }
   } else if (time instanceof Date) {
-    return numberToHrtime(time.getTime());
+    return epochMillisToHrTime(time.getTime());
   } else {
     throw TypeError('Invalid input type');
   }
@@ -181,3 +172,14 @@ export function isTimeInput(value: unknown): value is api.HrTime | number | Date
     value instanceof Date
   );
 }
+
+export function addHrTimes(time1: api.HrTime, time2: api.HrTime): api.HrTime {
+  const out: api.HrTime = [time1[0] + time2[0], time1[1] + time2[1]];
+
+  if(out[1] > SECOND_TO_NANOSECONDS) {
+    out[0] = out[0] + Math.floor(out[1] / SECOND_TO_NANOSECONDS);
+    out[1] = out[1] % SECOND_TO_NANOSECONDS;
+  }
+
+  return out;
+}

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

@@ -14,17 +14,32 @@
  * limitations under the License.
  */
 
-import * as api from '@opentelemetry/api';
-import { Context, HrTime, SpanAttributeValue } from '@opentelemetry/api';
 import {
-  Clock,
+  Context,
+  diag,
+  Exception,
+  HrTime,
+  Link,
+  Span as APISpan,
+  SpanAttributes,
+  SpanAttributeValue,
+  SpanContext,
+  SpanKind,
+  SpanStatus,
+  SpanStatusCode,
+  TimeInput
+} from '@opentelemetry/api';
+import {
+  addHrTimes,
+  epochMillisToHrTime,
+  hrTime,
   hrTimeDuration,
   InstrumentationLibrary,
   isAttributeValue,
   isTimeInput,
+  isTimeInputHrTime,
   otperformance,
-  sanitizeAttributes,
-  timeInputToHrTime
+  sanitizeAttributes
 } from '@opentelemetry/core';
 import { Resource } from '@opentelemetry/resources';
 import { SemanticAttributes } from '@opentelemetry/semantic-conventions';
@@ -38,29 +53,33 @@ import { SpanLimits } from './types';
 /**
  * This class represents a span.
  */
-export class Span implements api.Span, ReadableSpan {
+export class Span implements APISpan, ReadableSpan {
   // Below properties are included to implement ReadableSpan for export
   // purposes but are not intended to be written-to directly.
-  private readonly _spanContext: api.SpanContext;
-  readonly kind: api.SpanKind;
+  private readonly _spanContext: SpanContext;
+  readonly kind: SpanKind;
   readonly parentSpanId?: string;
-  readonly attributes: api.SpanAttributes = {};
-  readonly links: api.Link[] = [];
+  readonly attributes: SpanAttributes = {};
+  readonly links: Link[] = [];
   readonly events: TimedEvent[] = [];
-  readonly startTime: api.HrTime;
+  readonly startTime: HrTime;
   readonly resource: Resource;
   readonly instrumentationLibrary: InstrumentationLibrary;
   name: string;
-  status: api.SpanStatus = {
-    code: api.SpanStatusCode.UNSET,
+  status: SpanStatus = {
+    code: SpanStatusCode.UNSET,
   };
-  endTime: api.HrTime = [0, 0];
+  endTime: HrTime = [0, 0];
   private _ended = false;
-  private _duration: api.HrTime = [-1, -1];
+  private _duration: HrTime = [-1, -1];
   private readonly _spanProcessor: SpanProcessor;
   private readonly _spanLimits: SpanLimits;
   private readonly _attributeValueLengthLimit: number;
-  private readonly _clock: Clock;
+
+  private readonly _performanceStartTime: number;
+  private readonly _performanceOffset: number;
+  private readonly _startTimeProvided: boolean;
+
 
   /**
    * Constructs a new Span instance.
@@ -71,20 +90,27 @@ export class Span implements api.Span, ReadableSpan {
     parentTracer: Tracer,
     context: Context,
     spanName: string,
-    spanContext: api.SpanContext,
-    kind: api.SpanKind,
+    spanContext: SpanContext,
+    kind: SpanKind,
     parentSpanId?: string,
-    links: api.Link[] = [],
-    startTime?: api.TimeInput,
-    clock: Clock = otperformance,
+    links: Link[] = [],
+    startTime?: TimeInput,
+    _deprecatedClock?: unknown, // keeping this argument even though it is unused to ensure backwards compatibility
   ) {
-    this._clock = clock;
     this.name = spanName;
     this._spanContext = spanContext;
     this.parentSpanId = parentSpanId;
     this.kind = kind;
     this.links = links;
-    this.startTime = timeInputToHrTime(startTime ?? clock.now());
+
+    const now = Date.now();
+    this._performanceStartTime = otperformance.now();
+    this._performanceOffset = now - this._performanceStartTime;
+    this._startTimeProvided = startTime != null;
+
+
+    this.startTime = this._getTime(startTime ?? now);
+
     this.resource = parentTracer.resource;
     this.instrumentationLibrary = parentTracer.instrumentationLibrary;
     this._spanLimits = parentTracer.getSpanLimits();
@@ -93,19 +119,19 @@ export class Span implements api.Span, ReadableSpan {
     this._attributeValueLengthLimit = this._spanLimits.attributeValueLengthLimit || 0;
   }
 
-  spanContext(): api.SpanContext {
+  spanContext(): SpanContext {
     return this._spanContext;
   }
 
   setAttribute(key: string, value?: SpanAttributeValue): this;
   setAttribute(key: string, value: unknown): this {
     if (value == null || this._isSpanEnded()) return this;
     if (key.length === 0) {
-      api.diag.warn(`Invalid attribute key: ${key}`);
+      diag.warn(`Invalid attribute key: ${key}`);
       return this;
     }
     if (!isAttributeValue(value)) {
-      api.diag.warn(`Invalid attribute value set for key: ${key}`);
+      diag.warn(`Invalid attribute value set for key: ${key}`);
       return this;
     }
 
@@ -120,7 +146,7 @@ export class Span implements api.Span, ReadableSpan {
     return this;
   }
 
-  setAttributes(attributes: api.SpanAttributes): this {
+  setAttributes(attributes: SpanAttributes): this {
     for (const [k, v] of Object.entries(attributes)) {
       this.setAttribute(k, v);
     }
@@ -132,42 +158,40 @@ export class Span implements api.Span, ReadableSpan {
    * @param name Span Name
    * @param [attributesOrStartTime] Span attributes or start time
    *     if type is {@type TimeInput} and 3rd param is undefined
-   * @param [startTime] Specified start time for the event
+   * @param [timeStamp] Specified time stamp for the event
    */
   addEvent(
     name: string,
-    attributesOrStartTime?: api.SpanAttributes | api.TimeInput,
-    startTime?: api.TimeInput
+    attributesOrStartTime?: SpanAttributes | TimeInput,
+    timeStamp?: TimeInput
   ): this {
     if (this._isSpanEnded()) return this;
     if (this._spanLimits.eventCountLimit === 0) {
-      api.diag.warn('No events allowed.');
+      diag.warn('No events allowed.');
       return this;
     }
     if (this.events.length >= this._spanLimits.eventCountLimit!) {
-      api.diag.warn('Dropping extra events.');
+      diag.warn('Dropping extra events.');
       this.events.shift();
     }
+
     if (isTimeInput(attributesOrStartTime)) {
-      if (typeof startTime === 'undefined') {
-        startTime = attributesOrStartTime as api.TimeInput;
+      if (!isTimeInput(timeStamp)) {
+        timeStamp = attributesOrStartTime;
       }
       attributesOrStartTime = undefined;
     }
-    if (typeof startTime === 'undefined') {
-      startTime = this._clock.now();
-    }
 
     const attributes = sanitizeAttributes(attributesOrStartTime);
     this.events.push({
       name,
       attributes,
-      time: timeInputToHrTime(startTime),
+      time: this._getTime(timeStamp),
     });
     return this;
   }
 
-  setStatus(status: api.SpanStatus): this {
+  setStatus(status: SpanStatus): this {
     if (this._isSpanEnded()) return this;
     this.status = status;
     return this;
@@ -179,18 +203,18 @@ export class Span implements api.Span, ReadableSpan {
     return this;
   }
 
-  end(endTime?: api.TimeInput): void {
+  end(endTime?: TimeInput): void {
     if (this._isSpanEnded()) {
-      api.diag.error('You can only call end() on a span once.');
+      diag.error('You can only call end() on a span once.');
       return;
     }
     this._ended = true;
 
-    this.endTime = timeInputToHrTime(endTime ?? this._clock.now());
+    this.endTime = this._getTime(endTime);
     this._duration = hrTimeDuration(this.startTime, this.endTime);
 
     if (this._duration[0] < 0) {
-      api.diag.warn(
+      diag.warn(
         'Inconsistent start and end time, startTime > endTime. Setting span duration to 0ms.',
         this.startTime,
         this.endTime
@@ -202,12 +226,41 @@ export class Span implements api.Span, ReadableSpan {
     this._spanProcessor.onEnd(this);
   }
 
+  private _getTime(inp?: TimeInput): HrTime {
+    if (typeof inp === 'number' && inp < otperformance.now()) {
+      // must be a performance timestamp
+      // apply correction and convert to hrtime
+      return hrTime(inp + this._performanceOffset);
+    }
+
+    if (typeof inp === 'number') {
+      return epochMillisToHrTime(inp);
+    }
+
+    if (inp instanceof Date) {
+      return epochMillisToHrTime(inp.valueOf());
+    }
+
+    if (isTimeInputHrTime(inp)) {
+      return inp;
+    }
+
+    if (this._startTimeProvided) {
+      // if user provided a time for the start manually
+      // we can't use duration to calculate event/end times
+      return epochMillisToHrTime(Date.now());
+    }
+
+    const msDuration = otperformance.now() - this._performanceStartTime;
+    return addHrTimes(this.startTime, epochMillisToHrTime(msDuration));
+  }
+
   isRecording(): boolean {
     return this._ended === false;
   }
 
-  recordException(exception: api.Exception, time: api.TimeInput = this._clock.now()): void {
-    const attributes: api.SpanAttributes = {};
+  recordException(exception: Exception, time?: TimeInput): void {
+    const attributes: SpanAttributes = {};
     if (typeof exception === 'string') {
       attributes[SemanticAttributes.EXCEPTION_MESSAGE] = exception;
     } else if (exception) {
@@ -233,11 +286,11 @@ export class Span implements api.Span, ReadableSpan {
     ) {
       this.addEvent(ExceptionEventName, attributes, time);
     } else {
-      api.diag.warn(`Failed to record an exception ${exception}`);
+      diag.warn(`Failed to record an exception ${exception}`);
     }
   }
 
-  get duration(): api.HrTime {
+  get duration(): HrTime {
     return this._duration;
   }
 
@@ -247,7 +300,7 @@ export class Span implements api.Span, ReadableSpan {
 
   private _isSpanEnded(): boolean {
     if (this._ended) {
-      api.diag.warn(`Can not execute the operation on ended Span {traceId: ${this._spanContext.traceId}, spanId: ${this._spanContext.spanId}}`);
+      diag.warn(`Can not execute the operation on ended Span {traceId: ${this._spanContext.traceId}, spanId: ${this._spanContext.spanId}}`);
     }
     return this._ended;
   }
@@ -279,7 +332,7 @@ export class Span implements api.Span, ReadableSpan {
     // Check limit
     if (limit <= 0) {
       // Negative values are invalid, so do not truncate
-      api.diag.warn(`Attribute value limit must be positive, got ${limit}`);
+      diag.warn(`Attribute value limit must be positive, got ${limit}`);
       return value;
     }
 

packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts

@@ -136,6 +136,8 @@ describe('Span', () => {
       spanContext,
       SpanKind.SERVER
     );
+    // @ts-expect-error writing readonly property. performance time origin is mocked to return ms value of [1,1]
+    span['_performanceOffset'] = 0;
     span.end(hrTimeToMilliseconds(span.startTime) - 1);
     assert.ok(hrTimeToNanoseconds(span.duration) >= 0);
   });
@@ -1088,6 +1090,8 @@ describe('Span', () => {
           spanContext,
           SpanKind.CLIENT
         );
+        // @ts-expect-error writing readonly property. performance time origin is mocked to return ms value of [1,1]
+        span['_performanceOffset'] = 0;
         assert.strictEqual(span.events.length, 0);
         span.recordException('boom', [0, 123]);
         const event = span.events[0];