fix(performance): add more debug logs to native frames integration (#3880)

Author: krystofwoldrich

CHANGELOG.md

@@ -8,6 +8,10 @@
   - 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))
 
+### Fixes
+
+- Add more expressive debug logs to Native Frames Integration ([#3880](https://github.com/getsentry/sentry-react-native/pull/3880))
+
 ### Dependencies
 
 - Bump Cocoa SDK from v8.27.0 to v8.28.0 ([#3866](https://github.com/getsentry/sentry-react-native/pull/3866))

src/js/tracing/nativeframes.ts

@@ -6,6 +6,13 @@ import type { NativeFramesResponse } from '../NativeRNSentry';
 import { NATIVE } from '../wrapper';
 import { instrumentChildSpanFinish } from './utils';
 
+/**
+ * Timeout from the final native frames fetch to processing the associated transaction.
+ * If the transaction is not processed by this time, the native frames will be dropped
+ * and not added to the event.
+ */
+const FINAL_FRAMES_TIMEOUT_MS = 2000;
+
 export interface FramesMeasurements extends Measurements {
   frames_total: { value: number; unit: MeasurementUnit };
   frames_slow: { value: number; unit: MeasurementUnit };
@@ -45,14 +52,24 @@ export class NativeFramesInstrumentation {
    * Logs the native frames at this start point and instruments child span finishes.
    */
   public onTransactionStart(transaction: Transaction): void {
+    logger.debug(`[NativeFrames] Fetching frames for root span start (${transaction.spanContext().spanId}).`);
     void NATIVE.fetchNativeFrames()
       .then(framesMetrics => {
         if (framesMetrics) {
           transaction.setData('__startFrames', framesMetrics);
+        } else {
+          logger.warn(
+            `[NativeFrames] Fetched frames for root span start (${
+              transaction.spanContext().spanId
+            }), but no frames were returned.`,
+          );
         }
       })
       .then(undefined, error => {
-        logger.error(`[ReactNativeTracing] Error while fetching native frames: ${error}`);
+        logger.error(
+          `[NativeFrames] Error while fetching frames for root span start (${transaction.spanContext().spanId})`,
+          error,
+        );
       });
 
     instrumentChildSpanFinish(transaction, (_: Span, endTimestamp?: number) => {
@@ -66,8 +83,11 @@ export class NativeFramesInstrumentation {
    * To be called when a transaction is finished
    */
   public onTransactionFinish(transaction: Transaction): void {
-    this._fetchFramesForTransaction(transaction).then(undefined, (reason: unknown) => {
-      logger.error(`[ReactNativeTracing] Error while fetching native frames:`, reason);
+    this._fetchEndFramesForTransaction(transaction).then(undefined, (reason: unknown) => {
+      logger.error(
+        `[NativeFrames] Error while fetching frames for root span start (${transaction.spanContext().spanId})`,
+        reason,
+      );
     });
   }
 
@@ -88,7 +108,7 @@ export class NativeFramesInstrumentation {
         }
       })
       .then(undefined, error => {
-        logger.error(`[ReactNativeTracing] Error while fetching native frames: ${error}`);
+        logger.error(`[NativeFrames] Error while fetching frames for child span end.`, error);
       });
   }
 
@@ -101,17 +121,20 @@ export class NativeFramesInstrumentation {
     startFrames: NativeFramesResponse,
   ): Promise<FramesMeasurements | null> {
     if (_finishFrames.has(traceId)) {
+      logger.debug(`[NativeFrames] Native end frames already fetched for trace id (${traceId}).`);
       return this._prepareMeasurements(traceId, finalEndTimestamp, startFrames);
     }
 
     return new Promise(resolve => {
       const timeout = setTimeout(() => {
+        logger.debug(`[NativeFrames] Native end frames listener removed by timeout for trace id (${traceId}).`);
         _framesListeners.delete(traceId);
 
         resolve(null);
       }, 2000);
 
       _framesListeners.set(traceId, () => {
+        logger.debug(`[NativeFrames] Native end frames listener called for trace id (${traceId}).`);
         resolve(this._prepareMeasurements(traceId, finalEndTimestamp, startFrames));
 
         clearTimeout(timeout);
@@ -137,15 +160,20 @@ export class NativeFramesInstrumentation {
       // Must be in the margin of error of the actual transaction finish time (finalEndTimestamp)
       Math.abs(finish.timestamp - finalEndTimestamp) < MARGIN_OF_ERROR_SECONDS
     ) {
+      logger.debug(`[NativeFrames] Using frames from root span end (traceId, ${traceId}).`);
       finalFinishFrames = finish.nativeFrames;
     } else if (
       this._lastSpanFinishFrames &&
       Math.abs(this._lastSpanFinishFrames.timestamp - finalEndTimestamp) < MARGIN_OF_ERROR_SECONDS
     ) {
       // Fallback to the last span finish if it is within the margin of error of the actual finish timestamp.
       // This should be the case for trimEnd.
+      logger.debug(`[NativeFrames] Using native frames from last span end (traceId, ${traceId}).`);
       finalFinishFrames = this._lastSpanFinishFrames.nativeFrames;
     } else {
+      logger.warn(
+        `[NativeFrames] Frames were collected within larger than margin of error delay for traceId (${traceId}). Dropping the inaccurate values.`,
+      );
       return null;
     }
 
@@ -170,7 +198,7 @@ export class NativeFramesInstrumentation {
   /**
    * Fetch finish frames for a transaction at the current time. Calls any awaiting listeners.
    */
-  private async _fetchFramesForTransaction(transaction: Transaction): Promise<void> {
+  private async _fetchEndFramesForTransaction(transaction: Transaction): Promise<void> {
     const startFrames = transaction.data.__startFrames as NativeFramesResponse | undefined;
 
     // This timestamp marks when the finish frames were retrieved. It should be pretty close to the transaction finish.
@@ -187,13 +215,13 @@ export class NativeFramesInstrumentation {
 
     _framesListeners.get(transaction.traceId)?.();
 
-    setTimeout(() => this._cancelFinishFrames(transaction), 2000);
+    setTimeout(() => this._cancelEndFrames(transaction), FINAL_FRAMES_TIMEOUT_MS);
   }
 
   /**
    * On a finish frames failure, we cancel the await.
    */
-  private _cancelFinishFrames(transaction: Transaction): void {
+  private _cancelEndFrames(transaction: Transaction): void {
     if (_finishFrames.has(transaction.traceId)) {
       _finishFrames.delete(transaction.traceId);
 
@@ -222,18 +250,20 @@ export class NativeFramesInstrumentation {
 
       const traceId = traceContext.trace_id;
 
+      if (!traceContext.data?.__startFrames) {
+        logger.warn(
+          `[NativeFrames] Start frames of transaction ${event.transaction} (eventId, ${event.event_id}) are missing, but it already ended.`,
+        );
+      }
+
       if (traceId && traceContext.data?.__startFrames && event.timestamp) {
         const measurements = await this._getFramesMeasurements(
           traceId,
           event.timestamp,
           traceContext.data.__startFrames as NativeFramesResponse,
         );
 
-        if (!measurements) {
-          logger.log(
-            `[NativeFrames] Could not fetch native frames for ${traceContext.op} transaction ${event.transaction}. Not adding native frames measurements.`,
-          );
-        } else {
+        if (measurements) {
           logger.log(
             `[Measurements] Adding measurements to ${traceContext.op} transaction ${
               event.transaction

src/js/tracing/reactnativetracing.ts

@@ -279,6 +279,12 @@ export class ReactNativeTracing implements Integration {
       // Only if this method is called at or within margin of error to the start timestamp.
       this.nativeFramesInstrumentation?.onTransactionStart(transaction);
       this.stallTrackingInstrumentation?.onTransactionStart(transaction);
+    } else {
+      logger.warn(
+        `[ReactNativeTracing] onTransactionStart called with delay (larger than margin of error) for transaction ${
+          transaction.description
+        } (${transaction.spanContext().spanId}). Not fetching native frames or tracking stalls.`,
+      );
     }
   }