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

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 ?? []),
  ]
  : [],
  };