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

* fix(tracing): make spans resilient to performance clock drift * Fix changelog * Do not export getTimeOrigin * Apply shift to shim spans * Lint * Lint * Remove unused imports * Fix drift calculation * Remove bad import * Use Date.now for fetch span end * Fetch changelog * Test addHrTimes * lint * lint * lint * Fix flaky test * lint * Use perf timer for perf API * Apply date fix to xhr * Changelog * lint * Revert to previous addHrTimes impl * Review comments * Fix flaky test
open-telemetry · Jan 11, 2023 · 969bb62 · 969bb62
1 parent 2dcc898
commit 969bb62
Show file tree

Hide file tree

Showing 9 changed files with 190 additions and 82 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -22,6 +22,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
 * fix(selenium-tests): updated webpack version for selenium test issue [#3456](https://github.com/open-telemetry/opentelemetry-js/issues/3456) @SaumyaBhushan
 * fix(sdk-metrics): fix duplicated registration of metrics for collectors [#3488](https://github.com/open-telemetry/opentelemetry-js/pull/3488) @legendecas
 * fix(core): fix precision loss in numberToHrtime [#3480](https://github.com/open-telemetry/opentelemetry-js/pull/3480) @legendecas

diff --git a/experimental/CHANGELOG.md b/experimental/CHANGELOG.md
@@ -23,6 +23,8 @@ All notable changes to experimental packages in this project will be documented
 * fix(prometheus-sanitization): replace repeated `_` with a single `_` [3470](https://github.com/open-telemetry/opentelemetry-js/pull/3470) @samimusallam
 * fix(prometheus-serializer): correct string used for NaN [#3477](https://github.com/open-telemetry/opentelemetry-js/pull/3477) @JacksonWeber
 * fix(instrumentation-http): close server span when response finishes [#3407](https://github.com/open-telemetry/opentelemetry-js/pull/3407) @legendecas
+* fix(instrumentation-fetch): make spans resilient to clock drift by using Date.now [#3434](https://github.com/open-telemetry/opentelemetry-js/pull/3434) @dyladan
+* fix(instrumentation-xml-http-request): make spans resilient to clock drift by using Date.now [#3434](https://github.com/open-telemetry/opentelemetry-js/pull/3434) @dyladan
 * fix(sdk-node): fix exporter to be read only OTEL_TRACES_EXPORTER is set to a valid exporter [3492] @svetlanabrennan
 
 ### :books: (Refine Doc)

diff --git a/experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts b/experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts
@@ -276,12 +276,13 @@ export class FetchInstrumentation extends InstrumentationBase<
     spanData: SpanData,
     response: FetchResponse
   ) {
-    const endTime = core.hrTime();
+    const endTime = core.millisToHrTime(Date.now());
+    const performanceEndTime = core.hrTime();
     this._addFinalSpanAttributes(span, response);
 
     setTimeout(() => {
       spanData.observer?.disconnect();
-      this._findResourceAndAddNetworkEvents(span, spanData, endTime);
+      this._findResourceAndAddNetworkEvents(span, spanData, performanceEndTime);
       this._tasksCount--;
       this._clearResources();
       span.end(endTime);

diff --git a/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/xhr.ts b/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/xhr.ts
@@ -389,7 +389,8 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase<XMLHttpRe
     function endSpanTimeout(
       eventName: string,
       xhrMem: XhrMem,
-      endTime: api.HrTime
+      performanceEndTime: api.HrTime,
+      endTime: number
     ) {
       const callbackToRemoveEvents = xhrMem.callbackToRemoveEvents;
 
@@ -405,7 +406,7 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase<XMLHttpRe
           span,
           spanUrl,
           sendStartTime,
-          endTime
+          performanceEndTime
         );
         span.addEvent(eventName, endTime);
         plugin._addFinalSpanAttributes(span, xhrMem, spanUrl);
@@ -427,13 +428,14 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase<XMLHttpRe
       if (xhrMem.span) {
         plugin._applyAttributesAfterXHR(xhrMem.span, xhr);
       }
-      const endTime = hrTime();
+      const performanceEndTime = hrTime();
+      const endTime = Date.now();
 
       // the timeout is needed as observer doesn't have yet information
       // when event "load" is called. Also the time may differ depends on
       // browser and speed of computer
       setTimeout(() => {
-        endSpanTimeout(eventName, xhrMem, endTime);
+        endSpanTimeout(eventName, xhrMem, performanceEndTime, endTime);
       }, OBSERVER_WAIT_TIME_MS);
     }
 

diff --git a/packages/opentelemetry-core/src/common/time.ts b/packages/opentelemetry-core/src/common/time.ts
@@ -27,7 +27,7 @@ const SECOND_TO_NANOSECONDS = Math.pow(10, NANOSECOND_DIGITS);
  * Converts a number of milliseconds from epoch to HrTime([seconds, remainder in nanoseconds]).
  * @param epochMillis
  */
-function numberToHrtime(epochMillis: number): api.HrTime {
+export function millisToHrTime(epochMillis: number): api.HrTime {
   const epochSeconds = epochMillis / 1000;
   // Decimals only.
   const seconds = Math.trunc(epochSeconds);
@@ -36,7 +36,7 @@ function numberToHrtime(epochMillis: number): api.HrTime {
   return [seconds, nanos];
 }
 
-function getTimeOrigin(): number {
+export function getTimeOrigin(): number {
   let timeOrigin = performance.timeOrigin;
   if (typeof timeOrigin !== 'number') {
     const perf: TimeOriginLegacy = performance as unknown as TimeOriginLegacy;
@@ -50,21 +50,12 @@ function getTimeOrigin(): number {
  * @param performanceNow
  */
 export function hrTime(performanceNow?: number): api.HrTime {
-  const timeOrigin = numberToHrtime(getTimeOrigin());
-  const now = numberToHrtime(
+  const timeOrigin = millisToHrTime(getTimeOrigin());
+  const now = millisToHrTime(
     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);
 }
 
 /**
@@ -82,10 +73,10 @@ export function timeInputToHrTime(time: api.TimeInput): api.HrTime {
       return hrTime(time);
     } else {
       // epoch milliseconds or performance.timeOrigin
-      return numberToHrtime(time);
+      return millisToHrTime(time);
     }
   } else if (time instanceof Date) {
-    return numberToHrtime(time.getTime());
+    return millisToHrTime(time.getTime());
   } else {
     throw TypeError('Invalid input type');
   }
@@ -175,3 +166,18 @@ export function isTimeInput(
     value instanceof Date
   );
 }
+
+/**
+ * Given 2 HrTime formatted times, return their sum as an HrTime.
+ */
+export function addHrTimes(time1: api.HrTime, time2: api.HrTime): api.HrTime {
+  const out = [time1[0] + time2[0], time1[1] + time2[1]] as api.HrTime;
+
+  // Nanoseconds
+  if (out[1] >= SECOND_TO_NANOSECONDS) {
+    out[1] -= SECOND_TO_NANOSECONDS;
+    out[0] += 1;
+  }
+
+  return out;
+}
diff --git a/packages/opentelemetry-core/test/common/time.test.ts b/packages/opentelemetry-core/test/common/time.test.ts
@@ -27,6 +27,7 @@ import {
   hrTimeToMicroseconds,
   hrTimeToTimeStamp,
   isTimeInput,
+  addHrTimes,
 } from '../../src/common/time';
 
 describe('time', () => {
@@ -224,4 +225,34 @@ describe('time', () => {
       assert.strictEqual(isTimeInput(undefined), false);
     });
   });
+
+  describe('#addHrTimes', () => {
+    const NANOSECOND_DIGITS = 9;
+    const SECOND_TO_NANOSECONDS = Math.pow(10, NANOSECOND_DIGITS);
+
+    it('should add two positive times', () => {
+      const output = addHrTimes([10, 20], [30, 40]);
+      assert.deepStrictEqual(output, [40, 60]);
+    });
+    it('should add two negative times', () => {
+      const output = addHrTimes([-10, 20], [-30, 40]);
+      assert.deepStrictEqual(output, [-40, 60]);
+    });
+    it('should add a positive and negative time (result positive)', () => {
+      const output = addHrTimes([-10, 20], [30, 40]);
+      assert.deepStrictEqual(output, [20, 60]);
+    });
+    it('should add a positive and negative time (result negative)', () => {
+      const output = addHrTimes([10, 20], [-30, 40]);
+      assert.deepStrictEqual(output, [-20, 60]);
+    });
+    it('should overflow nanoseconds to seconds', () => {
+      const output = addHrTimes([10, SECOND_TO_NANOSECONDS - 10], [10, 20]);
+      assert.deepStrictEqual(output, [21, 10]);
+    });
+    it('should overflow nanoseconds to seconds (negative)', () => {
+      const output = addHrTimes([-10, SECOND_TO_NANOSECONDS - 10], [-10, 20]);
+      assert.deepStrictEqual(output, [-19, 10]);
+    });
+  });
 });