From 5d8dd46e4c06cea914bd3ddce9437f6e32a085ed Mon Sep 17 00:00:00 2001 From: Daniel Dyla Date: Mon, 21 Nov 2022 13:18:42 -0500 Subject: [PATCH] fix(tracing): make spans resilient to performance clock drift --- CHANGELOG.md | 1 + .../opentelemetry-core/src/common/time.ts | 34 ++-- .../opentelemetry-sdk-trace-base/src/Span.ts | 153 ++++++++++++------ .../test/common/Span.test.ts | 4 + 4 files changed, 127 insertions(+), 65 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index ab76cfe6178..f4d5f710ca1 100644 --- a/CHANGELOG.md +++ b/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 [#3384](https://github.com/open-telemetry/opentelemetry-js/pull/3384) @dyladan ### :books: (Refine Doc) diff --git a/packages/opentelemetry-core/src/common/time.ts b/packages/opentelemetry-core/src/common/time.ts index 52a3fc0fd19..ce197e400a2 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 epochMillisToHrTime(epochMillis: number): api.HrTime { const epochSeconds = epochMillis / 1000; // Decimals only. const seconds = Math.trunc(epochSeconds); @@ -44,7 +44,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; @@ -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; +} diff --git a/packages/opentelemetry-sdk-trace-base/src/Span.ts b/packages/opentelemetry-sdk-trace-base/src/Span.ts index 058507b7f7b..b73be3f2544 100644 --- a/packages/opentelemetry-sdk-trace-base/src/Span.ts +++ b/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'; @@ -35,32 +50,38 @@ import { TimedEvent } from './TimedEvent'; import { Tracer } from './Tracer'; import { SpanLimits } from './types'; +const MILLIS_TO_NANOS = 1000000; + /** * 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 +92,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 = performance.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,7 +121,7 @@ export class Span implements api.Span, ReadableSpan { this._attributeValueLengthLimit = this._spanLimits.attributeValueLengthLimit || 0; } - spanContext(): api.SpanContext { + spanContext(): SpanContext { return this._spanContext; } @@ -101,11 +129,11 @@ export class Span implements api.Span, ReadableSpan { 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 +148,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 +160,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 +205,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 +228,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 +288,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 +302,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 +334,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; } diff --git a/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts b/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts index 792c1f88dfd..2e57e81881b 100644 --- a/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts +++ b/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];