diff --git a/src/libs/telemetry/activeSpans.ts b/src/libs/telemetry/activeSpans.ts index e0fd5715a6cb..bc74a6475253 100644 --- a/src/libs/telemetry/activeSpans.ts +++ b/src/libs/telemetry/activeSpans.ts @@ -2,7 +2,7 @@ import CONST from '@src/CONST'; import type {Span, SpanAttributeValue, StartSpanOptions} from '@sentry/core'; -import {SPAN_STATUS_OK} from '@sentry/core'; +import {SPAN_STATUS_OK, spanTimeInputToSeconds} from '@sentry/core'; import * as Sentry from '@sentry/react-native'; import {AppState} from 'react-native'; @@ -13,6 +13,17 @@ type ActiveSpanEntry = { const activeSpans = new Map(); +function getPerformanceStartTimeForLog(startTime: StartSpanOptions['startTime']): number { + const performanceTimestamp = performance.now(); + if (startTime === undefined) { + return performanceTimestamp; + } + + // Sentry start times are Unix timestamps, while performance.now() is relative to the process start. Translate the timestamp once so elapsed time stays monotonic. + const epochStartTime = spanTimeInputToSeconds(startTime) * 1000; + return performanceTimestamp - (Date.now() - epochStartTime); +} + function startSpan(spanId: string, options: StartSpanOptions) { if ((AppState.currentState ?? CONST.APP_STATE.ACTIVE) !== CONST.APP_STATE.ACTIVE) { return; @@ -26,12 +37,7 @@ function startSpan(spanId: string, options: StartSpanOptions) { }); const span = Sentry.startInactiveSpan(options); - let startTimeForLog: number; - if (typeof options.startTime === 'number') { - startTimeForLog = options.startTime; - } else { - startTimeForLog = performance.now(); - } + const startTimeForLog = getPerformanceStartTimeForLog(options.startTime); activeSpans.set(spanId, {span, startTimeForLog}); @@ -45,9 +51,9 @@ function endSpan(spanId: string) { return; } const {span, startTimeForLog} = entry; - const now = performance.now(); - const durationMs = Math.round(now - startTimeForLog); - console.debug(`[Sentry][${spanId}] Ending span (${durationMs}ms)`, {spanId, durationMs, timestamp: now, attributes: Sentry.spanToJSON(span).data}); + const performanceTimestamp = performance.now(); + const durationMs = Math.round(performanceTimestamp - startTimeForLog); + console.debug(`[Sentry][${spanId}] Ending span (${durationMs}ms)`, {spanId, durationMs, timestamp: Date.now(), attributes: Sentry.spanToJSON(span).data}); span.setStatus({code: SPAN_STATUS_OK}); span.setAttribute(CONST.TELEMETRY.ATTRIBUTE_FINISHED_MANUALLY, true); diff --git a/tests/unit/ActiveSpansTest.ts b/tests/unit/ActiveSpansTest.ts new file mode 100644 index 000000000000..3c34f2dae9fa --- /dev/null +++ b/tests/unit/ActiveSpansTest.ts @@ -0,0 +1,35 @@ +import {endSpan, startSpan} from '@libs/telemetry/activeSpans'; + +import CONST from '@src/CONST'; + +jest.mock('@sentry/react-native', () => ({ + startInactiveSpan: () => ({ + setAttribute: jest.fn(), + setStatus: jest.fn(), + end: jest.fn(), + }), + spanToJSON: () => ({data: {}}), +})); + +afterEach(() => { + jest.restoreAllMocks(); +}); + +describe('activeSpans', () => { + it('calculates the duration from an epoch start time using the monotonic clock', () => { + const dateNowSpy = jest.spyOn(Date, 'now').mockReturnValue(1_786_362_201_500); + const performanceNowSpy = jest.spyOn(performance, 'now').mockReturnValue(10_000); + const consoleDebugSpy = jest.spyOn(console, 'debug').mockImplementation(() => {}); + + startSpan(CONST.TELEMETRY.SPAN_APP_STARTUP_NETWORK_REQUEST, { + name: CONST.TELEMETRY.SPAN_APP_STARTUP_NETWORK_REQUEST, + startTime: 1_786_362_201_000, + }); + + dateNowSpy.mockReturnValue(1_786_362_201_750); + performanceNowSpy.mockReturnValue(10_250); + endSpan(CONST.TELEMETRY.SPAN_APP_STARTUP_NETWORK_REQUEST); + + expect(consoleDebugSpy).toHaveBeenLastCalledWith(expect.stringContaining('Ending span (750ms)'), expect.objectContaining({durationMs: 750, timestamp: 1_786_362_201_750})); + }); +});