Add frame data to time to display spans

Author: antonis

packages/core/src/js/tracing/timetodisplay.tsx

@@ -1,15 +1,23 @@
-import type { Span,StartSpanOptions  } from '@sentry/core';
+/* eslint-disable max-lines */
+import type { Span, StartSpanOptions } from '@sentry/core';
 import { fill, getActiveSpan, getSpanDescendants, logger, SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN, SPAN_STATUS_ERROR, SPAN_STATUS_OK, spanToJSON, startInactiveSpan } from '@sentry/core';
 import * as React from 'react';
 import { useState } from 'react';
 
+import type { NativeFramesResponse } from '../NativeRNSentry';
 import { isTurboModuleEnabled } from '../utils/environment';
+import { NATIVE } from '../wrapper';
 import { SPAN_ORIGIN_AUTO_UI_TIME_TO_DISPLAY, SPAN_ORIGIN_MANUAL_UI_TIME_TO_DISPLAY } from './origin';
 import { getRNSentryOnDrawReporter, nativeComponentExists } from './timetodisplaynative';
 import { setSpanDurationAsMeasurement, setSpanDurationAsMeasurementOnSpan } from './utils';
 
 let nativeComponentMissingLogged = false;
 
+/**
+ * Timeout for fetching native frames
+ */
+const FETCH_FRAMES_TIMEOUT_MS = 2_000;
+
 /**
  * Flags of active spans with manual initial display.
  */
@@ -20,6 +28,13 @@ export const manualInitialDisplaySpans = new WeakMap<Span, true>();
  */
 const fullDisplayBeforeInitialDisplay = new WeakMap<Span, true>();
 
