Fix(V6): Implement fallback system to screens that aren't reporting on the native layer the time to display. #4042 (#4189)

lucas-zimerman · web-flow · commit c639edf12520 · 2024-10-30T18:39:53.000Z
* merge main

* fix tests / yarn fix

* changelog

* undoo changes to sample

* fix android

* NIT

* NIT extra line

* fix-android-lint

* fix java format

* pub private constructor

* make it final

* test

* add missing dependencies changelog
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -8,6 +8,10 @@
 
 ## Unreleased
 
+### Fixes
+
+- Enhanced accuracy of time-to-display spans. ([#4189](https://github.com/getsentry/sentry-react-native/pull/4189))
+
 ### Dependencies
 
 - Bump JavaScript SDK from v8.34.0 to v8.35.0 ([#4196](https://github.com/getsentry/sentry-react-native/pull/4196))
diff --git a/packages/core/android/src/main/java/io/sentry/react/RNSentryModuleImpl.java b/packages/core/android/src/main/java/io/sentry/react/RNSentryModuleImpl.java
@@ -126,10 +126,13 @@ public class RNSentryModuleImpl {
   /** Max trace file size in bytes. */
   private long maxTraceFileSize = 5 * 1024 * 1024;
 
+  private final @NotNull SentryDateProvider dateProvider;
+
   public RNSentryModuleImpl(ReactApplicationContext reactApplicationContext) {
     packageInfo = getPackageInfo(reactApplicationContext);
     this.reactApplicationContext = reactApplicationContext;
     this.emitNewFrameEvent = createEmitNewFrameEvent();
+    this.dateProvider = new SentryAndroidDateProvider();
   }
 
   private ReactApplicationContext getReactApplicationContext() {
@@ -141,8 +144,6 @@ private ReactApplicationContext getReactApplicationContext() {
   }
 
   private @NotNull Runnable createEmitNewFrameEvent() {
-    final @NotNull SentryDateProvider dateProvider = new SentryAndroidDateProvider();
-
     return () -> {
       final SentryDate endDate = dateProvider.now();
       WritableMap event = Arguments.createMap();
@@ -745,6 +746,10 @@ public void disableNativeFramesTracking() {
     }
   }
 
+  public void getNewScreenTimeToDisplay(Promise promise) {
+    RNSentryTimeToDisplay.getTimeToDisplay(promise, dateProvider);
+  }
+
   private String getProfilingTracesDirPath() {
     if (cacheDirPath == null) {
       cacheDirPath =
diff --git a/packages/core/android/src/main/java/io/sentry/react/RNSentryTimeToDisplay.java b/packages/core/android/src/main/java/io/sentry/react/RNSentryTimeToDisplay.java
@@ -0,0 +1,42 @@
+package io.sentry.react;
+
+import android.os.Handler;
+import android.os.Looper;
+import android.view.Choreographer;
+import com.facebook.react.bridge.Promise;
+import io.sentry.SentryDate;
+import io.sentry.SentryDateProvider;
+
+public final class RNSentryTimeToDisplay {
+
+  private RNSentryTimeToDisplay() {}
+
+  public static void getTimeToDisplay(Promise promise, SentryDateProvider dateProvider) {
+    Looper mainLooper = Looper.getMainLooper();
+
+    if (mainLooper == null) {
+      promise.reject(
+          "GetTimeToDisplay is not able to measure the time to display: Main looper not"
+              + " available.");
+      return;
+    }
+
+    // Ensure the code runs on the main thread
+    new Handler(mainLooper)
+        .post(
+            () -> {
+              try {
+                Choreographer choreographer = Choreographer.getInstance();
+
+                // Invoke the callback after the frame is rendered
+                choreographer.postFrameCallback(
+                    frameTimeNanos -> {
+                      final SentryDate endDate = dateProvider.now();
+                      promise.resolve(endDate.nanoTimestamp() / 1e9);
+                    });
+              } catch (Exception exception) {
+                promise.reject("Failed to receive the instance of Choreographer", exception);
+              }
+            });
+  }
+}
diff --git a/packages/core/android/src/newarch/java/io/sentry/react/RNSentryModule.java b/packages/core/android/src/newarch/java/io/sentry/react/RNSentryModule.java
@@ -172,4 +172,9 @@ public String getCurrentReplayId() {
   public void crashedLastRun(Promise promise) {
     this.impl.crashedLastRun(promise);
   }
+
+  @Override
+  public void getNewScreenTimeToDisplay(Promise promise) {
+    this.impl.getNewScreenTimeToDisplay(promise);
+  }
 }
diff --git a/packages/core/android/src/oldarch/java/io/sentry/react/RNSentryModule.java b/packages/core/android/src/oldarch/java/io/sentry/react/RNSentryModule.java
@@ -172,4 +172,9 @@ public String getCurrentReplayId() {
   public void crashedLastRun(Promise promise) {
     this.impl.crashedLastRun(promise);
   }
+
+  @ReactMethod()
+  public void getNewScreenTimeToDisplay(Promise promise) {
+    this.impl.getNewScreenTimeToDisplay(promise);
+  }
 }
diff --git a/packages/core/ios/RNSentry.mm b/packages/core/ios/RNSentry.mm
@@ -1,5 +1,6 @@
 #import <dlfcn.h>
 #import "RNSentry.h"
+#import "RNSentryTimeToDisplay.h"
 
 #if __has_include(<React/RCTConvert.h>)
 #import <React/RCTConvert.h>
@@ -62,6 +63,7 @@ + (void)storeEnvelope:(SentryEnvelope *)envelope;
 @implementation RNSentry {
     bool sentHybridSdkDidBecomeActive;
     bool hasListeners;
+    RNSentryTimeToDisplay *_timeToDisplay;
 }
 
 - (dispatch_queue_t)methodQueue
@@ -139,6 +141,8 @@ - (SentryOptions *_Nullable)createOptionsWithDictionary:(NSDictionary *_Nonnull)
     [mutableOptions removeObjectForKey:@"tracesSampler"];
     [mutableOptions removeObjectForKey:@"enableTracing"];
 
+    _timeToDisplay = [[RNSentryTimeToDisplay alloc] init];
+
 #if SENTRY_TARGET_REPLAY_SUPPORTED
     [RNSentryReplay updateOptions:mutableOptions];
 #endif
@@ -786,4 +790,9 @@ - (NSDictionary*) fetchNativeStackFramesBy: (NSArray<NSNumber*>*)instructionsAdd
 }
 #endif
 
+RCT_EXPORT_METHOD(getNewScreenTimeToDisplay:(RCTPromiseResolveBlock)resolve
+                  rejecter:(RCTPromiseRejectBlock)reject) {
+    [_timeToDisplay getTimeToDisplay:resolve];
+}
+
 @end
diff --git a/packages/core/ios/RNSentryTimeToDisplay.h b/packages/core/ios/RNSentryTimeToDisplay.h
@@ -0,0 +1,7 @@
+#import <React/RCTBridgeModule.h>
+
+@interface RNSentryTimeToDisplay : NSObject
+
+- (void)getTimeToDisplay:(RCTResponseSenderBlock)callback;
+
+@end
diff --git a/packages/core/ios/RNSentryTimeToDisplay.m b/packages/core/ios/RNSentryTimeToDisplay.m
@@ -0,0 +1,43 @@
+#import "RNSentryTimeToDisplay.h"
+#import <QuartzCore/QuartzCore.h>
+#import <React/RCTLog.h>
+
+@implementation RNSentryTimeToDisplay
+{
+  CADisplayLink *displayLink;
+  RCTResponseSenderBlock resolveBlock;
+}
+
+// Rename requestAnimationFrame to getTimeToDisplay
+- (void)getTimeToDisplay:(RCTResponseSenderBlock)callback
+{
+  // Store the resolve block to use in the callback.
+  resolveBlock = callback;
+
+#if TARGET_OS_IOS
+  // Create and add a display link to get the callback after the screen is rendered.
+  displayLink = [CADisplayLink displayLinkWithTarget:self selector:@selector(handleDisplayLink:)];
+  [displayLink addToRunLoop:[NSRunLoop mainRunLoop] forMode:NSRunLoopCommonModes];
+#else
+  resolveBlock(@[]); // Return nothing if not iOS.
+#endif
+}
+
+#if TARGET_OS_IOS
+- (void)handleDisplayLink:(CADisplayLink *)link {
+  // Get the current time
+  NSTimeInterval currentTime = [[NSDate date] timeIntervalSince1970] * 1000.0; // Convert to milliseconds
+
+  // Ensure the callback is valid and pass the current time back
+  if (resolveBlock) {
+    resolveBlock(@[@(currentTime)]); // Call the callback with the current time
+    resolveBlock = nil; // Clear the block after it's called
+  }
+
+  // Invalidate the display link to stop future callbacks
+  [displayLink invalidate];
+  displayLink = nil;
+}
+#endif
+
+@end
diff --git a/packages/core/src/js/NativeRNSentry.ts b/packages/core/src/js/NativeRNSentry.ts
@@ -9,6 +9,7 @@ import type { UnsafeObject } from './utils/rnlibrariesinterface';
 export interface Spec extends TurboModule {
   addListener: (eventType: string) => void;
   removeListeners: (id: number) => void;
+  getNewScreenTimeToDisplay(): Promise<number | undefined | null>;
   addBreadcrumb(breadcrumb: UnsafeObject): void;
   captureEnvelope(
     bytes: string,
diff --git a/packages/core/src/js/tracing/reactnavigation.ts b/packages/core/src/js/tracing/reactnavigation.ts
@@ -12,8 +12,9 @@ import {
 import type { Client, Integration, Span } from '@sentry/types';
 import { isPlainObject, logger, timestampInSeconds } from '@sentry/utils';
 
-import type { NewFrameEvent, SentryEventEmitter } from '../utils/sentryeventemitter';
-import { createSentryEventEmitter, NewFrameEventName } from '../utils/sentryeventemitter';
+import type { NewFrameEvent } from '../utils/sentryeventemitter';
+import type { SentryEventEmitterFallback } from '../utils/sentryeventemitterfallback';
+import { createSentryFallbackEventEmitter } from '../utils/sentryeventemitterfallback';
 import { isSentrySpan } from '../utils/span';
 import { RN_GLOBAL_OBJ } from '../utils/worldwide';
 import { NATIVE } from '../wrapper';
@@ -30,7 +31,6 @@ import {
 } from './span';
 import { manualInitialDisplaySpans, startTimeToInitialDisplaySpan } from './timetodisplay';
 import { setSpanDurationAsMeasurementOnSpan } from './utils';
-
 export const INTEGRATION_NAME = 'ReactNavigation';
 
 const NAVIGATION_HISTORY_MAX_SIZE = 200;
@@ -81,7 +81,7 @@ export const reactNavigationIntegration = ({
   registerNavigationContainer: (navigationContainerRef: unknown) => void;
 } => {
   let navigationContainer: NavigationContainer | undefined;
-  let newScreenFrameEventEmitter: SentryEventEmitter | undefined;
+  let newScreenFrameEventEmitter: SentryEventEmitterFallback | undefined;
 
   let tracing: ReactNativeTracingIntegration | undefined;
   let idleSpanOptions: Parameters<typeof startGenericIdleNavigationSpan>[1] = defaultIdleOptions;
@@ -95,8 +95,8 @@ export const reactNavigationIntegration = ({
   let recentRouteKeys: string[] = [];
 
   if (enableTimeToInitialDisplay) {
-    newScreenFrameEventEmitter = createSentryEventEmitter();
-    newScreenFrameEventEmitter.initAsync(NewFrameEventName);
+    newScreenFrameEventEmitter = createSentryFallbackEventEmitter();
+    newScreenFrameEventEmitter.initAsync();
     NATIVE.initNativeReactNavigationNewFrameTracking().catch((reason: unknown) => {
       logger.error(`${INTEGRATION_NAME} Failed to initialize native new frame tracking: ${reason}`);
     });
@@ -258,9 +258,8 @@ export const reactNavigationIntegration = ({
       });
 
     const navigationSpanWithTtid = latestNavigationSpan;
-    !routeHasBeenSeen &&
-      latestTtidSpan &&
-      newScreenFrameEventEmitter?.once(NewFrameEventName, ({ newFrameTimestampInSeconds }: NewFrameEvent) => {
+    if (!routeHasBeenSeen && latestTtidSpan) {
+      newScreenFrameEventEmitter?.onceNewFrame(({ newFrameTimestampInSeconds }: NewFrameEvent) => {
         const activeSpan = getActiveSpan();
         if (activeSpan && manualInitialDisplaySpans.has(activeSpan)) {
           logger.warn('[ReactNavigationInstrumentation] Detected manual instrumentation for the current active span.');
@@ -271,6 +270,7 @@ export const reactNavigationIntegration = ({
         latestTtidSpan.end(newFrameTimestampInSeconds);
         setSpanDurationAsMeasurementOnSpan('time_to_initial_display', latestTtidSpan, navigationSpanWithTtid);
       });
+    }
 
     navigationProcessingSpan?.updateName(`Processing navigation to ${route.name}`);
     navigationProcessingSpan?.setStatus({ code: SPAN_STATUS_OK });
diff --git a/packages/core/src/js/utils/sentryeventemitterfallback.ts b/packages/core/src/js/utils/sentryeventemitterfallback.ts
@@ -0,0 +1,98 @@
+import { logger, timestampInSeconds } from '@sentry/utils';
+
+import { NATIVE } from '../wrapper';
+import type { NewFrameEvent, SentryEventEmitter } from './sentryeventemitter';
+import { createSentryEventEmitter, NewFrameEventName } from './sentryeventemitter';
+
+export const FALLBACK_TIMEOUT_MS = 10_000;
+
+export type FallBackNewFrameEvent = { newFrameTimestampInSeconds: number; isFallback?: boolean };
+export interface SentryEventEmitterFallback {
+  /**
+   * Initializes the fallback event emitter
+   * This method is synchronous in JS but the event emitter starts asynchronously.
+   */
+  initAsync: () => void;
+  onceNewFrame: (listener: (event: FallBackNewFrameEvent) => void) => void;
+}
+
+/**
+ * Creates emitter that allows to listen to UI Frame events when ready.
+ */
+export function createSentryFallbackEventEmitter(
+  emitter: SentryEventEmitter = createSentryEventEmitter(),
+  fallbackTimeoutMs = FALLBACK_TIMEOUT_MS,
+): SentryEventEmitterFallback {
+  let fallbackTimeout: ReturnType<typeof setTimeout> | undefined;
+  let animationFrameTimestampSeconds: number | undefined;
+  let nativeNewFrameTimestampSeconds: number | undefined;
+
+  function getAnimationFrameTimestampSeconds(): void {
+    // https://reactnative.dev/docs/timers#timers
+    // NOTE: The current implementation of requestAnimationFrame is the same
+    // as setTimeout(0). This isn't exactly how requestAnimationFrame
+    // is supposed to work on web, so it doesn't get called when UI Frames are rendered.: https://github.com/facebook/react-native/blob/5106933c750fee2ce49fe1945c3e3763eebc92bc/packages/react-native/ReactCommon/react/runtime/TimerManager.cpp#L442-L443
+    requestAnimationFrame(() => {
+      if (fallbackTimeout === undefined) {
+        return;
+      }
+      animationFrameTimestampSeconds = timestampInSeconds();
+    });
+  }
+
+  function getNativeNewFrameTimestampSeconds(): void {
+    NATIVE.getNewScreenTimeToDisplay()
+      .then(resolve => {
+        if (fallbackTimeout === undefined) {
+          return;
+        }
+        nativeNewFrameTimestampSeconds = resolve ?? undefined;
+      })
+      .catch(reason => {
+        logger.error('Failed to receive Native fallback timestamp.', reason);
+      });
+  }
+
+  return {
+    initAsync() {
+      emitter.initAsync(NewFrameEventName);
+    },
+
+    onceNewFrame(listener: (event: FallBackNewFrameEvent) => void) {
+      animationFrameTimestampSeconds = undefined;
+      nativeNewFrameTimestampSeconds = undefined;
+
+      const internalListener = (event: NewFrameEvent): void => {
+        if (fallbackTimeout !== undefined) {
+          clearTimeout(fallbackTimeout);
+          fallbackTimeout = undefined;
+        }
+        animationFrameTimestampSeconds = undefined;
+        nativeNewFrameTimestampSeconds = undefined;
+        listener(event);
+      };
+      fallbackTimeout = setTimeout(() => {
+        if (nativeNewFrameTimestampSeconds) {
+          logger.log('Native event emitter did not reply in time');
+          return listener({
+            newFrameTimestampInSeconds: nativeNewFrameTimestampSeconds,
+            isFallback: true,
+          });
+        } else if (animationFrameTimestampSeconds) {
+          logger.log('[Sentry] Native event emitter did not reply in time. Using JavaScript fallback emitter.');
+          return listener({
+            newFrameTimestampInSeconds: animationFrameTimestampSeconds,
+            isFallback: true,
+          });
+        } else {
+          emitter.removeListener(NewFrameEventName, internalListener);
+          logger.error('Failed to receive any fallback timestamp.');
+        }
+      }, fallbackTimeoutMs);
+
+      getNativeNewFrameTimestampSeconds();
+      getAnimationFrameTimestampSeconds();
+      emitter.once(NewFrameEventName, internalListener);
+    },
+  };
+}
diff --git a/packages/core/src/js/wrapper.ts b/packages/core/src/js/wrapper.ts
@@ -116,6 +116,7 @@ interface SentryNativeWrapper {
   getCurrentReplayId(): string | null;
 
   crashedLastRun(): Promise<boolean | null>;
+  getNewScreenTimeToDisplay(): Promise<number | null | undefined>;
 }
 
 const EOL = utf8ToBytes('\n');
@@ -690,6 +691,14 @@ export const NATIVE: SentryNativeWrapper = {
     return typeof result === 'boolean' ? result : null;
   },
 
+  getNewScreenTimeToDisplay(): Promise<number | null | undefined> {
+    if (!this.enableNative || !this._isModuleLoaded(RNSentry)) {
+      return Promise.resolve(null);
+    }
+
+    return RNSentry.getNewScreenTimeToDisplay();
+  },
+
   /**
    * Gets the event from envelopeItem and applies the level filter to the selected event.
    * @param data An envelope item containing the event.
diff --git a/packages/core/test/mockWrapper.ts b/packages/core/test/mockWrapper.ts
@@ -58,6 +58,7 @@ const NATIVE: MockInterface<NativeType> = {
   getCurrentReplayId: jest.fn(),
 
   crashedLastRun: jest.fn(),
+  getNewScreenTimeToDisplay: jest.fn().mockResolvedValue(42),
 };
 
 NATIVE.isNativeAvailable.mockReturnValue(true);
diff --git a/packages/core/test/tracing/reactnavigation.ttid.test.tsx b/packages/core/test/tracing/reactnavigation.ttid.test.tsx
diff --git a/packages/core/test/utils/mockedSentryeventemitter.ts b/packages/core/test/utils/mockedSentryeventemitter.ts
diff --git a/packages/core/test/utils/mockedSentryeventemitterfallback.ts b/packages/core/test/utils/mockedSentryeventemitterfallback.ts
diff --git a/packages/core/test/utils/sentryeventemitterfallback.test.ts b/packages/core/test/utils/sentryeventemitterfallback.test.ts

Original file line number	Diff line number	Diff line change
`@@ -172,4 +172,9 @@ public String getCurrentReplayId() {`
`172`	`172`	`public void crashedLastRun(Promise promise) {`
`173`	`173`	`this.impl.crashedLastRun(promise);`
`174`	`174`	`}`
	`175`	`+`
	`176`	`+ @Override`
	`177`	`+ public void getNewScreenTimeToDisplay(Promise promise) {`
	`178`	`+ this.impl.getNewScreenTimeToDisplay(promise);`
	`179`	`+ }`
`175`	`180`	`}`