diff --git a/CHANGELOG.md b/CHANGELOG.md index 732b98d714..e94019c447 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 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 index b69f2078a9..8268824172 100644 --- a/packages/core/android/src/main/java/io/sentry/react/RNSentryModuleImpl.java +++ b/packages/core/android/src/main/java/io/sentry/react/RNSentryModuleImpl.java @@ -491,6 +491,7 @@ public void fetchNativeFrames(Promise promise) { int totalFrames = 0; int slowFrames = 0; int frozenFrames = 0; + int framesDelay = 0; // TODO final SparseIntArray[] framesRates = frameMetricsAggregator.getMetrics(); @@ -518,6 +519,7 @@ public void fetchNativeFrames(Promise promise) { map.putInt("totalFrames", totalFrames); map.putInt("slowFrames", slowFrames); map.putInt("frozenFrames", frozenFrames); + map.putInt("framesDelay", framesDelay); promise.resolve(map); } catch (Throwable ignored) { // NOPMD - We don't want to crash in any case diff --git a/packages/core/ios/RNSentry.mm b/packages/core/ios/RNSentry.mm index 6b3070be11..070f444d6d 100644 --- a/packages/core/ios/RNSentry.mm +++ b/packages/core/ios/RNSentry.mm @@ -517,6 +517,11 @@ - (NSDictionary *)fetchNativeStackFramesBy:(NSArray *)instructionsAd #if TARGET_OS_IPHONE || TARGET_OS_MACCATALYST if (PrivateSentrySDKOnly.isFramesTrackingRunning) { + // TODO + CFTimeInterval framesDelay = [PrivateSentrySDKOnly getFramesDelay:0.0 + endSystemTimestamp:0.0]; + NSNumber *delay = [NSNumber numberWithDouble:framesDelay]; + SentryScreenFrames *frames = PrivateSentrySDKOnly.currentScreenFrames; if (frames == nil) { @@ -532,6 +537,7 @@ - (NSDictionary *)fetchNativeStackFramesBy:(NSArray *)instructionsAd @"totalFrames" : total, @"frozenFrames" : frozen, @"slowFrames" : slow, + @"framesDelay" : delay, }); } else { resolve(nil); diff --git a/packages/core/src/js/NativeRNSentry.ts b/packages/core/src/js/NativeRNSentry.ts index 5b00b62116..026f4c0738 100644 --- a/packages/core/src/js/NativeRNSentry.ts +++ b/packages/core/src/js/NativeRNSentry.ts @@ -112,6 +112,7 @@ export type NativeFramesResponse = { totalFrames: number; slowFrames: number; frozenFrames: number; + framesDelay: number; }; export type NativeReleaseResponse = { diff --git a/packages/core/src/js/tracing/integrations/appStart.ts b/packages/core/src/js/tracing/integrations/appStart.ts index df0713bc57..f992ed8c34 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,30 @@ export function _clearRootComponentCreationTimestampMs(): void { rootComponentCreationTimestampMs = undefined; } +/** + * 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; + span.data['frames.frozen'] = frames.frozenFrames; + span.data['frames.delay'] = frames.framesDelay; + + 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 +265,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 +348,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 +428,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..7e5298648c 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,204 @@ 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, + framesDelay: 0, + }; + + 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, + framesDelay: 0, + }; + + 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, + framesDelay: 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, + framesDelay: 0, + }; + + 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 they are no frames', async () => { + const mockEndFrames = { + totalFrames: 0, + slowFrames: 0, + frozenFrames: 0, + framesDelay: 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')); + + 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 +1294,10 @@ function mockAppStart({ : [], }; - _setAppStartEndTimestampMs(appStartEndTimestampMs || timeOriginMilliseconds); + _setAppStartEndData({ + timestampMs: appStartEndTimestampMs || timeOriginMilliseconds, + endFrames: null, + }); mockFunction(getTimeOriginMilliseconds).mockReturnValue(timeOriginMilliseconds); mockFunction(NATIVE.fetchNativeAppStart).mockResolvedValue(mockAppStartResponse); @@ -1112,7 +1314,10 @@ function mockTooLongAppStart() { spans: [], }; - _setAppStartEndTimestampMs(timeOriginMilliseconds); + _setAppStartEndData({ + timestampMs: timeOriginMilliseconds, + endFrames: null, + }); mockFunction(getTimeOriginMilliseconds).mockReturnValue(timeOriginMilliseconds); mockFunction(NATIVE.fetchNativeAppStart).mockResolvedValue(mockAppStartResponse); @@ -1134,7 +1339,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/integrations/nativeframes.test.ts b/packages/core/test/tracing/integrations/nativeframes.test.ts index 839bdd5d1b..19bcd42e96 100644 --- a/packages/core/test/tracing/integrations/nativeframes.test.ts +++ b/packages/core/test/tracing/integrations/nativeframes.test.ts @@ -59,11 +59,13 @@ describe('NativeFramesInstrumentation', () => { totalFrames: 100, slowFrames: 20, frozenFrames: 5, + framesDelay: 0, }; const finishFrames = { totalFrames: 200, slowFrames: 40, frozenFrames: 10, + framesDelay: 0, }; mockFunction(NATIVE.fetchNativeFrames).mockResolvedValueOnce(startFrames).mockResolvedValueOnce(finishFrames); @@ -99,11 +101,13 @@ describe('NativeFramesInstrumentation', () => { totalFrames: 0, slowFrames: 0, frozenFrames: 0, + framesDelay: 0, }; const finishFrames = { totalFrames: 100, slowFrames: 20, frozenFrames: 5, + framesDelay: 0, }; mockFunction(NATIVE.fetchNativeFrames).mockResolvedValueOnce(startFrames).mockResolvedValueOnce(finishFrames); @@ -139,11 +143,13 @@ describe('NativeFramesInstrumentation', () => { totalFrames: 100, slowFrames: 20, frozenFrames: 5, + framesDelay: 0, }; const finishFrames = { totalFrames: 100, slowFrames: 20, frozenFrames: 5, + framesDelay: 0, }; mockFunction(NATIVE.fetchNativeFrames).mockResolvedValueOnce(startFrames).mockResolvedValueOnce(finishFrames); @@ -174,6 +180,7 @@ describe('NativeFramesInstrumentation', () => { totalFrames: 200, slowFrames: 40, frozenFrames: 10, + framesDelay: 0, }; mockFunction(NATIVE.fetchNativeFrames).mockResolvedValueOnce(startFrames).mockResolvedValueOnce(finishFrames); @@ -203,6 +210,7 @@ describe('NativeFramesInstrumentation', () => { totalFrames: 100, slowFrames: 20, frozenFrames: 5, + framesDelay: 0, }; const finishFrames: null = null; mockFunction(NATIVE.fetchNativeFrames).mockResolvedValueOnce(startFrames).mockResolvedValueOnce(finishFrames); @@ -244,11 +252,13 @@ describe('NativeFramesInstrumentation', () => { totalFrames: 100, slowFrames: 20, frozenFrames: 5, + framesDelay: 0, }; const finishFrames = { totalFrames: 200, slowFrames: 40, frozenFrames: 10, + framesDelay: 0, }; mockFunction(NATIVE.fetchNativeFrames).mockResolvedValueOnce(startFrames).mockResolvedValueOnce(finishFrames); 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;