Skip to content

fix(ttid/ttfd): Add frame data to ttid/ttfd spans #4871

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
wants to merge 4 commits into
base: antonis/appstart-frames
Choose a base branch
from
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
204 changes: 181 additions & 23 deletions packages/core/src/js/tracing/timetodisplay.tsx
Original file line number Diff line number Diff line change
@@ -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.
*/
Expand All @@ -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;
Expand Down Expand Up @@ -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({
Expand All @@ -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 {
Expand Down Expand Up @@ -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);

Expand Down Expand Up @@ -235,20 +267,37 @@ 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 {
/**
* @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.`);
Expand Down Expand Up @@ -278,17 +327,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.`);
}

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);
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);
});
}

/**
Expand Down Expand Up @@ -342,3 +400,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);
});
}
Loading
Loading