diff --git a/src/CONST/index.ts b/src/CONST/index.ts index 7e9324d82ecf..7ed11008133a 100644 --- a/src/CONST/index.ts +++ b/src/CONST/index.ts @@ -2919,6 +2919,7 @@ const CONST = { ATTRIBUTE_NEUTRAL_ZOOM: 'neutral_zoom', ATTRIBUTE_ODOMETER_IMAGE_TYPE: 'odometer_image_type', ATTRIBUTE_DURATION_SINCE_NATIVE_APP_STARTUP_MS: 'duration_since_native_app_startup_ms', + ATTRIBUTE_DURATION_SINCE_JS_STARTUP_MS: 'duration_since_js_startup_ms', CAPTURE_METHOD: { PHOTO: 'photo', SNAPSHOT: 'snapshot', diff --git a/src/libs/telemetry/nativeAppStartTime.ts b/src/libs/telemetry/nativeAppStartTime.ts new file mode 100644 index 000000000000..1557c310c66f --- /dev/null +++ b/src/libs/telemetry/nativeAppStartTime.ts @@ -0,0 +1,34 @@ +// Elapsed time takes the larger of the Date.now() and performance.now() deltas: Date.now() goes backwards when the +// device clock is corrected, and performance.now() stops during Android deep sleep. JS cannot tell a forward clock +// correction from sleep, so a forward correction after setup inflates the value. +let appStartAgeAtSetupMs: number | undefined; +let dateNowAtSetupMs: number | undefined; +let performanceNowAtSetupMs = 0; + +function setNativeAppStartTime(timestampMs: number | undefined) { + dateNowAtSetupMs = Date.now(); + performanceNowAtSetupMs = performance.now(); + appStartAgeAtSetupMs = timestampMs === undefined ? undefined : dateNowAtSetupMs - timestampMs; +} + +function getElapsedMsSinceSetup(): number | undefined { + if (dateNowAtSetupMs === undefined) { + return undefined; + } + return Math.max(Date.now() - dateNowAtSetupMs, performance.now() - performanceNowAtSetupMs); +} + +function getMsSinceJsStartup(): number | undefined { + const elapsedMs = getElapsedMsSinceSetup(); + return elapsedMs === undefined ? undefined : Math.round(elapsedMs); +} + +function getMsSinceNativeAppStart(): number | undefined { + const elapsedMs = getElapsedMsSinceSetup(); + if (appStartAgeAtSetupMs === undefined || elapsedMs === undefined) { + return undefined; + } + return Math.round(appStartAgeAtSetupMs + elapsedMs); +} + +export {getMsSinceJsStartup, getMsSinceNativeAppStart, setNativeAppStartTime}; diff --git a/src/pages/iou/request/step/IOURequestStepScan/components/Camera/index.native.tsx b/src/pages/iou/request/step/IOURequestStepScan/components/Camera/index.native.tsx index bf2a16230c85..6de8565eda3f 100644 --- a/src/pages/iou/request/step/IOURequestStepScan/components/Camera/index.native.tsx +++ b/src/pages/iou/request/step/IOURequestStepScan/components/Camera/index.native.tsx @@ -15,6 +15,7 @@ import HapticFeedback from '@libs/HapticFeedback'; import Log from '@libs/Log'; import ReceiptStorage from '@libs/ReceiptStorage'; import {cancelSpan, endSpanWithAttributes, getSpan, startSpan} from '@libs/telemetry/activeSpans'; +import {getMsSinceJsStartup, getMsSinceNativeAppStart} from '@libs/telemetry/nativeAppStartTime'; import captureReceipt, {shouldTakePhoto} from '@pages/iou/request/step/IOURequestStepScan/captureReceipt'; import CameraPermissionPrompt from '@pages/iou/request/step/IOURequestStepScan/components/CameraPermissionPrompt'; @@ -126,11 +127,24 @@ function Camera({onCapture, onPicked, shouldAcceptMultipleFiles = false, onLayou }; const capturePhoto = () => { + const isPhotoCapture = shouldTakePhoto({flash, hasFlash, isInLandscapeMode}); + const captureAttributes = { + [CONST.TELEMETRY.ATTRIBUTE_CAPTURE_METHOD]: isPhotoCapture ? CONST.TELEMETRY.CAPTURE_METHOD.PHOTO : CONST.TELEMETRY.CAPTURE_METHOD.SNAPSHOT, + [CONST.TELEMETRY.ATTRIBUTE_FLASH_USED]: flash && hasFlash, + }; + if (!isMultiScanEnabled) { + const msSinceNativeAppStart = getMsSinceNativeAppStart(); + const msSinceJsStartup = getMsSinceJsStartup(); startSpan(CONST.TELEMETRY.SPAN_SHUTTER_TO_CONFIRMATION, { name: CONST.TELEMETRY.SPAN_SHUTTER_TO_CONFIRMATION, op: CONST.TELEMETRY.SPAN_SHUTTER_TO_CONFIRMATION, - attributes: {[CONST.TELEMETRY.ATTRIBUTE_PLATFORM]: CONST.TELEMETRY.SPAN_PLATFORM.NATIVE}, + attributes: { + [CONST.TELEMETRY.ATTRIBUTE_PLATFORM]: CONST.TELEMETRY.SPAN_PLATFORM.NATIVE, + ...captureAttributes, + ...(msSinceNativeAppStart !== undefined && {[CONST.TELEMETRY.ATTRIBUTE_DURATION_SINCE_NATIVE_APP_STARTUP_MS]: msSinceNativeAppStart}), + ...(msSinceJsStartup !== undefined && {[CONST.TELEMETRY.ATTRIBUTE_DURATION_SINCE_JS_STARTUP_MS]: msSinceJsStartup}), + }, }); } @@ -155,16 +169,13 @@ function Camera({onCapture, onPicked, shouldAcceptMultipleFiles = false, onLayou return; } - const isPhotoCapture = shouldTakePhoto({flash, hasFlash, isInLandscapeMode}); - startSpan(CONST.TELEMETRY.SPAN_RECEIPT_CAPTURE, { name: CONST.TELEMETRY.SPAN_RECEIPT_CAPTURE, op: CONST.TELEMETRY.SPAN_RECEIPT_CAPTURE, parentSpan: getSpan(CONST.TELEMETRY.SPAN_SHUTTER_TO_CONFIRMATION), attributes: { [CONST.TELEMETRY.ATTRIBUTE_PLATFORM]: CONST.TELEMETRY.SPAN_PLATFORM.NATIVE, - [CONST.TELEMETRY.ATTRIBUTE_CAPTURE_METHOD]: isPhotoCapture ? CONST.TELEMETRY.CAPTURE_METHOD.PHOTO : CONST.TELEMETRY.CAPTURE_METHOD.SNAPSHOT, - [CONST.TELEMETRY.ATTRIBUTE_FLASH_USED]: flash && hasFlash, + ...captureAttributes, }, }); diff --git a/src/setup/telemetry/index.native.ts b/src/setup/telemetry/index.native.ts index c80a2161a58b..fa42c037253b 100644 --- a/src/setup/telemetry/index.native.ts +++ b/src/setup/telemetry/index.native.ts @@ -1,5 +1,6 @@ import Log from '@libs/Log'; import {startSpan} from '@libs/telemetry/activeSpans'; +import {setNativeAppStartTime} from '@libs/telemetry/nativeAppStartTime'; import CONST from '@src/CONST'; @@ -102,6 +103,7 @@ export default function (): void { Log.warn('[Telemetry] Failed to read native app start time from NitroModule', {error}); nativeAppStartTimeMs = undefined; } + setNativeAppStartTime(nativeAppStartTimeMs); const startupSpan = startSpan(CONST.TELEMETRY.SPAN_APP_STARTUP, { name: CONST.TELEMETRY.SPAN_APP_STARTUP, diff --git a/tests/unit/telemetryStartupMarkersTest.ts b/tests/unit/telemetryStartupMarkersTest.ts index d7faed936ca4..630aa8b0ed5a 100644 --- a/tests/unit/telemetryStartupMarkersTest.ts +++ b/tests/unit/telemetryStartupMarkersTest.ts @@ -1,3 +1,5 @@ +import {getMsSinceJsStartup, getMsSinceNativeAppStart} from '@libs/telemetry/nativeAppStartTime'; + import setupTelemetry from '@src/setup/telemetry/index.native'; // jest/setup.ts mocks '@src/setup/telemetry' globally; unmock (hoisted above imports) so we exercise the real native implementation. @@ -37,6 +39,7 @@ describe('telemetry startup markers (native)', () => { jest.clearAllMocks(); // Keep "now" close to the mocked appStartTime so the prewarm staleness guard accepts it. jest.spyOn(Date, 'now').mockReturnValue(2_000); + jest.spyOn(performance, 'now').mockReturnValue(10_000); global.requestAnimationFrame = jest.fn(); mockMarkers.mockReturnValue({}); activeSpansMock.startSpan.mockReturnValue({setAttribute: jest.fn()}); @@ -108,4 +111,98 @@ describe('telemetry startup markers (native)', () => { expect(() => setupTelemetry()).not.toThrow(); expect(startInactiveSpanMock).not.toHaveBeenCalled(); }); + + it('keeps the accepted native start time for spans that start later, such as the scan shutter span', () => { + // Given a native start time one second before telemetry setup + setupTelemetry(); + + // When a span starts 500ms after setup + jest.spyOn(performance, 'now').mockReturnValue(10_500); + + // Then it can read the time since the native app start + expect(getMsSinceNativeAppStart()).toBe(1_500); + }); + + it('ignores wall-clock corrections after setup when reporting the time since the native app start', () => { + // Given a native start time one second before telemetry setup + setupTelemetry(); + + // When the device clock is set back an hour and a span starts 500ms after setup + jest.spyOn(Date, 'now').mockReturnValue(2_500 - 60 * 60 * 1000); + jest.spyOn(performance, 'now').mockReturnValue(10_500); + + // Then the duration follows the monotonic clock instead of going negative + expect(getMsSinceNativeAppStart()).toBe(1_500); + }); + + it('counts time the device spent in deep sleep after setup', () => { + // Given a native start time one second before telemetry setup + setupTelemetry(); + + // When the device sleeps for an hour, so performance.now() advances only 500ms while the wall clock advances an hour + jest.spyOn(Date, 'now').mockReturnValue(2_000 + 60 * 60 * 1000); + jest.spyOn(performance, 'now').mockReturnValue(10_500); + + // Then the duration includes the sleep instead of reporting a scan right after a cold launch + expect(getMsSinceNativeAppStart()).toBe(1_000 + 60 * 60 * 1000); + }); + + it('counts a forward clock correction after setup as elapsed time, an accepted limitation', () => { + // Given a native start time one second before telemetry setup + setupTelemetry(); + + // When the device clock jumps forward an hour and a span starts 500ms after setup + jest.spyOn(Date, 'now').mockReturnValue(2_500 + 60 * 60 * 1000); + jest.spyOn(performance, 'now').mockReturnValue(10_500); + + // Then the hour is included, because JS cannot tell a forward correction apart from deep sleep + expect(getMsSinceNativeAppStart()).toBe(1_500 + 60 * 60 * 1000); + }); + + it('drops the native start time of a prewarmed process so later spans report no duration', () => { + // Given a native start time older than the prewarm threshold, as on a prewarmed process + jest.spyOn(Date, 'now').mockReturnValue(1_000 + 60 * 1000 + 1); + + // When telemetry setup discards it + setupTelemetry(); + + // Then later spans get no duration instead of minutes or hours + expect(getMsSinceNativeAppStart()).toBeUndefined(); + }); + + it('reports the time since JS startup even when the native start time is discarded', () => { + // Given an old native process, as when a HybridApp user opens NewDot after more than a minute in OldDot + jest.spyOn(Date, 'now').mockReturnValue(1_000 + 60 * 1000 + 1); + setupTelemetry(); + + // When a span starts 500ms after setup + jest.spyOn(performance, 'now').mockReturnValue(10_500); + + // Then the JS-startup duration is still reported, so these sessions can be told apart from true cold launches + expect(getMsSinceNativeAppStart()).toBeUndefined(); + expect(getMsSinceJsStartup()).toBe(500); + }); + + it('counts deep sleep in the time since JS startup', () => { + // Given telemetry setup has run + setupTelemetry(); + + // When the device sleeps for an hour, so performance.now() advances only 500ms while the wall clock advances an hour + jest.spyOn(Date, 'now').mockReturnValue(2_000 + 60 * 60 * 1000); + jest.spyOn(performance, 'now').mockReturnValue(10_500); + + // Then the duration includes the sleep, like the native duration + expect(getMsSinceJsStartup()).toBe(60 * 60 * 1000); + }); + + it('reports no JS-startup duration before telemetry setup has run', () => { + // Given a fresh module that telemetry setup has not touched yet + jest.isolateModules(() => { + const {getMsSinceJsStartup: getMsSinceJsStartupBeforeSetup} = jest.requireActual<{getMsSinceJsStartup: typeof getMsSinceJsStartup}>('@libs/telemetry/nativeAppStartTime'); + + // When a span reads the duration + // Then there is no value, instead of a time measured from an unset origin + expect(getMsSinceJsStartupBeforeSetup()).toBeUndefined(); + }); + }); });