diff --git a/CHANGELOG.md b/CHANGELOG.md index 5b688ba123..723e13b4ab 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,10 @@ ## Unreleased +### Fixes + +- Bound TTID/TTFD to prevent inflated transactions ([#6210](https://github.com/getsentry/sentry-react-native/pull/6210)) + ### Features - Expose `pauseAppHangTracking` and `resumeAppHangTracking` APIs on iOS ([#6192](https://github.com/getsentry/sentry-react-native/pull/6192)) diff --git a/packages/core/src/js/tracing/integrations/timeToDisplayIntegration.ts b/packages/core/src/js/tracing/integrations/timeToDisplayIntegration.ts index c0d0f932b5..eaf331ab29 100644 --- a/packages/core/src/js/tracing/integrations/timeToDisplayIntegration.ts +++ b/packages/core/src/js/tracing/integrations/timeToDisplayIntegration.ts @@ -57,30 +57,41 @@ export const timeToDisplayIntegration = (): Integration => { }); const ttfdSpan = await addTimeToFullDisplay({ event, rootSpanId, transactionStartTimestampSeconds, ttidSpan }); - if (ttidSpan?.start_timestamp && ttidSpan?.timestamp) { + const ttidDurationMs = + ttidSpan?.start_timestamp && ttidSpan?.timestamp + ? (ttidSpan.timestamp - ttidSpan.start_timestamp) * 1000 + : undefined; + const ttidDeadlineExceeded = ttidDurationMs !== undefined && isDeadlineExceeded(ttidDurationMs); + + if (ttidDurationMs !== undefined && !ttidDeadlineExceeded) { event.measurements['time_to_initial_display'] = { - value: (ttidSpan.timestamp - ttidSpan.start_timestamp) * 1000, + value: ttidDurationMs, unit: 'millisecond', }; } - if (ttfdSpan?.start_timestamp && ttfdSpan?.timestamp) { - const durationMs = (ttfdSpan.timestamp - ttfdSpan.start_timestamp) * 1000; - if (isDeadlineExceeded(durationMs)) { + const ttfdDurationMs = + ttfdSpan?.start_timestamp && ttfdSpan?.timestamp + ? (ttfdSpan.timestamp - ttfdSpan.start_timestamp) * 1000 + : undefined; + const ttfdDeadlineExceeded = ttfdDurationMs !== undefined && isDeadlineExceeded(ttfdDurationMs); + + if (ttfdDurationMs !== undefined) { + if (ttfdDeadlineExceeded) { if (event.measurements['time_to_initial_display']) { event.measurements['time_to_full_display'] = event.measurements['time_to_initial_display']; } } else { event.measurements['time_to_full_display'] = { - value: durationMs, + value: ttfdDurationMs, unit: 'millisecond', }; } } const newTransactionEndTimestampSeconds = Math.max( - ttidSpan?.timestamp ?? -1, - ttfdSpan?.timestamp ?? -1, + !ttidDeadlineExceeded && ttidSpan?.timestamp ? ttidSpan.timestamp : -1, + !ttfdDeadlineExceeded && ttfdSpan?.timestamp ? ttfdSpan.timestamp : -1, event.timestamp ?? -1, ); if (newTransactionEndTimestampSeconds !== -1) { @@ -126,14 +137,18 @@ async function addTimeToInitialDisplay({ }); } + const manualDurationMs = (ttidEndTimestampSeconds - transactionStartTimestampSeconds) * 1000; + const manualStatus = isDeadlineExceeded(manualDurationMs) ? 'deadline_exceeded' : 'ok'; + if (ttidSpan?.status && ttidSpan.status !== 'ok') { - ttidSpan.status = 'ok'; + ttidSpan.status = manualStatus; ttidSpan.timestamp = ttidEndTimestampSeconds; debug.log(`[${INTEGRATION_NAME}] Updated existing ttid span.`, ttidSpan); return ttidSpan; } ttidSpan = createSpanJSON({ + status: manualStatus, op: UI_LOAD_INITIAL_DISPLAY, description: 'Time To Initial Display', start_timestamp: transactionStartTimestampSeconds, @@ -180,7 +195,9 @@ async function addAutomaticTimeToInitialDisplay({ const viewNames = event.contexts?.app?.view_names; const screenName = Array.isArray(viewNames) ? viewNames[0] : viewNames; + const durationMs = (ttidTimestampSeconds - transactionStartTimestampSeconds) * 1000; const ttidSpan = createSpanJSON({ + status: isDeadlineExceeded(durationMs) ? 'deadline_exceeded' : 'ok', op: UI_LOAD_INITIAL_DISPLAY, description: screenName ? `${screenName} initial display` : 'Time To Initial Display', start_timestamp: transactionStartTimestampSeconds, @@ -225,15 +242,17 @@ async function addTimeToFullDisplay({ const durationMs = (ttfdAdjustedEndTimestampSeconds - transactionStartTimestampSeconds) * 1000; + const ttfdStatus = isDeadlineExceeded(durationMs) ? 'deadline_exceeded' : 'ok'; + if (ttfdSpan?.status && ttfdSpan.status !== 'ok') { - ttfdSpan.status = 'ok'; + ttfdSpan.status = ttfdStatus; ttfdSpan.timestamp = ttfdAdjustedEndTimestampSeconds; debug.log(`[${INTEGRATION_NAME}] Updated existing ttfd span.`, ttfdSpan); return ttfdSpan; } ttfdSpan = createSpanJSON({ - status: isDeadlineExceeded(durationMs) ? 'deadline_exceeded' : 'ok', + status: ttfdStatus, op: UI_LOAD_FULL_DISPLAY, description: 'Time To Full Display', start_timestamp: transactionStartTimestampSeconds, diff --git a/packages/core/test/tracing/reactnavigation.ttid.test.tsx b/packages/core/test/tracing/reactnavigation.ttid.test.tsx index 14f4c6e812..6d64ba6ce8 100644 --- a/packages/core/test/tracing/reactnavigation.ttid.test.tsx +++ b/packages/core/test/tracing/reactnavigation.ttid.test.tsx @@ -433,6 +433,43 @@ describe('React Navigation - TTID', () => { ); }); + test('should mark ttid as deadline_exceeded and not extend transaction when ttid exceeds 30s', () => { + jest.runOnlyPendingTimers(); // Flush app start transaction + + mockedNavigation.navigateToNewScreen(); + const activeSpanId = spanToJSON(getActiveSpan()).span_id; + const transactionStartTimestamp = spanToJSON(getActiveSpan()).start_timestamp; + + // Simulate a stale TTID 60 seconds after the transaction start + mockRecordedTimeToDisplay({ + ttidNavigation: { + [activeSpanId]: transactionStartTimestamp + 60, + }, + }); + jest.runOnlyPendingTimers(); // Flush ttid transaction + + const transaction = getLastTransaction(transportSendMock); + expect(transaction).toEqual( + expect.objectContaining({ + type: 'transaction', + spans: expect.arrayContaining([ + expect.objectContaining>({ + op: 'ui.load.initial_display', + status: 'deadline_exceeded', + }), + ]), + }), + ); + expect(transaction.measurements).toBeOneOf([ + undefined, + expect.not.objectContaining['measurements']>({ + time_to_initial_display: expect.any(Object), + }), + ]); + // Transaction timestamp should NOT be extended to the stale TTID + expect(transaction.timestamp - transaction.start_timestamp).toBeLessThan(30); + }); + test('should not sample empty back navigation transactions with navigation processing', () => { jest.runOnlyPendingTimers(); // Flush app start transaction diff --git a/packages/core/test/tracing/timetodisplay.test.tsx b/packages/core/test/tracing/timetodisplay.test.tsx index 9a07e94ef1..d02a99d0c6 100644 --- a/packages/core/test/tracing/timetodisplay.test.tsx +++ b/packages/core/test/tracing/timetodisplay.test.tsx @@ -292,6 +292,77 @@ describe('TimeToDisplay', () => { ); }); + test('deadline exceeded full display does not extend transaction timestamp', async () => { + let transactionStartTimestamp: number; + + startSpanManual( + { + name: 'Root Manual Span', + startTime: secondAgoTimestampMs(), + }, + (activeSpan: Span | undefined) => { + transactionStartTimestamp = spanToJSON(activeSpan).start_timestamp; + startTimeToInitialDisplaySpan(); + startTimeToFullDisplaySpan(); + + render(); + render(); + + mockRecordedTimeToDisplay({ + ttid: { + [spanToJSON(activeSpan).span_id]: nowInSeconds(), + }, + ttfd: { + [spanToJSON(activeSpan).span_id]: nowInSeconds() + 60, + }, + }); + + activeSpan?.end(); + }, + ); + + await jest.runOnlyPendingTimersAsync(); + await client.flush(); + + const event = client.event!; + expect(event.timestamp! - transactionStartTimestamp!).toBeLessThan(30); + }); + + test('deadline exceeded manual initial display does not extend transaction timestamp', async () => { + let transactionStartTimestamp: number; + + startSpanManual( + { + name: 'Root Manual Span', + startTime: secondAgoTimestampMs(), + }, + (activeSpan: Span | undefined) => { + transactionStartTimestamp = spanToJSON(activeSpan).start_timestamp; + startTimeToInitialDisplaySpan(); + + render(); + + mockRecordedTimeToDisplay({ + ttid: { + [spanToJSON(activeSpan).span_id]: nowInSeconds() + 60, + }, + }); + + activeSpan?.end(); + }, + ); + + await jest.runOnlyPendingTimersAsync(); + await client.flush(); + + const event = client.event!; + expectNoInitialDisplayMeasurementOnSpan(event); + expect(event.timestamp! - transactionStartTimestamp!).toBeLessThan(30); + + const ttidSpan = event.spans!.find(s => s.op === 'ui.load.initial_display'); + expect(ttidSpan?.status).toBe('deadline_exceeded'); + }); + test('full display which ended before initial display is extended to initial display end', async () => { const fullDisplayEndTimestampMs = secondInFutureTimestampMs(); const initialDisplayEndTimestampMs = secondInFutureTimestampMs() + 500;