From 32592ee9e5817cb616f2efecb455ade040dcb39c Mon Sep 17 00:00:00 2001 From: Antonis Lilis Date: Tue, 27 May 2025 21:16:48 +0300 Subject: [PATCH 1/7] feat(appStart): Add frame data in app start span --- .../src/js/tracing/integrations/appStart.ts | 80 +++++++- .../tracing/integrations/appStart.test.ts | 181 +++++++++++++++++- .../tracing/reactnavigation.ttid.test.tsx | 7 +- 3 files changed, 252 insertions(+), 16 deletions(-) diff --git a/packages/core/src/js/tracing/integrations/appStart.ts b/packages/core/src/js/tracing/integrations/appStart.ts index df0713bc57..5504552bed 100644 --- a/packages/core/src/js/tracing/integrations/appStart.ts +++ b/packages/core/src/js/tracing/integrations/appStart.ts @@ -16,7 +16,7 @@ import { APP_START_COLD as APP_START_COLD_MEASUREMENT, APP_START_WARM as APP_START_WARM_MEASUREMENT, } from '../../measurements'; -import type { NativeAppStartResponse } from '../../NativeRNSentry'; +import type { NativeAppStartResponse, NativeFramesResponse } from '../../NativeRNSentry'; import type { ReactNativeClientOptions } from '../../options'; import { convertSpanToTransaction, isRootSpan, setEndTimeValue } from '../../utils/span'; import { NATIVE } from '../../wrapper'; @@ -49,7 +49,12 @@ const MAX_APP_START_AGE_MS = 60_000; /** App Start transaction name */ const APP_START_TX_NAME = 'App Start'; -let recordedAppStartEndTimestampMs: number | undefined = undefined; +interface AppStartEndData { + timestampMs: number; + endFrames: NativeFramesResponse | null; +} + +let appStartEndData: AppStartEndData | undefined = undefined; let isRecordedAppStartEndTimestampMsManual = false; let rootComponentCreationTimestampMs: number | undefined = undefined; @@ -76,7 +81,24 @@ export async function _captureAppStart({ isManual }: { isManual: boolean }): Pro } isRecordedAppStartEndTimestampMsManual = isManual; - _setAppStartEndTimestampMs(timestampInSeconds() * 1000); + + const timestampMs = timestampInSeconds() * 1000; + let endFrames: NativeFramesResponse | null = null; + + if (NATIVE.enableNative) { + try { + endFrames = await NATIVE.fetchNativeFrames(); + logger.debug('[AppStart] Captured end frames for app start.', endFrames); + } catch (error) { + logger.debug('[AppStart] Failed to capture end frames for app start.', error); + } + } + + _setAppStartEndData({ + timestampMs, + endFrames, + }); + await client.getIntegrationByName(INTEGRATION_NAME)?.captureStandaloneAppStart(); } @@ -85,8 +107,7 @@ export async function _captureAppStart({ isManual }: { isManual: boolean }): Pro * Used automatically by `Sentry.wrap` and `Sentry.ReactNativeProfiler`. */ export function setRootComponentCreationTimestampMs(timestampMs: number): void { - recordedAppStartEndTimestampMs && - logger.warn('Setting Root component creation timestamp after app start end is set.'); + appStartEndData?.timestampMs && logger.warn('Setting Root component creation timestamp after app start end is set.'); rootComponentCreationTimestampMs && logger.warn('Overwriting already set root component creation timestamp.'); rootComponentCreationTimestampMs = timestampMs; isRootComponentCreationTimestampMsManual = true; @@ -107,9 +128,9 @@ export function _setRootComponentCreationTimestampMs(timestampMs: number): void * * @private */ -export const _setAppStartEndTimestampMs = (timestampMs: number): void => { - recordedAppStartEndTimestampMs && logger.warn('Overwriting already set app start.'); - recordedAppStartEndTimestampMs = timestampMs; +export const _setAppStartEndData = (data: AppStartEndData): void => { + appStartEndData && logger.warn('Overwriting already set app start end data.'); + appStartEndData = data; }; /** @@ -121,6 +142,25 @@ export function _clearRootComponentCreationTimestampMs(): void { rootComponentCreationTimestampMs = undefined; } +/** + * Attaches frame data to a span's data object. + */ +function attachFrameDataToSpan(span: SpanJSON, frames: NativeFramesResponse): void { + span.data = span.data || {}; + span.data['frames.total'] = frames.totalFrames; + span.data['frames.slow'] = frames.slowFrames; + span.data['frames.frozen'] = frames.frozenFrames; + + logger.debug('[AppStart] Attached frame data to span.', { + spanId: span.span_id, + frameData: { + total: frames.totalFrames, + slow: frames.slowFrames, + frozen: frames.frozenFrames, + }, + }); +} + /** * Adds AppStart spans from the native layer to the transaction event. */ @@ -220,6 +260,21 @@ export const appStartIntegration = ({ logger.debug('[AppStart] App start tracking standalone root span (transaction).'); + if (!appStartEndData?.endFrames && NATIVE.enableNative) { + try { + const endFrames = await NATIVE.fetchNativeFrames(); + logger.debug('[AppStart] Captured end frames for standalone app start.', endFrames); + + const currentTimestamp = appStartEndData?.timestampMs || timestampInSeconds() * 1000; + _setAppStartEndData({ + timestampMs: currentTimestamp, + endFrames, + }); + } catch (error) { + logger.debug('[AppStart] Failed to capture frames for standalone app start.', error); + } + } + const span = startInactiveSpan({ forceTransaction: true, name: APP_START_TX_NAME, @@ -288,10 +343,10 @@ export const appStartIntegration = ({ return; } - const appStartEndTimestampMs = recordedAppStartEndTimestampMs || getBundleStartTimestampMs(); + const appStartEndTimestampMs = appStartEndData?.timestampMs || getBundleStartTimestampMs(); if (!appStartEndTimestampMs) { logger.warn( - '[AppStart] Javascript failed to record app start end. `setAppStartEndTimestampMs` was not called nor could the bundle start be found.', + '[AppStart] Javascript failed to record app start end. `_setAppStartEndData` was not called nor could the bundle start be found.', ); return; } @@ -368,6 +423,11 @@ export const appStartIntegration = ({ parent_span_id: event.contexts.trace.span_id, origin, }); + + if (appStartEndData?.endFrames) { + attachFrameDataToSpan(appStartSpanJSON, appStartEndData.endFrames); + } + const jsExecutionSpanJSON = createJSExecutionStartSpan(appStartSpanJSON, rootComponentCreationTimestampMs); const appStartSpans = [ diff --git a/packages/core/test/tracing/integrations/appStart.test.ts b/packages/core/test/tracing/integrations/appStart.test.ts index b31c35db66..1625c8d9e3 100644 --- a/packages/core/test/tracing/integrations/appStart.test.ts +++ b/packages/core/test/tracing/integrations/appStart.test.ts @@ -20,8 +20,9 @@ import { UI_LOAD, } from '../../../src/js/tracing'; import { + _captureAppStart, _clearRootComponentCreationTimestampMs, - _setAppStartEndTimestampMs, + _setAppStartEndData, _setRootComponentCreationTimestampMs, appStartIntegration, setRootComponentCreationTimestampMs, @@ -788,6 +789,169 @@ describe('App Start Integration', () => { }); }); +describe('Frame Data Integration', () => { + it('attaches frame data to standalone cold app start span', async () => { + const mockEndFrames = { + totalFrames: 150, + slowFrames: 5, + frozenFrames: 2, + }; + + mockFunction(NATIVE.fetchNativeFrames).mockResolvedValue(mockEndFrames); + + mockAppStart({ cold: true }); + + const actualEvent = await captureStandAloneAppStart(); + + const appStartSpan = actualEvent!.spans!.find(({ description }) => description === 'Cold App Start'); + + expect(appStartSpan).toBeDefined(); + expect(appStartSpan!.data).toEqual( + expect.objectContaining({ + 'frames.total': 150, + 'frames.slow': 5, + 'frames.frozen': 2, + [SEMANTIC_ATTRIBUTE_SENTRY_OP]: APP_START_COLD_OP, + [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: SPAN_ORIGIN_AUTO_APP_START, + }), + ); + }); + + it('attaches frame data to standalone warm app start span', async () => { + const mockEndFrames = { + totalFrames: 200, + slowFrames: 8, + frozenFrames: 1, + }; + + mockFunction(NATIVE.fetchNativeFrames).mockResolvedValue(mockEndFrames); + + mockAppStart({ cold: false }); + + const actualEvent = await captureStandAloneAppStart(); + + const appStartSpan = actualEvent!.spans!.find(({ description }) => description === 'Warm App Start'); + + expect(appStartSpan).toBeDefined(); + expect(appStartSpan!.data).toEqual( + expect.objectContaining({ + 'frames.total': 200, + 'frames.slow': 8, + 'frames.frozen': 1, + [SEMANTIC_ATTRIBUTE_SENTRY_OP]: APP_START_WARM_OP, + [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: SPAN_ORIGIN_AUTO_APP_START, + }), + ); + }); + + it('attaches frame data to attached cold app start span', async () => { + const mockEndFrames = { + totalFrames: 120, + slowFrames: 3, + frozenFrames: 0, + }; + + mockFunction(NATIVE.fetchNativeFrames).mockResolvedValue(mockEndFrames); + + mockAppStart({ cold: true }); + + await _captureAppStart({ isManual: false }); + + const actualEvent = await processEvent(getMinimalTransactionEvent()); + + const appStartSpan = actualEvent!.spans!.find(({ description }) => description === 'Cold App Start'); + + expect(appStartSpan).toBeDefined(); + expect(appStartSpan!.data).toEqual( + expect.objectContaining({ + 'frames.total': 120, + 'frames.slow': 3, + 'frames.frozen': 0, + [SEMANTIC_ATTRIBUTE_SENTRY_OP]: APP_START_COLD_OP, + [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: SPAN_ORIGIN_AUTO_APP_START, + }), + ); + }); + + it('attaches frame data to attached warm app start span', async () => { + const mockEndFrames = { + totalFrames: 180, + slowFrames: 12, + frozenFrames: 3, + }; + + mockFunction(NATIVE.fetchNativeFrames).mockResolvedValue(mockEndFrames); + + mockAppStart({ cold: false }); + + await _captureAppStart({ isManual: false }); + + const actualEvent = await processEvent(getMinimalTransactionEvent()); + + const appStartSpan = actualEvent!.spans!.find(({ description }) => description === 'Warm App Start'); + + expect(appStartSpan).toBeDefined(); + expect(appStartSpan!.data).toEqual( + expect.objectContaining({ + 'frames.total': 180, + 'frames.slow': 12, + 'frames.frozen': 3, + [SEMANTIC_ATTRIBUTE_SENTRY_OP]: APP_START_WARM_OP, + [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: SPAN_ORIGIN_AUTO_APP_START, + }), + ); + }); + + it('does not attach frame data when native frames are not available', async () => { + mockFunction(NATIVE.fetchNativeFrames).mockRejectedValue(new Error('Native frames not available')); + + mockAppStart({ cold: true }); + + const actualEvent = await captureStandAloneAppStart(); + + const appStartSpan = actualEvent!.spans!.find(({ description }) => description === 'Cold App Start'); + + expect(appStartSpan).toBeDefined(); + expect(appStartSpan!.data).toEqual( + expect.objectContaining({ + [SEMANTIC_ATTRIBUTE_SENTRY_OP]: APP_START_COLD_OP, + [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: SPAN_ORIGIN_AUTO_APP_START, + }), + ); + + expect(appStartSpan!.data).not.toHaveProperty('frames.total'); + expect(appStartSpan!.data).not.toHaveProperty('frames.slow'); + expect(appStartSpan!.data).not.toHaveProperty('frames.frozen'); + }); + + it('does not attach frame data when NATIVE is not enabled', async () => { + const originalEnableNative = NATIVE.enableNative; + (NATIVE as any).enableNative = false; + + try { + mockAppStart({ cold: true }); + + const actualEvent = await captureStandAloneAppStart(); + + const appStartSpan = actualEvent!.spans!.find(({ description }) => description === 'Cold App Start'); + + expect(appStartSpan).toBeDefined(); + expect(appStartSpan!.data).toEqual( + expect.objectContaining({ + [SEMANTIC_ATTRIBUTE_SENTRY_OP]: APP_START_COLD_OP, + [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: SPAN_ORIGIN_AUTO_APP_START, + }), + ); + + expect(appStartSpan!.data).not.toHaveProperty('frames.total'); + expect(appStartSpan!.data).not.toHaveProperty('frames.slow'); + expect(appStartSpan!.data).not.toHaveProperty('frames.frozen'); + } finally { + (NATIVE as any).enableNative = originalEnableNative; + } + }); +}); + function setupIntegration() { const client = new TestClient(getDefaultTestClientOptions()); const integration = appStartIntegration(); @@ -1095,7 +1259,10 @@ function mockAppStart({ : [], }; - _setAppStartEndTimestampMs(appStartEndTimestampMs || timeOriginMilliseconds); + _setAppStartEndData({ + timestampMs: appStartEndTimestampMs || timeOriginMilliseconds, + endFrames: null, + }); mockFunction(getTimeOriginMilliseconds).mockReturnValue(timeOriginMilliseconds); mockFunction(NATIVE.fetchNativeAppStart).mockResolvedValue(mockAppStartResponse); @@ -1112,7 +1279,10 @@ function mockTooLongAppStart() { spans: [], }; - _setAppStartEndTimestampMs(timeOriginMilliseconds); + _setAppStartEndData({ + timestampMs: timeOriginMilliseconds, + endFrames: null, + }); mockFunction(getTimeOriginMilliseconds).mockReturnValue(timeOriginMilliseconds); mockFunction(NATIVE.fetchNativeAppStart).mockResolvedValue(mockAppStartResponse); @@ -1134,7 +1304,10 @@ function mockTooOldAppStart() { // App start finish timestamp // App start length is 5 seconds - _setAppStartEndTimestampMs(appStartEndTimestampMilliseconds); + _setAppStartEndData({ + timestampMs: appStartEndTimestampMilliseconds, + endFrames: null, + }); mockFunction(getTimeOriginMilliseconds).mockReturnValue(timeOriginMilliseconds - 64000); mockFunction(NATIVE.fetchNativeAppStart).mockResolvedValue(mockAppStartResponse); // Transaction start timestamp diff --git a/packages/core/test/tracing/reactnavigation.ttid.test.tsx b/packages/core/test/tracing/reactnavigation.ttid.test.tsx index 68d0f3bb91..7830012e0d 100644 --- a/packages/core/test/tracing/reactnavigation.ttid.test.tsx +++ b/packages/core/test/tracing/reactnavigation.ttid.test.tsx @@ -14,7 +14,7 @@ jest.mock('../../src/js/tracing/timetodisplaynative', () => mockedtimetodisplayn import * as Sentry from '../../src/js'; import { startSpanManual } from '../../src/js'; import { TimeToFullDisplay, TimeToInitialDisplay } from '../../src/js/tracing'; -import { _setAppStartEndTimestampMs } from '../../src/js/tracing/integrations/appStart'; +import { _setAppStartEndData } from '../../src/js/tracing/integrations/appStart'; import { SPAN_ORIGIN_AUTO_NAVIGATION_REACT_NAVIGATION, SPAN_ORIGIN_AUTO_UI_TIME_TO_DISPLAY, SPAN_ORIGIN_MANUAL_UI_TIME_TO_DISPLAY } from '../../src/js/tracing/origin'; import { SPAN_THREAD_NAME, SPAN_THREAD_NAME_JAVASCRIPT } from '../../src/js/tracing/span'; import { isHermesEnabled, notWeb } from '../../src/js/utils/environment'; @@ -47,7 +47,10 @@ describe('React Navigation - TTID', () => { type: 'cold', spans: [], }); - _setAppStartEndTimestampMs(mockedAppStartTimeSeconds * 1000); + _setAppStartEndData({ + timestampMs: mockedAppStartTimeSeconds * 1000, + endFrames: null + }); const sut = createTestedInstrumentation({ enableTimeToInitialDisplay: true }); transportSendMock = initSentry(sut).transportSendMock; From 9429126c97f1f2a92c3f1c67c2bfbe95451ee350 Mon Sep 17 00:00:00 2001 From: Antonis Lilis Date: Tue, 27 May 2025 21:20:58 +0300 Subject: [PATCH 2/7] Adds changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 99e3895e71..83799c2d47 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -20,6 +20,7 @@ - crashedLastRun now returns the correct value ([#4829](https://github.com/getsentry/sentry-react-native/pull/4829)) - Use engine-specific promise rejection tracking ([#4826](https://github.com/getsentry/sentry-react-native/pull/4826)) - Fixes Feedback Widget accessibility issue on iOS ([#4739](https://github.com/getsentry/sentry-react-native/pull/4739)) +- Report slow and frozen frames as app start span data ([#4865](https://github.com/getsentry/sentry-react-native/pull/4865)) ### Dependencies From 6d79f63916d97fc52c8ef882341cddbc049a8fa7 Mon Sep 17 00:00:00 2001 From: Antonis Lilis Date: Wed, 28 May 2025 13:50:28 +0300 Subject: [PATCH 3/7] Do not attach zero slow/frozen frames --- .../src/js/tracing/integrations/appStart.ts | 4 +++ .../tracing/integrations/appStart.test.ts | 30 +++++++++++++++++++ 2 files changed, 34 insertions(+) diff --git a/packages/core/src/js/tracing/integrations/appStart.ts b/packages/core/src/js/tracing/integrations/appStart.ts index 5504552bed..b5576d8b2f 100644 --- a/packages/core/src/js/tracing/integrations/appStart.ts +++ b/packages/core/src/js/tracing/integrations/appStart.ts @@ -146,6 +146,10 @@ export function _clearRootComponentCreationTimestampMs(): void { * Attaches frame data to a span's data object. */ function attachFrameDataToSpan(span: SpanJSON, frames: NativeFramesResponse): void { + if (frames.totalFrames <= 0 && frames.slowFrames <= 0 && frames.totalFrames <= 0) { + logger.warn(`[AppStart] Detected zero slow or frozen frames. Not adding measurements to spanId (${span.span_id}).`); + return; + } span.data = span.data || {}; span.data['frames.total'] = frames.totalFrames; span.data['frames.slow'] = frames.slowFrames; diff --git a/packages/core/test/tracing/integrations/appStart.test.ts b/packages/core/test/tracing/integrations/appStart.test.ts index 1625c8d9e3..d86b293b3f 100644 --- a/packages/core/test/tracing/integrations/appStart.test.ts +++ b/packages/core/test/tracing/integrations/appStart.test.ts @@ -902,6 +902,36 @@ describe('Frame Data Integration', () => { ); }); + it('does not attach frame data when they are zero', async () => { + const mockEndFrames = { + totalFrames: 0, + slowFrames: 0, + frozenFrames: 0, + }; + + mockFunction(NATIVE.fetchNativeFrames).mockResolvedValue(mockEndFrames); + + mockAppStart({ cold: true }); + + await _captureAppStart({ isManual: false }); + + const actualEvent = await processEvent(getMinimalTransactionEvent()); + + const appStartSpan = actualEvent!.spans!.find(({ description }) => description === 'Cold App Start'); + + expect(appStartSpan).toBeDefined(); + expect(appStartSpan!.data).toEqual( + expect.objectContaining({ + [SEMANTIC_ATTRIBUTE_SENTRY_OP]: APP_START_COLD_OP, + [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: SPAN_ORIGIN_AUTO_APP_START, + }), + ); + + expect(appStartSpan!.data).not.toHaveProperty('frames.total'); + expect(appStartSpan!.data).not.toHaveProperty('frames.slow'); + expect(appStartSpan!.data).not.toHaveProperty('frames.frozen'); + }); + it('does not attach frame data when native frames are not available', async () => { mockFunction(NATIVE.fetchNativeFrames).mockRejectedValue(new Error('Native frames not available')); From c680ff0605a132af500f503b9049b93cc3a13d3d Mon Sep 17 00:00:00 2001 From: Antonis Lilis Date: Wed, 28 May 2025 15:35:02 +0300 Subject: [PATCH 4/7] Rename test for clarity Co-authored-by: LucasZF --- packages/core/test/tracing/integrations/appStart.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/core/test/tracing/integrations/appStart.test.ts b/packages/core/test/tracing/integrations/appStart.test.ts index d86b293b3f..042114d240 100644 --- a/packages/core/test/tracing/integrations/appStart.test.ts +++ b/packages/core/test/tracing/integrations/appStart.test.ts @@ -902,7 +902,7 @@ describe('Frame Data Integration', () => { ); }); - it('does not attach frame data when they are zero', async () => { + it('does not attach frame data when they are no frames', async () => { const mockEndFrames = { totalFrames: 0, slowFrames: 0, From 108c3ec958b0d6191ec627b2a9afc7f1de2a5583 Mon Sep 17 00:00:00 2001 From: Antonis Lilis Date: Thu, 29 May 2025 17:19:14 +0300 Subject: [PATCH 5/7] Add frame data to time to display spans --- .../core/src/js/tracing/timetodisplay.tsx | 199 ++++++++++++++++-- 1 file changed, 177 insertions(+), 22 deletions(-) diff --git a/packages/core/src/js/tracing/timetodisplay.tsx b/packages/core/src/js/tracing/timetodisplay.tsx index f33216b875..d42ad45433 100644 --- a/packages/core/src/js/tracing/timetodisplay.tsx +++ b/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(); */ const fullDisplayBeforeInitialDisplay = new WeakMap(); +interface FrameDataForSpan { + startFrames: NativeFramesResponse | null; + endFrames: NativeFramesResponse | null; +} + +const spanFrameDataMap = new Map(); + 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 { + 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 { + 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 { + return new Promise((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); + }); +} From 5c4e6fd59734323f0d5fbca31202f2afaf009c37 Mon Sep 17 00:00:00 2001 From: Antonis Lilis Date: Wed, 4 Jun 2025 13:49:11 +0300 Subject: [PATCH 6/7] Adds tests --- .../core/src/js/tracing/timetodisplay.tsx | 5 +- .../core/test/tracing/timetodisplay.test.tsx | 215 +++++++++++++++++- 2 files changed, 216 insertions(+), 4 deletions(-) diff --git a/packages/core/src/js/tracing/timetodisplay.tsx b/packages/core/src/js/tracing/timetodisplay.tsx index d42ad45433..2bfbca8308 100644 --- a/packages/core/src/js/tracing/timetodisplay.tsx +++ b/packages/core/src/js/tracing/timetodisplay.tsx @@ -294,7 +294,10 @@ export function updateInitialDisplaySpan( }); } -function updateFullDisplaySpan(frameTimestampSeconds: number, passedInitialDisplaySpan?: Span): void { +/** + * @internal Exposed for testing purposes + */ +export function updateFullDisplaySpan(frameTimestampSeconds: number, passedInitialDisplaySpan?: Span): void { const activeSpan = getActiveSpan(); if (!activeSpan) { logger.warn(`[TimeToDisplay] No active span found to update ui.load.full_display in.`); diff --git a/packages/core/test/tracing/timetodisplay.test.tsx b/packages/core/test/tracing/timetodisplay.test.tsx index 43413abcbc..bcaa6c0abe 100644 --- a/packages/core/test/tracing/timetodisplay.test.tsx +++ b/packages/core/test/tracing/timetodisplay.test.tsx @@ -21,13 +21,14 @@ 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, updateFullDisplaySpan, updateInitialDisplaySpan } from '../../src/js/tracing/timetodisplay'; +import { NATIVE } from '../../src/js/wrapper'; import { getDefaultTestClientOptions, TestClient } from '../mocks/client'; -import { nowInSeconds, secondAgoTimestampMs, secondInFutureTimestampMs } from '../testutils'; +import { mockFunction,nowInSeconds, secondAgoTimestampMs, secondInFutureTimestampMs } from '../testutils'; const { mockRecordedTimeToDisplay, getMockedOnDrawReportedProps, clearMockedOnDrawReportedProps } = mockedtimetodisplaynative; -jest.useFakeTimers({advanceTimers: true}); +jest.useFakeTimers({ advanceTimers: true }); describe('TimeToDisplay', () => { let client: TestClient; @@ -308,6 +309,214 @@ describe('TimeToDisplay', () => { expect(logger.warn).toHaveBeenCalledWith( 'TimeToInitialDisplay and TimeToFullDisplay are not supported on the web, Expo Go and New Architecture. Run native build or report an issue at https://github.com/getsentry/sentry-react-native'); }); + + describe('Frame Data Integration', () => { + test('attaches frame data to initial display span', async () => { + const mockStartFrames = { + totalFrames: 50, + slowFrames: 2, + frozenFrames: 1, + }; + const mockEndFrames = { + totalFrames: 186, + slowFrames: 7, + frozenFrames: 3, + }; + + mockFunction(NATIVE.fetchNativeFrames) + .mockResolvedValueOnce(mockStartFrames) + .mockResolvedValueOnce(mockEndFrames); + + let initialDisplaySpan: Span | undefined; + + await startSpanManual( + { + name: 'Root Manual Span', + startTime: secondAgoTimestampMs(), + }, + async (activeSpan: Span | undefined) => { + initialDisplaySpan = startTimeToInitialDisplaySpan(); + TestRenderer.create(); + + await jest.advanceTimersByTimeAsync(100); + + updateInitialDisplaySpan(nowInSeconds(), { + activeSpan, + span: initialDisplaySpan, + }); + + await jest.advanceTimersByTimeAsync(200); + activeSpan?.end(); + }, + ); + + await jest.advanceTimersByTimeAsync(100); + await client.flush(); + + const initialDisplaySpanJSON = getInitialDisplaySpanJSON(client.event!.spans!); + expect(initialDisplaySpanJSON).toBeDefined(); + expect(initialDisplaySpanJSON!.data).toEqual( + expect.objectContaining({ + 'frames.total': 136, // 186 - 50 + 'frames.slow': 5, // 7 - 2 + 'frames.frozen': 2, // 3 - 1 + }), + ); + }); + + test('attaches frame data to full display span', async () => { + const mockStartFrames = { + totalFrames: 50, + slowFrames: 2, + frozenFrames: 1, + }; + const mockEndFrames = { + totalFrames: 200, + slowFrames: 10, + frozenFrames: 4, + }; + + mockFunction(NATIVE.fetchNativeFrames) + .mockResolvedValueOnce(mockStartFrames) // Initial display start + .mockResolvedValueOnce(mockEndFrames) // Initial display end + .mockResolvedValueOnce(mockStartFrames) // Full display start + .mockResolvedValueOnce(mockEndFrames); // Full display end + + let initialDisplaySpan: Span | undefined; + + await startSpanManual( + { + name: 'Root Manual Span', + startTime: secondAgoTimestampMs(), + }, + async (activeSpan: Span | undefined) => { + initialDisplaySpan = startTimeToInitialDisplaySpan(); + TestRenderer.create(); + + await jest.advanceTimersByTimeAsync(100); + + updateInitialDisplaySpan(nowInSeconds(), { + activeSpan, + span: initialDisplaySpan, + }); + + await jest.advanceTimersByTimeAsync(100); + + startTimeToFullDisplaySpan(); + TestRenderer.create(); + + await jest.advanceTimersByTimeAsync(100); + + updateFullDisplaySpan(nowInSeconds() + 0.1, initialDisplaySpan); + + await jest.advanceTimersByTimeAsync(200); + activeSpan?.end(); + }, + ); + + await jest.advanceTimersByTimeAsync(100); + await client.flush(); + + const fullDisplaySpanJSON = getFullDisplaySpanJSON(client.event!.spans!); + expect(fullDisplaySpanJSON).toBeDefined(); + expect(fullDisplaySpanJSON!.data).toEqual( + expect.objectContaining({ + 'frames.total': 150, // 200 - 50 + 'frames.slow': 8, // 10 - 2 + 'frames.frozen': 3, // 4 - 1 + }), + ); + }); + + test('does not attach frame data when frames are zero', async () => { + const mockFrames = { + totalFrames: 10, + slowFrames: 20, + frozenFrames: 30, + }; + + mockFunction(NATIVE.fetchNativeFrames) + .mockResolvedValueOnce(mockFrames) + .mockResolvedValueOnce(mockFrames); // same frames for both initial and full display + + let initialDisplaySpan: Span | undefined; + + await startSpanManual( + { + name: 'Root Manual Span', + startTime: secondAgoTimestampMs(), + }, + async (activeSpan: Span | undefined) => { + initialDisplaySpan = startTimeToInitialDisplaySpan(); + TestRenderer.create(); + + await jest.advanceTimersByTimeAsync(100); + + updateInitialDisplaySpan(nowInSeconds(), { + activeSpan, + span: initialDisplaySpan, + }); + + await jest.advanceTimersByTimeAsync(200); + activeSpan?.end(); + }, + ); + + await jest.advanceTimersByTimeAsync(100); + await client.flush(); + + const initialDisplaySpanJSON = getInitialDisplaySpanJSON(client.event!.spans!); + expect(initialDisplaySpanJSON).toBeDefined(); + expect(initialDisplaySpanJSON!.data).not.toHaveProperty('frames.total'); + expect(initialDisplaySpanJSON!.data).not.toHaveProperty('frames.slow'); + expect(initialDisplaySpanJSON!.data).not.toHaveProperty('frames.frozen'); + }); + + test('handles frame data fetch failure gracefully', async () => { + mockFunction(NATIVE.fetchNativeFrames) + .mockRejectedValueOnce(new Error('Start frames failed')) + .mockRejectedValueOnce(new Error('End frames failed')); + + let initialDisplaySpan: Span | undefined; + + await startSpanManual( + { + name: 'Root Manual Span', + startTime: secondAgoTimestampMs(), + }, + async (activeSpan: Span | undefined) => { + initialDisplaySpan = startTimeToInitialDisplaySpan(); + TestRenderer.create(); + + await jest.advanceTimersByTimeAsync(100); + + updateInitialDisplaySpan(nowInSeconds(), { + activeSpan, + span: initialDisplaySpan, + }); + + await jest.advanceTimersByTimeAsync(200); + activeSpan?.end(); + }, + ); + + await jest.advanceTimersByTimeAsync(100); + await client.flush(); + + const initialDisplaySpanJSON = getInitialDisplaySpanJSON(client.event!.spans!); + + expect(initialDisplaySpanJSON).toBeDefined(); + expect(initialDisplaySpanJSON!.op).toBe('ui.load.initial_display'); + expect(initialDisplaySpanJSON!.status).toBe('ok'); + + expect(initialDisplaySpanJSON!.data).not.toHaveProperty('frames.total'); + expect(initialDisplaySpanJSON!.data).not.toHaveProperty('frames.slow'); + expect(initialDisplaySpanJSON!.data).not.toHaveProperty('frames.frozen'); + + expect(client.event!.measurements).toBeDefined(); + expect(client.event!.measurements!.time_to_initial_display).toBeDefined(); + }); + }); }); function getInitialDisplaySpanJSON(spans: SpanJSON[]) { From d355217bbdba27b48a29074f3a5298b31524316b Mon Sep 17 00:00:00 2001 From: Antonis Lilis Date: Wed, 4 Jun 2025 13:51:27 +0300 Subject: [PATCH 7/7] Adds changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 788b0d672d..b386110b97 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -45,6 +45,7 @@ - Fixes Feedback Widget accessibility issue on iOS ([#4739](https://github.com/getsentry/sentry-react-native/pull/4739)) - Measuring TTID or TTFD could cause a crash when `parentSpanId` was removed ([#4881](https://github.com/getsentry/sentry-react-native/pull/4881)) - Report slow and frozen frames as app start span data ([#4865](https://github.com/getsentry/sentry-react-native/pull/4865)) +- Report slow and frozen frames in TTID and TTFD span data ([#4871](https://github.com/getsentry/sentry-react-native/pull/4871)) ### Dependencies