From 7ad5c9daa024f47cbf6d999be24165fe1a5b10e0 Mon Sep 17 00:00:00 2001 From: Chengzhong Wu Date: Tue, 3 Jan 2023 17:54:49 +0800 Subject: [PATCH] fix(instrumentation): fix web instrumentation span clock drifts --- .../src/fetch.ts | 90 ++++++++++++++----- .../src/types.ts | 3 + .../src/types.ts | 8 +- .../src/xhr.ts | 76 ++++++++++++---- .../opentelemetry-core/src/common/time.ts | 33 ++++--- .../test/common/time.test.ts | 43 +++++++++ .../opentelemetry-sdk-trace-web/src/utils.ts | 89 +++++++++++++++--- .../test/utils.test.ts | 28 ++++-- 8 files changed, 299 insertions(+), 71 deletions(-) diff --git a/experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts b/experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts index 14862a8e814..19b90fc9897 100644 --- a/experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts +++ b/experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts @@ -27,7 +27,12 @@ import { AttributeNames } from './enums/AttributeNames'; import { SemanticAttributes } from '@opentelemetry/semantic-conventions'; import { FetchError, FetchResponse, SpanData } from './types'; import { VERSION } from './version'; -import { _globalThis } from '@opentelemetry/core'; +import { + hrTimeAdd, + hrTimeDuration, + numberToHrtime, + _globalThis, +} from '@opentelemetry/core'; // how long to wait for observer to collect information about resources // this is needed as event "load" is called before observer @@ -96,21 +101,37 @@ export class FetchInstrumentation extends InstrumentationBase< */ private _addChildSpan( span: api.Span, + spanData: SpanData, corsPreFlightRequest: PerformanceResourceTiming ): void { + const preflightStartTime = this._calcEpochHrTime( + spanData, + numberToHrtime( + corsPreFlightRequest[web.PerformanceTimingNames.FETCH_START] + ) + ); + const preflightEndTime = this._calcEpochHrTime( + spanData, + numberToHrtime( + corsPreFlightRequest[web.PerformanceTimingNames.RESPONSE_END] + ) + ); const childSpan = this.tracer.startSpan( 'CORS Preflight', { - startTime: corsPreFlightRequest[web.PerformanceTimingNames.FETCH_START], + startTime: preflightStartTime, }, api.trace.setSpan(api.context.active(), span) ); if (!this._getConfig().ignoreNetworkEvents) { - web.addSpanNetworkEvents(childSpan, corsPreFlightRequest); + web.addSpanNetworkEvents( + childSpan, + corsPreFlightRequest, + spanData.startTime, + spanData.startHrTime + ); } - childSpan.end( - corsPreFlightRequest[web.PerformanceTimingNames.RESPONSE_END] - ); + childSpan.end(preflightEndTime); } /** @@ -190,7 +211,8 @@ export class FetchInstrumentation extends InstrumentationBase< */ private _createSpan( url: string, - options: Partial = {} + options: Partial = {}, + startTime: api.HrTime ): api.Span | undefined { if (core.isUrlIgnored(url, this._getConfig().ignoreUrls)) { this._diag.debug('ignoring span as url matches ignored url'); @@ -205,21 +227,22 @@ export class FetchInstrumentation extends InstrumentationBase< [SemanticAttributes.HTTP_METHOD]: method, [SemanticAttributes.HTTP_URL]: url, }, + startTime, }); } /** * Finds appropriate resource and add network events to the span * @param span - * @param resourcesObserver + * @param spanData * @param endTime */ private _findResourceAndAddNetworkEvents( span: api.Span, - resourcesObserver: SpanData, + spanData: SpanData, endTime: api.HrTime ): void { - let resources: PerformanceResourceTiming[] = resourcesObserver.entries; + let resources: PerformanceResourceTiming[] = spanData.entries; if (!resources.length) { if (!performance.getEntriesByType) { return; @@ -232,8 +255,8 @@ export class FetchInstrumentation extends InstrumentationBase< ) as PerformanceResourceTiming[]; } const resource = web.getResource( - resourcesObserver.spanUrl, - resourcesObserver.startTime, + spanData.spanUrl, + spanData.startHrTime, endTime, resources, this._usedResources, @@ -246,11 +269,16 @@ export class FetchInstrumentation extends InstrumentationBase< const corsPreFlightRequest = resource.corsPreFlightRequest; if (corsPreFlightRequest) { - this._addChildSpan(span, corsPreFlightRequest); + this._addChildSpan(span, spanData, corsPreFlightRequest); this._markResourceAsUsed(corsPreFlightRequest); } if (!this._getConfig().ignoreNetworkEvents) { - web.addSpanNetworkEvents(span, mainRequest); + web.addSpanNetworkEvents( + span, + mainRequest, + spanData.startTime, + spanData.startHrTime + ); } } } @@ -276,18 +304,31 @@ export class FetchInstrumentation extends InstrumentationBase< spanData: SpanData, response: FetchResponse ) { - const endTime = core.hrTime(); + const endHrTime = core.hrTime(); this._addFinalSpanAttributes(span, response); setTimeout(() => { spanData.observer?.disconnect(); - this._findResourceAndAddNetworkEvents(span, spanData, endTime); + this._findResourceAndAddNetworkEvents(span, spanData, endHrTime); this._tasksCount--; this._clearResources(); + + const endTime = this._calcEpochHrTime(spanData, endHrTime); span.end(endTime); }, OBSERVER_WAIT_TIME_MS); } + /** + * Calculate the epoch time from the given span data and the hrTime. + */ + private _calcEpochHrTime(spanData: SpanData, hrTime: api.HrTime): api.HrTime { + // Calculate the duration from the hrTimes. + const duration = hrTimeDuration(spanData.startHrTime, hrTime); + // Calculate the endTime from the epoch and the duration. + const endTime = hrTimeAdd(spanData.startTime, duration); + return endTime; + } + /** * Patches the constructor of fetch */ @@ -300,15 +341,19 @@ export class FetchInstrumentation extends InstrumentationBase< ): Promise { const self = this; const url = web.parseUrl( - args[0] instanceof Request ? args[0].url : args[0] + args[0] instanceof Request ? args[0].url : String(args[0]) ).href; const options = args[0] instanceof Request ? args[0] : args[1] || {}; - const createdSpan = plugin._createSpan(url, options); + const spanData = plugin._prepareSpanData(url); + const createdSpan = plugin._createSpan( + url, + options, + spanData.startTime + ); if (!createdSpan) { return original.apply(this, args); } - const spanData = plugin._prepareSpanData(url); function endSpanOnError(span: api.Span, error: FetchError) { plugin._applyAttributesAfterFetch(span, options, error); @@ -431,10 +476,11 @@ export class FetchInstrumentation extends InstrumentationBase< * @param spanUrl */ private _prepareSpanData(spanUrl: string): SpanData { - const startTime = core.hrTime(); + const startTime = numberToHrtime(Date.now()); + const startHrTime = core.hrTime(); const entries: PerformanceResourceTiming[] = []; if (typeof PerformanceObserver !== 'function') { - return { entries, startTime, spanUrl }; + return { entries, startHrTime, startTime, spanUrl }; } const observer = new PerformanceObserver(list => { @@ -448,7 +494,7 @@ export class FetchInstrumentation extends InstrumentationBase< observer.observe({ entryTypes: ['resource'], }); - return { entries, observer, startTime, spanUrl }; + return { entries, observer, startHrTime, startTime, spanUrl }; } /** diff --git a/experimental/packages/opentelemetry-instrumentation-fetch/src/types.ts b/experimental/packages/opentelemetry-instrumentation-fetch/src/types.ts index 7f2e5c6d73a..f7d1c87316a 100644 --- a/experimental/packages/opentelemetry-instrumentation-fetch/src/types.ts +++ b/experimental/packages/opentelemetry-instrumentation-fetch/src/types.ts @@ -41,5 +41,8 @@ export interface SpanData { entries: PerformanceResourceTiming[]; observer?: PerformanceObserver; spanUrl: string; + // startTime of the span from the epoch. startTime: api.HrTime; + // startTime of the span used to calculate durations. + startHrTime: api.HrTime; } diff --git a/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/types.ts b/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/types.ts index 430e9e217bc..62422fdfc6d 100644 --- a/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/types.ts +++ b/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/types.ts @@ -55,8 +55,12 @@ export interface XhrMem { span: api.Span; // span url - not available on types.Span spanUrl?: string; - // startTime of send function - used to filter cors preflight requests - sendStartTime?: api.HrTime; + // startTime of the span from the epoch. + startTime: api.HrTime; + // startTime of the span used to calculate durations. + startHrTime: api.HrTime; + // startTime of send function - used to filter cors preflight requests. + sendStartHrTime?: api.HrTime; // resources created between send and end plus some additional timeout createdResources?: { observer: PerformanceObserver; diff --git a/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/xhr.ts b/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/xhr.ts index 621dc73f89c..df41446b9c2 100644 --- a/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/xhr.ts +++ b/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/xhr.ts @@ -21,7 +21,14 @@ import { InstrumentationConfig, safeExecuteInTheMiddle, } from '@opentelemetry/instrumentation'; -import { hrTime, isUrlIgnored, otperformance } from '@opentelemetry/core'; +import { + hrTimeAdd, + hrTime, + hrTimeDuration, + isUrlIgnored, + numberToHrtime, + otperformance, +} from '@opentelemetry/core'; import { SemanticAttributes } from '@opentelemetry/semantic-conventions'; import { addSpanNetworkEvents, @@ -134,14 +141,29 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase { + const startTime = this._calcEpochHrTime( + xhrMem, + numberToHrtime(corsPreFlightRequest[PTN.FETCH_START]) + ); + const endTime = this._calcEpochHrTime( + xhrMem, + numberToHrtime(corsPreFlightRequest[PTN.RESPONSE_END]) + ); + const childSpan = this.tracer.startSpan('CORS Preflight', { - startTime: corsPreFlightRequest[PTN.FETCH_START], + startTime, }); - addSpanNetworkEvents(childSpan, corsPreFlightRequest); - childSpan.end(corsPreFlightRequest[PTN.RESPONSE_END]); + addSpanNetworkEvents( + childSpan, + corsPreFlightRequest, + xhrMem.startTime, + xhrMem.startHrTime + ); + childSpan.end(endTime); }); } @@ -255,10 +277,10 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase { plugin._tasksCount++; - xhrMem.sendStartTime = hrTime(); + xhrMem.sendStartHrTime = hrTime(); currentSpan.addEvent(EventNames.METHOD_SEND); this.addEventListener('abort', onAbort); diff --git a/packages/opentelemetry-core/src/common/time.ts b/packages/opentelemetry-core/src/common/time.ts index 64bc64d2d9a..46919660ec3 100644 --- a/packages/opentelemetry-core/src/common/time.ts +++ b/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 numberToHrtime(epochMillis: number): api.HrTime { const epochSeconds = epochMillis / 1000; // Decimals only. const seconds = Math.trunc(epochSeconds); @@ -63,20 +63,10 @@ export function hrTime(performanceNow?: number): api.HrTime { 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 hrTimeAdd(timeOrigin, now); } /** - * * Converts a TimeInput to an HrTime, defaults to _hrtime(). * @param time */ @@ -121,6 +111,25 @@ export function hrTimeDuration( return [seconds, nanos]; } +/** + * Calculate the arithmetic sum of two provided HrTime and return the sum + * in a new HrTime. + */ +export function hrTimeAdd(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; + } else if (out[1] < 0) { + out[0] -= 1; + // negate + out[1] += SECOND_TO_NANOSECONDS; + } + + return out; +} + /** * Convert hrTime to timestamp, for example "2019-05-14T17:00:00.000123456Z" * @param time diff --git a/packages/opentelemetry-core/test/common/time.test.ts b/packages/opentelemetry-core/test/common/time.test.ts index a8c284b9b04..37a53a32ecf 100644 --- 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, + hrTimeAdd, } from '../../src/common/time'; describe('time', () => { @@ -149,6 +150,48 @@ describe('time', () => { const output = hrTimeDuration(startTime, endTime); assert.deepStrictEqual(output, [9, 800000000]); }); + + it('should handle negative duration', () => { + const startTime: api.HrTime = [22, 400000000]; + const endTime: api.HrTime = [12, 200000000]; + + const output = hrTimeDuration(startTime, endTime); + assert.deepStrictEqual(output, [-11, 800000000]); + }); + }); + + describe('#hrTimeAdd', () => { + it('should return duration', () => { + const startTime: api.HrTime = [22, 100000000]; + const endTime: api.HrTime = [32, 800000000]; + + const output = hrTimeAdd(startTime, endTime); + assert.deepStrictEqual(output, [54, 900000000]); + }); + + it('should handle nanosecond overflow', () => { + const startTime: api.HrTime = [22, 400000000]; + const endTime: api.HrTime = [32, 800000000]; + + const output = hrTimeAdd(startTime, endTime); + assert.deepStrictEqual(output, [55, 200000000]); + }); + + it('should handle negative seconds', () => { + const startTime: api.HrTime = [22, 400000000]; + const endTime: api.HrTime = [-12, 200000000]; + + const output = hrTimeAdd(startTime, endTime); + assert.deepStrictEqual(output, [10, 600000000]); + }); + + it('should handle negative nanoseconds', () => { + const startTime: api.HrTime = [22, 400000000]; + const endTime: api.HrTime = [0, -600000000]; + + const output = hrTimeAdd(startTime, endTime); + assert.deepStrictEqual(output, [21, 800000000]); + }); }); describe('#hrTimeToTimeStamp', () => { diff --git a/packages/opentelemetry-sdk-trace-web/src/utils.ts b/packages/opentelemetry-sdk-trace-web/src/utils.ts index 30031e06235..f4c0e9d667c 100644 --- a/packages/opentelemetry-sdk-trace-web/src/utils.ts +++ b/packages/opentelemetry-sdk-trace-web/src/utils.ts @@ -22,7 +22,10 @@ import { import { PerformanceTimingNames as PTN } from './enums/PerformanceTimingNames'; import * as api from '@opentelemetry/api'; import { + hrTimeAdd, + hrTimeDuration, hrTimeToNanoseconds, + numberToHrtime, timeInputToHrTime, urlMatches, } from '@opentelemetry/core'; @@ -44,10 +47,25 @@ function getUrlNormalizingAnchor(): HTMLAnchorElement { * @param key */ // eslint-disable-next-line @typescript-eslint/no-explicit-any -export function hasKey(obj: O, key: keyof any): key is keyof O { +export function hasKey( + obj: O, + key: keyof any +): key is keyof O { return key in obj; } +function calcEpochHrTime( + startTime: api.HrTime, + startHrTime: api.HrTime, + hrTime: api.HrTime +): api.HrTime { + // Calculate the duration from the hrTimes. + const duration = hrTimeDuration(startHrTime, hrTime); + // Calculate the endTime from the epoch and the duration. + const endTime = hrTimeAdd(startTime, duration); + return endTime; +} + /** * Helper function for starting an event on span based on {@link PerformanceEntries} * @param span @@ -57,13 +75,20 @@ export function hasKey(obj: O, key: keyof any): key is keyof O { export function addSpanNetworkEvent( span: api.Span, performanceName: string, - entries: PerformanceEntries + entries: PerformanceEntries, + startTime: api.HrTime, + startHrTime: api.HrTime ): api.Span | undefined { if ( hasKey(entries, performanceName) && typeof entries[performanceName] === 'number' ) { - span.addEvent(performanceName, entries[performanceName]); + const entryTime = calcEpochHrTime( + startTime, + startHrTime, + numberToHrtime(entries[performanceName]!) + ); + span.addEvent(performanceName, entryTime); return span; } return undefined; @@ -76,17 +101,55 @@ export function addSpanNetworkEvent( */ export function addSpanNetworkEvents( span: api.Span, - resource: PerformanceEntries + resource: PerformanceEntries, + startTime: api.HrTime, + startHrTime: api.HrTime ): void { - addSpanNetworkEvent(span, PTN.FETCH_START, resource); - addSpanNetworkEvent(span, PTN.DOMAIN_LOOKUP_START, resource); - addSpanNetworkEvent(span, PTN.DOMAIN_LOOKUP_END, resource); - addSpanNetworkEvent(span, PTN.CONNECT_START, resource); - addSpanNetworkEvent(span, PTN.SECURE_CONNECTION_START, resource); - addSpanNetworkEvent(span, PTN.CONNECT_END, resource); - addSpanNetworkEvent(span, PTN.REQUEST_START, resource); - addSpanNetworkEvent(span, PTN.RESPONSE_START, resource); - addSpanNetworkEvent(span, PTN.RESPONSE_END, resource); + addSpanNetworkEvent(span, PTN.FETCH_START, resource, startTime, startHrTime); + addSpanNetworkEvent( + span, + PTN.DOMAIN_LOOKUP_START, + resource, + startTime, + startHrTime + ); + addSpanNetworkEvent( + span, + PTN.DOMAIN_LOOKUP_END, + resource, + startTime, + startHrTime + ); + addSpanNetworkEvent( + span, + PTN.CONNECT_START, + resource, + startTime, + startHrTime + ); + addSpanNetworkEvent( + span, + PTN.SECURE_CONNECTION_START, + resource, + startTime, + startHrTime + ); + addSpanNetworkEvent(span, PTN.CONNECT_END, resource, startTime, startHrTime); + addSpanNetworkEvent( + span, + PTN.REQUEST_START, + resource, + startTime, + startHrTime + ); + addSpanNetworkEvent( + span, + PTN.RESPONSE_START, + resource, + startTime, + startHrTime + ); + addSpanNetworkEvent(span, PTN.RESPONSE_END, resource, startTime, startHrTime); const encodedLength = resource[PTN.ENCODED_BODY_SIZE]; if (encodedLength !== undefined) { span.setAttribute( diff --git a/packages/opentelemetry-sdk-trace-web/test/utils.test.ts b/packages/opentelemetry-sdk-trace-web/test/utils.test.ts index 06e550c1f06..e26873deede 100644 --- a/packages/opentelemetry-sdk-trace-web/test/utils.test.ts +++ b/packages/opentelemetry-sdk-trace-web/test/utils.test.ts @@ -15,7 +15,9 @@ */ import { + hrTimeAdd, hrTimeToNanoseconds, + numberToHrtime, otperformance as performance, } from '@opentelemetry/core'; import * as core from '@opentelemetry/core'; @@ -37,6 +39,9 @@ import { import { PerformanceTimingNames as PTN } from '../src/enums/PerformanceTimingNames'; const SECOND_TO_NANOSECONDS = 1e9; +// Stub startTime and startHrTime that are identical to indicate that there is no time shifts. +const startTime: HrTime = [0, 0]; +const startHrTime: HrTime = [0, 0]; function createHrTime(startTime: HrTime, addToStart: number): HrTime { let seconds = startTime[0]; @@ -115,7 +120,7 @@ describe('utils', () => { assert.strictEqual(addEventSpy.callCount, 0); - addSpanNetworkEvents(span, entries); + addSpanNetworkEvents(span, entries, startTime, startHrTime); assert.strictEqual(addEventSpy.callCount, 9); assert.strictEqual(setAttributeSpy.callCount, 2); @@ -134,7 +139,7 @@ describe('utils', () => { assert.strictEqual(setAttributeSpy.callCount, 0); - addSpanNetworkEvents(span, entries); + addSpanNetworkEvents(span, entries, startTime, startHrTime); assert.strictEqual(addEventSpy.callCount, 0); assert.strictEqual(setAttributeSpy.callCount, 1); @@ -154,13 +159,22 @@ describe('utils', () => { assert.strictEqual(addEventSpy.callCount, 0); - addSpanNetworkEvent(span, PTN.FETCH_START, entries); + addSpanNetworkEvent( + span, + PTN.FETCH_START, + entries, + startTime, + startHrTime + ); assert.strictEqual(addEventSpy.callCount, 1); const args = addEventSpy.args[0]; assert.strictEqual(args[0], 'fetchStart'); - assert.strictEqual(args[1], value); + assert.deepStrictEqual( + args[1], + hrTimeAdd([0, 0], numberToHrtime(value)) + ); }); }); }); @@ -179,7 +193,9 @@ describe('utils', () => { addSpanNetworkEvent( span, PTN.FETCH_START, - entries as PerformanceEntries + entries as PerformanceEntries, + startTime, + startHrTime ); assert.strictEqual(addEventSpy.callCount, 0); @@ -197,7 +213,7 @@ describe('utils', () => { assert.strictEqual(addEventSpy.callCount, 0); - addSpanNetworkEvent(span, 'foo', entries); + addSpanNetworkEvent(span, 'foo', entries, startTime, startHrTime); assert.strictEqual( addEventSpy.callCount,