fix(performance): UIKit can't end after JS execution starts (#3884)

Author: krystofwoldrich

CHANGELOG.md

@@ -4,7 +4,7 @@
 
 ### Features
 
-- Add native application start spans ([#3855](https://github.com/getsentry/sentry-react-native/pull/3855))
+- Add native application start spans ([#3855](https://github.com/getsentry/sentry-react-native/pull/3855), [#3884](https://github.com/getsentry/sentry-react-native/pull/3884))
   - 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))
 

src/js/tracing/reactnativetracing.ts

@@ -554,6 +554,10 @@ export class ReactNativeTracing implements Integration {
    */
   private _addNativeSpansTo(appStartSpan: Span, nativeSpans: NativeAppStartResponse['spans']): void {
     nativeSpans.forEach(span => {
+      if (span.description === 'UIKit init') {
+        return this._createUIKitSpan(appStartSpan, span);
+      }
+
       appStartSpan.startChild({
         op: appStartSpan.op,
         description: span.description,
@@ -563,6 +567,33 @@ export class ReactNativeTracing implements Integration {
     });
   }
 
+  /**
+   * UIKit init is measured by the native layers till the native SDK start
+   * RN initializes the native SDK later, the end timestamp would be wrong
+   */
+  private _createUIKitSpan(parentSpan: Span, nativeUIKitSpan: NativeAppStartResponse['spans'][number]): void {
+    const bundleStart = getBundleStartTimestampMs();
+
+    // If UIKit init ends after the bundle start, the native SDK was auto-initialized
+    // and so the end timestamp is incorrect.
+    // The timestamps can't equal, as RN initializes after UIKit.
+    if (bundleStart && bundleStart < nativeUIKitSpan.end_timestamp_ms) {
+      parentSpan.startChild({
+        op: parentSpan.op,
+        description: 'UIKit Init to JS Exec Start',
+        startTimestamp: nativeUIKitSpan.start_timestamp_ms / 1000,
+        endTimestamp: bundleStart / 1000,
+      });
+    } else {
+      parentSpan.startChild({
+        op: parentSpan.op,
+        description: 'UIKit Init',
+        startTimestamp: nativeUIKitSpan.start_timestamp_ms / 1000,
+        endTimestamp: nativeUIKitSpan.end_timestamp_ms / 1000,
+      });
+    }
+  }
+
   /** To be called when the route changes, but BEFORE the components of the new route mount. */
   private _onRouteWillChange(context: TransactionContext): TransactionType | undefined {
     return this._createRouteTransaction(context);

test/tracing/reactnativetracing.test.ts

@@ -478,6 +478,82 @@ describe('ReactNativeTracing', () => {
           }),
         );
       });
+
+      it('adds ui kit init full length as a child of the main app start span', async () => {
+        const integration = new ReactNativeTracing();
+
+        const timeOriginMilliseconds = Date.now();
+        mockAppStartResponse({
+          cold: true,
+          enableNativeSpans: true,
+          customNativeSpans: [
+            {
+              description: 'UIKit init',
+              start_timestamp_ms: timeOriginMilliseconds - 100,
+              end_timestamp_ms: timeOriginMilliseconds - 60,
+            },
+          ],
+        });
+        mockReactNativeBundleExecutionStartTimestamp();
+
+        setup(integration);
+
+        await jest.advanceTimersByTimeAsync(500);
+        await jest.runOnlyPendingTimersAsync();
+
+        const transaction = client.event;
+
+        const nativeSpan = transaction!.spans!.find(({ description }) => description?.startsWith('UIKit Init'));
+        const nativeSpanJSON = spanToJSON(nativeSpan!);
+
+        expect(nativeSpan).toBeDefined();
+        expect(nativeSpanJSON).toEqual(
+          expect.objectContaining(<SpanJSON>{
+            description: 'UIKit Init',
+            start_timestamp: (timeOriginMilliseconds - 100) / 1000,
+            timestamp: (timeOriginMilliseconds - 60) / 1000,
+          }),
+        );
+      });
+
+      it('adds ui kit init start mark as a child of the main app start span', async () => {
+        const integration = new ReactNativeTracing();
+
+        const timeOriginMilliseconds = Date.now();
+        mockAppStartResponse({
+          cold: true,
+          enableNativeSpans: true,
+          customNativeSpans: [
+            {
+              description: 'UIKit init',
+              start_timestamp_ms: timeOriginMilliseconds - 100,
+              end_timestamp_ms: timeOriginMilliseconds - 20, // After mocked bundle execution start
+            },
+          ],
+        });
+        mockReactNativeBundleExecutionStartTimestamp();
+
+        setup(integration);
+
+        await jest.advanceTimersByTimeAsync(500);
+        await jest.runOnlyPendingTimersAsync();
+
+        const transaction = client.event;
+
+        const nativeRuntimeInitSpan = transaction!.spans!.find(({ description }) =>
+          description?.startsWith('UIKit Init to JS Exec Start'),
+        );
+        const nativeRuntimeInitSpanJSON = spanToJSON(nativeRuntimeInitSpan!);
+
+        expect(nativeRuntimeInitSpanJSON).toBeDefined();
+        expect(nativeRuntimeInitSpanJSON).toEqual(
+          expect.objectContaining(<SpanJSON>{
+            description: 'UIKit Init to JS Exec Start',
+            start_timestamp: (timeOriginMilliseconds - 100) / 1000,
+            timestamp: (timeOriginMilliseconds - 50) / 1000,
+          }),
+        );
+      });
     });
 
     describe('With routing instrumentation', () => {
@@ -1068,10 +1144,12 @@ function mockAppStartResponse({
   cold,
   has_fetched,
   enableNativeSpans,
+  customNativeSpans,
 }: {
   cold: boolean;
   has_fetched?: boolean;
   enableNativeSpans?: boolean;
+  customNativeSpans?: NativeAppStartResponse['spans'];
 }) {
   const timeOriginMilliseconds = Date.now();
   const appStartTimeMilliseconds = timeOriginMilliseconds - 100;
@@ -1086,6 +1164,7 @@ function mockAppStartResponse({
             start_timestamp_ms: timeOriginMilliseconds - 100,
             end_timestamp_ms: timeOriginMilliseconds - 50,
           },
+          ...(customNativeSpans ?? []),
         ]
       : [],
   };