feat(tracing): Add JS Bundle Execution to the App Start span (#3857)

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
 

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<typeof Profiler>[0]) {
+    const client = getClient();
+    const integration = client && client.getIntegrationByName && client.getIntegrationByName<ReactNativeTracing>('ReactNativeTracing');
+    integration && integration.setRootComponentFirstConstructorCallTimestampMs(timestampInSeconds() * 1000);
+    super(props);
+  }
+
   /**
    * Get the app root mount time.
    */

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<ReactNativeTracingOptions> = {}) {
     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.
    */

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;
+}

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 */

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(<SpanJSON>{
+              description: 'Cold App Start',
+              span_id: expect.any(String),
+              op: APP_START_COLD_OP,
+            }),
+          );
+          expect(bundleStartSpanJSON).toEqual(
+            expect.objectContaining(<SpanJSON>{
+              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(<SpanJSON>{
+              description: 'Cold App Start',
+              span_id: expect.any(String),
+              op: APP_START_COLD_OP,
+            }),
+          );
+          expect(bundleStartSpanJSON).toEqual(
+            expect.objectContaining(<SpanJSON>{
+              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__;
+}