+interface FrameDataForSpan {
+  startFrames: NativeFramesResponse | null;
+  endFrames: NativeFramesResponse | null;
+}
+
+const spanFrameDataMap = new Map<string, FrameDataForSpan>();
+
 export type TimeToDisplayProps = {
   children?: React.ReactNode;
   record?: boolean;
@@ -106,7 +121,7 @@ export function startTimeToInitialDisplaySpan(
   const existingSpan = getSpanDescendants(activeSpan).find((span) => spanToJSON(span).op === 'ui.load.initial_display');
   if (existingSpan) {
     logger.debug(`[TimeToDisplay] Found existing ui.load.initial_display span.`);
-    return existingSpan
+    return existingSpan;
   }
 
   const initialDisplaySpan = startInactiveSpan({
@@ -120,6 +135,10 @@ export function startTimeToInitialDisplaySpan(
     return undefined;
   }
 
+  captureStartFramesForSpan(initialDisplaySpan.spanContext().spanId).catch((error) => {
+    logger.debug(`[TimeToDisplay] Failed to capture start frames for initial display span (${initialDisplaySpan.spanContext().spanId}).`, error);
+  });
+
   if (options?.isAutoInstrumented) {
     initialDisplaySpan.setAttribute(SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN, SPAN_ORIGIN_AUTO_UI_TIME_TO_DISPLAY);
   } else {
@@ -176,13 +195,26 @@ export function startTimeToFullDisplaySpan(
     return undefined;
   }
 
+  captureStartFramesForSpan(fullDisplaySpan.spanContext().spanId).catch((error) => {
+    logger.debug(`[TimeToDisplay] Failed to capture start frames for full display span(${fullDisplaySpan.spanContext().spanId}).`, error);
+  });
+
   const timeout = setTimeout(() => {
     if (spanToJSON(fullDisplaySpan).timestamp) {
       return;
     }
     fullDisplaySpan.setStatus({ code: SPAN_STATUS_ERROR, message: 'deadline_exceeded' });
-    fullDisplaySpan.end(spanToJSON(initialDisplaySpan).timestamp);
-    setSpanDurationAsMeasurement('time_to_full_display', fullDisplaySpan);
+
+    captureEndFramesAndAttachToSpan(fullDisplaySpan).then(() => {
+      logger.debug(`[TimeToDisplay] ${fullDisplaySpan.spanContext().spanId} span updated with frame data.`);
+      fullDisplaySpan.end(spanToJSON(initialDisplaySpan).timestamp);
+      setSpanDurationAsMeasurement('time_to_full_display', fullDisplaySpan);
+    }).catch(() => {
+      logger.warn(`[TimeToDisplay] Failed to capture end frames for full display span (${fullDisplaySpan.spanContext().spanId}).`);
+      fullDisplaySpan.end(spanToJSON(initialDisplaySpan).timestamp);
+      setSpanDurationAsMeasurement('time_to_full_display', fullDisplaySpan);
+    });
+
     logger.warn(`[TimeToDisplay] Full display span deadline_exceeded.`);
   }, options.timeoutMs);
 
@@ -235,17 +267,31 @@ export function updateInitialDisplaySpan(
     return;
   }
 
-  span.end(frameTimestampSeconds);
-  span.setStatus({ code: SPAN_STATUS_OK });
-  logger.debug(`[TimeToDisplay] ${spanToJSON(span).description} span updated with end timestamp.`);
+  captureEndFramesAndAttachToSpan(span).then(() => {
+    span.end(frameTimestampSeconds);
+    span.setStatus({ code: SPAN_STATUS_OK });
+    logger.debug(`[TimeToDisplay] ${spanToJSON(span).description} span updated with end timestamp and frame data.`);
 
-  if (fullDisplayBeforeInitialDisplay.has(activeSpan)) {
-    fullDisplayBeforeInitialDisplay.delete(activeSpan);
-    logger.debug(`[TimeToDisplay] Updating full display with initial display (${span.spanContext().spanId}) end.`);
-    updateFullDisplaySpan(frameTimestampSeconds, span);
-  }
+    if (fullDisplayBeforeInitialDisplay.has(activeSpan)) {
+      fullDisplayBeforeInitialDisplay.delete(activeSpan);
+      logger.debug(`[TimeToDisplay] Updating full display with initial display (${span.spanContext().spanId}) end.`);
+      updateFullDisplaySpan(frameTimestampSeconds, span);
+    }
 
-  setSpanDurationAsMeasurementOnSpan('time_to_initial_display', span, activeSpan);
+    setSpanDurationAsMeasurementOnSpan('time_to_initial_display', span, activeSpan);
+  }).catch((error) => {
+    logger.debug(`[TimeToDisplay] Failed to capture frame data for initial display span.`, error);
+    span.end(frameTimestampSeconds);
+    span.setStatus({ code: SPAN_STATUS_OK });
+
+    if (fullDisplayBeforeInitialDisplay.has(activeSpan)) {
+      fullDisplayBeforeInitialDisplay.delete(activeSpan);
+      logger.debug(`[TimeToDisplay] Updating full display with initial display (${span.spanContext().spanId}) end.`);
+      updateFullDisplaySpan(frameTimestampSeconds, span);
+    }
+
+    setSpanDurationAsMeasurementOnSpan('time_to_initial_display', span, activeSpan);
+  });
 }
 
 function updateFullDisplaySpan(frameTimestampSeconds: number, passedInitialDisplaySpan?: Span): void {
@@ -278,17 +324,26 @@ function updateFullDisplaySpan(frameTimestampSeconds: number, passedInitialDispl
     return;
   }
 
-  if (initialDisplayEndTimestamp > frameTimestampSeconds) {
-    logger.warn(`[TimeToDisplay] Using initial display end. Full display end frame timestamp is before initial display end.`);
-    span.end(initialDisplayEndTimestamp);
-  } else {
-    span.end(frameTimestampSeconds);
-  }
+  captureEndFramesAndAttachToSpan(span).then(() => {
+    const endTimestamp = initialDisplayEndTimestamp > frameTimestampSeconds ? initialDisplayEndTimestamp : frameTimestampSeconds;
 
-  span.setStatus({ code: SPAN_STATUS_OK });
-  logger.debug(`[TimeToDisplay] ${spanJSON.description} (${spanJSON.span_id}) span updated with end timestamp.`);
+    if (initialDisplayEndTimestamp > frameTimestampSeconds) {
+      logger.warn(`[TimeToDisplay] Using initial display end. Full display end frame timestamp is before initial display end.`);
+    }
 
-  setSpanDurationAsMeasurement('time_to_full_display', span);
+    span.end(endTimestamp);
+    span.setStatus({ code: SPAN_STATUS_OK });
+    logger.debug(`[TimeToDisplay] ${spanJSON.description} (${spanJSON.span_id}) span updated with end timestamp and frame data.`);
+
+    setSpanDurationAsMeasurement('time_to_full_display', span);
+  }).catch((error) => {
+    logger.debug(`[TimeToDisplay] Failed to capture frame data for full display span.`, error);
+    const endTimestamp = initialDisplayEndTimestamp > frameTimestampSeconds ? initialDisplayEndTimestamp : frameTimestampSeconds;
+
+    span.end(endTimestamp);
+    span.setStatus({ code: SPAN_STATUS_OK });
+    setSpanDurationAsMeasurement('time_to_full_display', span);
+  });
 }
 
 /**
@@ -342,3 +397,103 @@ function createTimeToDisplay({
   TimeToDisplayWrapper.displayName = `TimeToDisplayWrapper`;
   return TimeToDisplayWrapper;
 }
+
+/**
+ * Attaches frame data to a span's data object.
+ */
+function attachFrameDataToSpan(span: Span, startFrames: NativeFramesResponse, endFrames: NativeFramesResponse): void {
+  const totalFrames = endFrames.totalFrames - startFrames.totalFrames;
+  const slowFrames = endFrames.slowFrames - startFrames.slowFrames;
+  const frozenFrames = endFrames.frozenFrames - startFrames.frozenFrames;
+
+  if (totalFrames <= 0 && slowFrames <= 0 && frozenFrames <= 0) {
+    logger.warn(`[TimeToDisplay] Detected zero slow or frozen frames. Not adding measurements to span (${span.spanContext().spanId}).`);
+    return;
+  }
+  span.setAttribute('frames.total', totalFrames);
+  span.setAttribute('frames.slow', slowFrames);
+  span.setAttribute('frames.frozen', frozenFrames);
+
+  logger.debug('[TimeToDisplay] Attached frame data to span.', {
+    spanId: span.spanContext().spanId,
+    frameData: {
+      total: totalFrames,
+      slow: slowFrames,
+      frozen: frozenFrames,
+    },
+  });
+}
+
+/**
+ * Captures start frames for a time-to-display span
+ */
+async function captureStartFramesForSpan(spanId: string): Promise<void> {
+  if (!NATIVE.enableNative) {
+    return;
+  }
+
+  try {
+    const startFrames = await fetchNativeFramesWithTimeout();
+    if (!spanFrameDataMap.has(spanId)) {
+      spanFrameDataMap.set(spanId, { startFrames: null, endFrames: null });
+    }
+    const frameData = spanFrameDataMap.get(spanId)!;
+    frameData.startFrames = startFrames;
+    logger.debug(`[TimeToDisplay] Captured start frames for span ${spanId}.`, startFrames);
+  } catch (error) {
+    logger.debug(`[TimeToDisplay] Failed to capture start frames for span ${spanId}.`, error);
+  }
+}
+
+/**
+ * Captures end frames and attaches frame data to span
+ */
+async function captureEndFramesAndAttachToSpan(span: Span): Promise<void> {
+  if (!NATIVE.enableNative) {
+    return;
+  }
+
+  const spanId = span.spanContext().spanId;
+  const frameData = spanFrameDataMap.get(spanId);
+
+  if (!frameData?.startFrames) {
+    logger.debug(`[TimeToDisplay] No start frames found for span ${spanId}, skipping frame data collection.`);
+    return;
+  }
+
+  try {
+    const endFrames = await fetchNativeFramesWithTimeout();
+    frameData.endFrames = endFrames;
+
+    attachFrameDataToSpan(span, frameData.startFrames, endFrames);
+
+    logger.debug(`[TimeToDisplay] Captured and attached end frames for span ${spanId}.`, endFrames);
+  } catch (error) {
+    logger.debug(`[TimeToDisplay] Failed to capture end frames for span ${spanId}.`, error);
+  } finally {
+    spanFrameDataMap.delete(spanId);
+  }
+}
+
+/**
+ * Fetches native frames with a timeout
+ */
+function fetchNativeFramesWithTimeout(): Promise<NativeFramesResponse> {
+  return new Promise<NativeFramesResponse>((resolve, reject) => {
+    NATIVE.fetchNativeFrames()
+      .then(value => {
+        if (!value) {
+          reject('Native frames response is null.');
+          return;
+        }
+        resolve(value);
+      })
+      .then(undefined, (error: unknown) => {
+        reject(error);
+      });
+
+    setTimeout(() => {
+      reject('Fetching native frames took too long. Dropping frames.');
+    }, FETCH_FRAMES_TIMEOUT_MS);
+  });
+}