diff --git a/CHANGELOG.md b/CHANGELOG.md index deec3456aa..95772a98fb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,7 @@ - Adds Metrics Beta ([#5402](https://github.com/getsentry/sentry-react-native/pull/5402)) - Improves Expo Router integration to optionally include full paths to components instead of just component names ([#5414](https://github.com/getsentry/sentry-react-native/pull/5414)) +- Report slow and frozen frames as TTID/TTFD span data ([#5419](https://github.com/getsentry/sentry-react-native/pull/5419)) ### Fixes diff --git a/packages/core/src/js/tracing/timetodisplay.tsx b/packages/core/src/js/tracing/timetodisplay.tsx index b5e02a1147..976fb02d6f 100644 --- a/packages/core/src/js/tracing/timetodisplay.tsx +++ b/packages/core/src/js/tracing/timetodisplay.tsx @@ -1,11 +1,25 @@ -import type { Span,StartSpanOptions } from '@sentry/core'; +/* eslint-disable max-lines */ +import type { Span, StartSpanOptions } from '@sentry/core'; import { debug, fill, getActiveSpan, getSpanDescendants, 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 { NATIVE } from '../wrapper'; import { SPAN_ORIGIN_AUTO_UI_TIME_TO_DISPLAY, SPAN_ORIGIN_MANUAL_UI_TIME_TO_DISPLAY } from './origin'; import { getRNSentryOnDrawReporter } from './timetodisplaynative'; import { setSpanDurationAsMeasurement, setSpanDurationAsMeasurementOnSpan } from './utils'; +/** + * Timeout for fetching native frames + */ +const FETCH_FRAMES_TIMEOUT_MS = 2_000; + +/** + * Maximum time to keep frame data in memory before cleaning up. + * Prevents memory leaks for spans that never complete. + */ +const FRAME_DATA_CLEANUP_TIMEOUT_MS = 60_000; + /** * Flags of active spans with manual initial display. */ @@ -16,6 +30,20 @@ export const manualInitialDisplaySpans = new WeakMap(); */ const fullDisplayBeforeInitialDisplay = new WeakMap(); +interface FrameDataForSpan { + startFrames: NativeFramesResponse | null; + endFrames: NativeFramesResponse | null; + cleanupTimeout?: ReturnType; +} + +/** + * Stores frame data for in-flight TTID/TTFD spans. + * Entries are automatically cleaned up when spans end (in captureEndFramesAndAttachToSpan finally block). + * As a safety mechanism, entries are also cleaned up after FRAME_DATA_CLEANUP_TIMEOUT_MS + * to prevent memory leaks for spans that never complete. + */ +const spanFrameDataMap = new Map(); + export type TimeToDisplayProps = { children?: React.ReactNode; record?: boolean; @@ -105,6 +133,10 @@ export function startTimeToInitialDisplaySpan( return undefined; } + captureStartFramesForSpan(initialDisplaySpan.spanContext().spanId).catch((error) => { + debug.log(`[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 { @@ -161,13 +193,26 @@ export function startTimeToFullDisplaySpan( return undefined; } + captureStartFramesForSpan(fullDisplaySpan.spanContext().spanId).catch((error) => { + debug.log(`[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(() => { + debug.log(`[TimeToDisplay] ${fullDisplaySpan.spanContext().spanId} span updated with frame data.`); + fullDisplaySpan.end(spanToJSON(initialDisplaySpan).timestamp); + setSpanDurationAsMeasurement('time_to_full_display', fullDisplaySpan); + }).catch(() => { + debug.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); + }); + debug.warn('[TimeToDisplay] Full display span deadline_exceeded.'); }, options.timeoutMs); @@ -220,17 +265,31 @@ export function updateInitialDisplaySpan( return; } - span.end(frameTimestampSeconds); - span.setStatus({ code: SPAN_STATUS_OK }); - debug.log(`[TimeToDisplay] ${spanToJSON(span).description} span updated with end timestamp.`); + captureEndFramesAndAttachToSpan(span).then(() => { + span.end(frameTimestampSeconds); + span.setStatus({ code: SPAN_STATUS_OK }); + debug.log(`[TimeToDisplay] ${spanToJSON(span).description} span updated with end timestamp and frame data.`); + + if (fullDisplayBeforeInitialDisplay.has(activeSpan)) { + fullDisplayBeforeInitialDisplay.delete(activeSpan); + debug.log(`[TimeToDisplay] Updating full display with initial display (${span.spanContext().spanId}) end.`); + updateFullDisplaySpan(frameTimestampSeconds, span); + } - if (fullDisplayBeforeInitialDisplay.has(activeSpan)) { - fullDisplayBeforeInitialDisplay.delete(activeSpan); - debug.log(`[TimeToDisplay] Updating full display with initial display (${span.spanContext().spanId}) end.`); - updateFullDisplaySpan(frameTimestampSeconds, span); - } + setSpanDurationAsMeasurementOnSpan('time_to_initial_display', span, activeSpan); + }).catch((error) => { + debug.log('[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); + debug.log(`[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); + }); } function updateFullDisplaySpan(frameTimestampSeconds: number, passedInitialDisplaySpan?: Span): void { @@ -263,17 +322,26 @@ function updateFullDisplaySpan(frameTimestampSeconds: number, passedInitialDispl return; } - if (initialDisplayEndTimestamp > frameTimestampSeconds) { - debug.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 }); - debug.log(`[TimeToDisplay] ${spanJSON.description} (${spanJSON.span_id}) span updated with end timestamp.`); + if (initialDisplayEndTimestamp > frameTimestampSeconds) { + debug.warn('[TimeToDisplay] Using initial display end. Full display end frame timestamp is before initial display end.'); + } + + span.end(endTimestamp); + span.setStatus({ code: SPAN_STATUS_OK }); + debug.log(`[TimeToDisplay] ${spanJSON.description} (${spanJSON.span_id}) span updated with end timestamp and frame data.`); + + setSpanDurationAsMeasurement('time_to_full_display', span); + }).catch((error) => { + debug.log('[TimeToDisplay] Failed to capture frame data for full display span.', error); + const endTimestamp = initialDisplayEndTimestamp > frameTimestampSeconds ? initialDisplayEndTimestamp : frameTimestampSeconds; - setSpanDurationAsMeasurement('time_to_full_display', span); + span.end(endTimestamp); + span.setStatus({ code: SPAN_STATUS_OK }); + setSpanDurationAsMeasurement('time_to_full_display', span); + }); } /** @@ -327,3 +395,143 @@ 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) { + debug.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); + + debug.log('[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 { + if (!NATIVE.enableNative) { + return; + } + + try { + const startFrames = await fetchNativeFramesWithTimeout(); + + // Set up automatic cleanup as a safety mechanism for spans that never complete + const cleanupTimeout = setTimeout(() => { + const entry = spanFrameDataMap.get(spanId); + if (entry) { + spanFrameDataMap.delete(spanId); + debug.log(`[TimeToDisplay] Cleaned up stale frame data for span ${spanId} after timeout.`); + } + }, FRAME_DATA_CLEANUP_TIMEOUT_MS); + + if (!spanFrameDataMap.has(spanId)) { + spanFrameDataMap.set(spanId, { startFrames: null, endFrames: null, cleanupTimeout }); + } + + // Re-check after async operations - entry might have been deleted by captureEndFramesAndAttachToSpan + const frameData = spanFrameDataMap.get(spanId); + if (!frameData) { + // Span already ended and cleaned up, cancel the cleanup timeout + clearTimeout(cleanupTimeout); + debug.log(`[TimeToDisplay] Span ${spanId} already ended, discarding start frames.`); + return; + } + + frameData.startFrames = startFrames; + frameData.cleanupTimeout = cleanupTimeout; + debug.log(`[TimeToDisplay] Captured start frames for span ${spanId}.`, startFrames); + } catch (error) { + debug.log(`[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 { + if (!NATIVE.enableNative) { + return; + } + + const spanId = span.spanContext().spanId; + const frameData = spanFrameDataMap.get(spanId); + + if (!frameData?.startFrames) { + debug.log(`[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); + + debug.log(`[TimeToDisplay] Captured and attached end frames for span ${spanId}.`, endFrames); + } catch (error) { + debug.log(`[TimeToDisplay] Failed to capture end frames for span ${spanId}.`, error); + } finally { + // Clear the cleanup timeout since we're cleaning up now + if (frameData.cleanupTimeout) { + clearTimeout(frameData.cleanupTimeout); + } + spanFrameDataMap.delete(spanId); + } +} + +/** + * Fetches native frames with a timeout + */ +function fetchNativeFramesWithTimeout(): Promise { + return new Promise((resolve, reject) => { + let settled = false; + + const timeoutId = setTimeout(() => { + if (!settled) { + settled = true; + reject('Fetching native frames took too long. Dropping frames.'); + } + }, FETCH_FRAMES_TIMEOUT_MS); + + NATIVE.fetchNativeFrames() + .then(value => { + if (settled) { + return; + } + clearTimeout(timeoutId); + settled = true; + + if (!value) { + reject('Native frames response is null.'); + return; + } + resolve(value); + }) + .then(undefined, (error: unknown) => { + if (settled) { + return; + } + clearTimeout(timeoutId); + settled = true; + reject(error); + }); + }); +} diff --git a/packages/core/test/tracing/timetodisplay.test.tsx b/packages/core/test/tracing/timetodisplay.test.tsx index b66a4f8828..8258dc224a 100644 --- a/packages/core/test/tracing/timetodisplay.test.tsx +++ b/packages/core/test/tracing/timetodisplay.test.tsx @@ -17,7 +17,7 @@ import { timeToDisplayIntegration } from '../../src/js/tracing/integrations/time import { SPAN_ORIGIN_MANUAL_UI_TIME_TO_DISPLAY } from '../../src/js/tracing/origin'; import { SEMANTIC_ATTRIBUTE_SENTRY_OP, SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN } from '../../src/js/tracing/semanticAttributes'; import { SPAN_THREAD_NAME , SPAN_THREAD_NAME_JAVASCRIPT } from '../../src/js/tracing/span'; -import { startTimeToFullDisplaySpan, startTimeToInitialDisplaySpan, TimeToFullDisplay, TimeToInitialDisplay } from '../../src/js/tracing/timetodisplay'; +import { startTimeToFullDisplaySpan, startTimeToInitialDisplaySpan, TimeToFullDisplay, TimeToInitialDisplay, updateInitialDisplaySpan } from '../../src/js/tracing/timetodisplay'; import { getDefaultTestClientOptions, TestClient } from '../mocks/client'; import { nowInSeconds, secondAgoTimestampMs, secondInFutureTimestampMs } from '../testutils'; @@ -58,6 +58,8 @@ describe('TimeToDisplay', () => { afterEach(() => { jest.clearAllMocks(); + // Ensure mock properties are reset to default values for test isolation + mockWrapper.NATIVE.enableNative = true; }); test('creates manual initial display', async () => { @@ -390,3 +392,238 @@ function expectNoFullDisplayMeasurementOnSpan(event: Event) { expect.not.objectContaining({ time_to_full_display: expect.anything() }), ]); } + +describe('Frame Data', () => { + let client: TestClient; + + beforeEach(() => { + clearMockedOnDrawReportedProps(); + getCurrentScope().clear(); + getIsolationScope().clear(); + getGlobalScope().clear(); + + const options = getDefaultTestClientOptions({ + tracesSampleRate: 1.0, + }); + client = new TestClient({ + ...options, + integrations: [ + ...options.integrations, + timeToDisplayIntegration(), + ], + }); + setCurrentClient(client); + client.init(); + + // Note: jest.clearAllMocks() in afterEach handles this, but we clear explicitly for clarity + mockWrapper.NATIVE.fetchNativeFrames.mockClear(); + }); + + afterEach(() => { + jest.clearAllMocks(); + // Ensure mock properties are reset to default values for test isolation + mockWrapper.NATIVE.enableNative = true; + }); + + test('attaches frame data to initial display span', async () => { + const startFrames = { totalFrames: 100, slowFrames: 2, frozenFrames: 1 }; + const endFrames = { totalFrames: 150, slowFrames: 5, frozenFrames: 2 }; + + mockWrapper.NATIVE.fetchNativeFrames + .mockResolvedValueOnce(startFrames) + .mockResolvedValueOnce(endFrames); + + await startSpanManual( + { + name: 'Root Manual Span', + startTime: secondAgoTimestampMs(), + }, + async (activeSpan: Span | undefined) => { + const ttidSpan = startTimeToInitialDisplaySpan(); + render(); + + // Flush the entire start frame capture promise chain + // Need multiple awaits because captureStartFramesForSpan -> fetchNativeFramesWithTimeout -> NATIVE.fetchNativeFrames + await Promise.resolve(); + await Promise.resolve(); + await Promise.resolve(); + + // Simulate native onDraw callback that triggers span end with frame capture + updateInitialDisplaySpan(nowInSeconds(), { activeSpan, span: ttidSpan }); + + // Allow end frame capture promise chain to complete + await Promise.resolve(); + await Promise.resolve(); + await Promise.resolve(); + + activeSpan?.end(); + }, + ); + + await jest.runOnlyPendingTimersAsync(); + await client.flush(); + + // Verify frame capture was called twice (start and end) + expect(mockWrapper.NATIVE.fetchNativeFrames).toHaveBeenCalledTimes(2); + + const ttidSpan = client.event!.spans!.find((span: SpanJSON) => span.op === 'ui.load.initial_display'); + expect(ttidSpan).toBeDefined(); + + // Verify frame data is attached (delta: 150-100=50, 5-2=3, 2-1=1) + expect(ttidSpan!.data).toEqual( + expect.objectContaining({ + 'frames.total': 50, + 'frames.slow': 3, + 'frames.frozen': 1, + }), + ); + }); + + test('captures frame data for full display span', async () => { + const startFrames = { totalFrames: 100, slowFrames: 2, frozenFrames: 1 }; + const endFrames = { totalFrames: 200, slowFrames: 8, frozenFrames: 3 }; + + mockWrapper.NATIVE.fetchNativeFrames + .mockResolvedValueOnce(startFrames) + .mockResolvedValueOnce(startFrames) + .mockResolvedValueOnce(endFrames) + .mockResolvedValueOnce(endFrames); + + startSpanManual( + { + name: 'Root Manual Span', + startTime: secondAgoTimestampMs(), + }, + (activeSpan: Span | undefined) => { + startTimeToInitialDisplaySpan(); + startTimeToFullDisplaySpan(); + + render(); + render(); + mockRecordedTimeToDisplay({ + ttid: { + [spanToJSON(activeSpan).span_id]: nowInSeconds(), + }, + ttfd: { + [spanToJSON(activeSpan).span_id]: secondInFutureTimestampMs() / 1000, + }, + }); + + activeSpan?.end(); + }, + ); + + await jest.runOnlyPendingTimersAsync(); + await client.flush(); + + // Verify frame capture was initiated for both spans + expect(mockWrapper.NATIVE.fetchNativeFrames).toHaveBeenCalled(); + + const ttidSpan = client.event!.spans!.find((span: SpanJSON) => span.op === 'ui.load.initial_display'); + const ttfdSpan = client.event!.spans!.find((span: SpanJSON) => span.op === 'ui.load.full_display'); + expect(ttidSpan).toBeDefined(); + expect(ttfdSpan).toBeDefined(); + + // Note: This test doesn't manually trigger span end like the previous test, + // so frame capture is initiated but not completed in the test flow. + }); + + test('does not attach frame data when frames are zero', async () => { + const frames = { totalFrames: 100, slowFrames: 2, frozenFrames: 1 }; + + mockWrapper.NATIVE.fetchNativeFrames + .mockResolvedValueOnce(frames) + .mockResolvedValueOnce(frames); // Same frames = delta of 0 + + startSpanManual( + { + name: 'Root Manual Span', + startTime: secondAgoTimestampMs(), + }, + (activeSpan: Span | undefined) => { + startTimeToInitialDisplaySpan(); + render(); + mockRecordedTimeToDisplay({ + ttid: { + [spanToJSON(activeSpan).span_id]: nowInSeconds(), + }, + }); + + activeSpan?.end(); + }, + ); + + await jest.runOnlyPendingTimersAsync(); + await client.flush(); + + const ttidSpan = client.event!.spans!.find((span: SpanJSON) => span.op === 'ui.load.initial_display'); + expect(ttidSpan).toBeDefined(); + expect(ttidSpan!.data).not.toHaveProperty('frames.total'); + expect(ttidSpan!.data).not.toHaveProperty('frames.slow'); + expect(ttidSpan!.data).not.toHaveProperty('frames.frozen'); + }); + + test('does not attach frame data when fetchNativeFrames fails', async () => { + mockWrapper.NATIVE.fetchNativeFrames.mockRejectedValue(new Error('Failed to fetch frames')); + + startSpanManual( + { + name: 'Root Manual Span', + startTime: secondAgoTimestampMs(), + }, + (activeSpan: Span | undefined) => { + startTimeToInitialDisplaySpan(); + render(); + mockRecordedTimeToDisplay({ + ttid: { + [spanToJSON(activeSpan).span_id]: nowInSeconds(), + }, + }); + + activeSpan?.end(); + }, + ); + + await jest.runOnlyPendingTimersAsync(); + await client.flush(); + + const ttidSpan = client.event!.spans!.find((span: SpanJSON) => span.op === 'ui.load.initial_display'); + expect(ttidSpan).toBeDefined(); + expect(ttidSpan!.data).not.toHaveProperty('frames.total'); + expect(ttidSpan!.data).not.toHaveProperty('frames.slow'); + expect(ttidSpan!.data).not.toHaveProperty('frames.frozen'); + }); + + test('does not attach frame data when native is disabled', async () => { + mockWrapper.NATIVE.enableNative = false; + + startSpanManual( + { + name: 'Root Manual Span', + startTime: secondAgoTimestampMs(), + }, + (activeSpan: Span | undefined) => { + startTimeToInitialDisplaySpan(); + render(); + mockRecordedTimeToDisplay({ + ttid: { + [spanToJSON(activeSpan).span_id]: nowInSeconds(), + }, + }); + + activeSpan?.end(); + }, + ); + + await jest.runOnlyPendingTimersAsync(); + await client.flush(); + + const ttidSpan = client.event!.spans!.find((span: SpanJSON) => span.op === 'ui.load.initial_display'); + expect(ttidSpan).toBeDefined(); + expect(ttidSpan!.data).not.toHaveProperty('frames.total'); + expect(ttidSpan!.data).not.toHaveProperty('frames.slow'); + expect(ttidSpan!.data).not.toHaveProperty('frames.frozen'); + + // Note: Reset happens in afterEach, not here + }); +});