From 70e6261eb7fdf57e3aba1f72d12c3eb518bcad99 Mon Sep 17 00:00:00 2001 From: Krystof Woldrich <31292499+krystofwoldrich@users.noreply.github.com> Date: Mon, 10 Jun 2024 15:50:23 +0200 Subject: [PATCH] feat(tracing): Add JS Bundle Execution to the App Start span (#3857) --- CHANGELOG.md | 1 + src/js/tracing/reactnativeprofiler.tsx | 10 +- src/js/tracing/reactnativetracing.ts | 38 +++++++ src/js/tracing/utils.ts | 26 ++++- src/js/utils/worldwide.ts | 2 + test/tracing/reactnativetracing.test.ts | 125 ++++++++++++++++++++++++ 6 files changed, 200 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 8dd19d92e7..014f3d0cab 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,7 @@ - Add native application start spans ([#3855](https://github.com/getsentry/sentry-react-native/pull/3855)) - This doesn't change the app start measurement length, but add child spans (more detail) into the existing app start span +- Added JS Bundle Execution start information to the application start measurements ([#3857](https://github.com/getsentry/sentry-react-native/pull/3857)) ### Dependencies diff --git a/src/js/tracing/reactnativeprofiler.tsx b/src/js/tracing/reactnativeprofiler.tsx index 71fcfb8434..2f5a2f65f1 100644 --- a/src/js/tracing/reactnativeprofiler.tsx +++ b/src/js/tracing/reactnativeprofiler.tsx @@ -1,4 +1,5 @@ -import { getCurrentHub, Profiler } from '@sentry/react'; +import { getClient, getCurrentHub, Profiler } from '@sentry/react'; +import { timestampInSeconds } from '@sentry/utils'; import { createIntegration } from '../integrations/factory'; import { ReactNativeTracing } from './reactnativetracing'; @@ -13,6 +14,13 @@ const ReactNativeProfilerGlobalState = { export class ReactNativeProfiler extends Profiler { public readonly name: string = 'ReactNativeProfiler'; + public constructor(props: ConstructorParameters[0]) { + const client = getClient(); + const integration = client && client.getIntegrationByName && client.getIntegrationByName('ReactNativeTracing'); + integration && integration.setRootComponentFirstConstructorCallTimestampMs(timestampInSeconds() * 1000); + super(props); + } + /** * Get the app root mount time. */ diff --git a/src/js/tracing/reactnativetracing.ts b/src/js/tracing/reactnativetracing.ts index a242ab3492..33f85be4d4 100644 --- a/src/js/tracing/reactnativetracing.ts +++ b/src/js/tracing/reactnativetracing.ts @@ -24,6 +24,7 @@ import { cancelInBackground, onlySampleIfChildSpans } from './transaction'; import type { BeforeNavigate, RouteChangeContextData } from './types'; import { adjustTransactionDuration, + getBundleStartTimestampMs, getTimeOriginMilliseconds, isNearToNow, setSpanDurationAsMeasurement, @@ -153,6 +154,7 @@ export class ReactNativeTracing implements Integration { private _hasSetTracePropagationTargets: boolean; private _hasSetTracingOrigins: boolean; private _currentViewName: string | undefined; + private _firstConstructorCallTimestampMs: number | undefined; public constructor(options: Partial = {}) { this._hasSetTracePropagationTargets = !!( @@ -295,6 +297,13 @@ export class ReactNativeTracing implements Integration { this._appStartFinishTimestamp = endTimestamp; } + /** + * Sets the root component first constructor call timestamp. + */ + public setRootComponentFirstConstructorCallTimestampMs(timestamp: number): void { + this._firstConstructorCallTimestampMs = timestamp; + } + /** * Starts a new transaction for a user interaction. * @param userInteractionId Consists of `op` representation UI Event and `elementId` unique element identifier on current screen. @@ -499,12 +508,41 @@ export class ReactNativeTracing implements Integration { startTimestamp: appStartTimeSeconds, endTimestamp: this._appStartFinishTimestamp, }); + this._addJSExecutionBeforeRoot(appStartSpan); this._addNativeSpansTo(appStartSpan, appStart.spans); const measurement = appStart.type === 'cold' ? APP_START_COLD : APP_START_WARM; transaction.setMeasurement(measurement, appStartDurationMilliseconds, 'millisecond'); } + /** + * Adds JS Execution before React Root. If `Sentry.wrap` is not used, create a span for the start of JS Bundle execution. + */ + private _addJSExecutionBeforeRoot(appStartSpan: Span): void { + const bundleStartTimestampMs = getBundleStartTimestampMs(); + if (!bundleStartTimestampMs) { + return; + } + + if (!this._firstConstructorCallTimestampMs) { + logger.warn('Missing the root component first constructor call timestamp.'); + appStartSpan.startChild({ + description: 'JS Bundle Execution Start', + op: appStartSpan.op, + startTimestamp: bundleStartTimestampMs / 1000, + endTimestamp: bundleStartTimestampMs / 1000, + }); + return; + } + + appStartSpan.startChild({ + description: 'JS Bundle Execution Before React Root', + op: appStartSpan.op, + startTimestamp: bundleStartTimestampMs / 1000, + endTimestamp: this._firstConstructorCallTimestampMs / 1000, + }); + } + /** * Adds native spans to the app start span. */ diff --git a/src/js/tracing/utils.ts b/src/js/tracing/utils.ts index de74bfe447..f154322d18 100644 --- a/src/js/tracing/utils.ts +++ b/src/js/tracing/utils.ts @@ -6,7 +6,9 @@ import { spanToJSON, } from '@sentry/core'; import type { Span, TransactionContext, TransactionSource } from '@sentry/types'; -import { timestampInSeconds } from '@sentry/utils'; +import { logger, timestampInSeconds } from '@sentry/utils'; + +import { RN_GLOBAL_OBJ } from '../utils/worldwide'; export const defaultTransactionSource: TransactionSource = 'component'; export const customTransactionSource: TransactionSource = 'custom'; @@ -111,3 +113,25 @@ export function setSpanDurationAsMeasurement(name: string, span: Span): void { setMeasurement(name, (spanEnd - spanStart) * 1000, 'millisecond'); } + +/** + * Returns unix timestamp in ms of the bundle start time. + * + * If not available, returns undefined. + */ +export function getBundleStartTimestampMs(): number | undefined { + const bundleStartTime = RN_GLOBAL_OBJ.__BUNDLE_START_TIME__; + if (!bundleStartTime) { + logger.warn('Missing the bundle start time on the global object.'); + return undefined; + } + + if (!RN_GLOBAL_OBJ.nativePerformanceNow) { + // bundleStartTime is Date.now() in milliseconds + return bundleStartTime; + } + + // nativePerformanceNow() is monotonic clock like performance.now() + const approxStartingTimeOrigin = Date.now() - RN_GLOBAL_OBJ.nativePerformanceNow(); + return approxStartingTimeOrigin + bundleStartTime; +} diff --git a/src/js/utils/worldwide.ts b/src/js/utils/worldwide.ts index 4eedca2992..4f1cfc4c7b 100644 --- a/src/js/utils/worldwide.ts +++ b/src/js/utils/worldwide.ts @@ -22,6 +22,8 @@ export interface ReactNativeInternalGlobal extends InternalGlobal { ___SENTRY_METRO_DEV_SERVER___?: string; }; }; + __BUNDLE_START_TIME__?: number; + nativePerformanceNow?: () => number; } /** Get's the global object for the current JavaScript runtime */ diff --git a/test/tracing/reactnativetracing.test.ts b/test/tracing/reactnativetracing.test.ts index d786cfdd1d..d14047d9af 100644 --- a/test/tracing/reactnativetracing.test.ts +++ b/test/tracing/reactnativetracing.test.ts @@ -331,6 +331,114 @@ describe('ReactNativeTracing', () => { expect(transaction).toBeUndefined(); }); + describe('bundle execution spans', () => { + afterEach(() => { + clearReactNativeBundleExecutionStartTimestamp(); + }); + + it('does not add bundle executions span if __BUNDLE_START_TIME__ is undefined', async () => { + const integration = new ReactNativeTracing(); + + mockAppStartResponse({ cold: true }); + + setup(integration); + + await jest.advanceTimersByTimeAsync(500); + await jest.runOnlyPendingTimersAsync(); + + const transaction = client.event; + + const bundleStartSpan = transaction!.spans!.find( + ({ description }) => + description === 'JS Bundle Execution Start' || description === 'JS Bundle Execution Before React Root', + ); + + expect(bundleStartSpan).toBeUndefined(); + }); + + it('adds bundle execution span', async () => { + const integration = new ReactNativeTracing(); + + const [timeOriginMilliseconds] = mockAppStartResponse({ cold: true }); + mockReactNativeBundleExecutionStartTimestamp(); + + setup(integration); + integration.onAppStartFinish(timeOriginMilliseconds + 200); + + await jest.advanceTimersByTimeAsync(500); + await jest.runOnlyPendingTimersAsync(); + + const transaction = client.event; + + const appStartRootSpan = transaction!.spans!.find(({ description }) => description === 'Cold App Start'); + const bundleStartSpan = transaction!.spans!.find( + ({ description }) => description === 'JS Bundle Execution Start', + ); + const appStartRootSpanJSON = spanToJSON(appStartRootSpan!); + const bundleStartSpanJSON = spanToJSON(bundleStartSpan!); + + expect(appStartRootSpan).toBeDefined(); + expect(bundleStartSpan).toBeDefined(); + expect(appStartRootSpanJSON).toEqual( + expect.objectContaining({ + description: 'Cold App Start', + span_id: expect.any(String), + op: APP_START_COLD_OP, + }), + ); + expect(bundleStartSpanJSON).toEqual( + expect.objectContaining({ + description: 'JS Bundle Execution Start', + start_timestamp: expect.closeTo((timeOriginMilliseconds - 50) / 1000), + timestamp: expect.closeTo((timeOriginMilliseconds - 50) / 1000), + parent_span_id: spanToJSON(appStartRootSpan!).span_id, // parent is the root app start span + op: spanToJSON(appStartRootSpan!).op, // op is the same as the root app start span + }), + ); + }); + + it('adds bundle execution before react root', async () => { + const integration = new ReactNativeTracing(); + + const [timeOriginMilliseconds] = mockAppStartResponse({ cold: true }); + mockReactNativeBundleExecutionStartTimestamp(); + + setup(integration); + integration.setRootComponentFirstConstructorCallTimestampMs(timeOriginMilliseconds - 10); + + await jest.advanceTimersByTimeAsync(500); + await jest.runOnlyPendingTimersAsync(); + + const transaction = client.event; + + const appStartRootSpan = transaction!.spans!.find(({ description }) => description === 'Cold App Start'); + const bundleStartSpan = transaction!.spans!.find( + ({ description }) => description === 'JS Bundle Execution Before React Root', + ); + const appStartRootSpanJSON = spanToJSON(appStartRootSpan!); + const bundleStartSpanJSON = spanToJSON(bundleStartSpan!); + + expect(appStartRootSpan).toBeDefined(); + expect(bundleStartSpan).toBeDefined(); + expect(appStartRootSpanJSON).toEqual( + expect.objectContaining({ + description: 'Cold App Start', + span_id: expect.any(String), + op: APP_START_COLD_OP, + }), + ); + expect(bundleStartSpanJSON).toEqual( + expect.objectContaining({ + description: 'JS Bundle Execution Before React Root', + start_timestamp: expect.closeTo((timeOriginMilliseconds - 50) / 1000), + timestamp: (timeOriginMilliseconds - 10) / 1000, + parent_span_id: spanToJSON(appStartRootSpan!).span_id, // parent is the root app start span + op: spanToJSON(appStartRootSpan!).op, // op is the same as the root app start span + }), + ); + }); + }); + it('adds native spans as a child of the main app start span', async () => { const integration = new ReactNativeTracing(); @@ -991,3 +1099,20 @@ function mockAppStartResponse({ function setup(integration: ReactNativeTracing) { integration.setupOnce(addGlobalEventProcessor, getCurrentHub); } + +/** + * Mocks RN Bundle Start Module + * `var __BUNDLE_START_TIME__=this.nativePerformanceNow?nativePerformanceNow():Date.now()` + */ +function mockReactNativeBundleExecutionStartTimestamp() { + RN_GLOBAL_OBJ.nativePerformanceNow = () => 100; // monotonic clock like `performance.now()` + RN_GLOBAL_OBJ.__BUNDLE_START_TIME__ = 50; // 50ms after time origin +} + +/** + * Removes mock added by mockReactNativeBundleExecutionStartTimestamp + */ +function clearReactNativeBundleExecutionStartTimestamp() { + delete RN_GLOBAL_OBJ.nativePerformanceNow; + delete RN_GLOBAL_OBJ.__BUNDLE_START_TIME__; +}