diff --git a/CHANGELOG.md b/CHANGELOG.md index 7d0f01b16a..067c20a310 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,12 @@ ## Unreleased +### Features + +- Attach a per-`(module, method)` TurboModule breakdown to active spans on `spanEnd`, plus `native.turbo_module` breadcrumbs for slow async calls ([#6478](https://github.com/getsentry/sentry-react-native/pull/6478)) + + When a root span ends (idle nav spans from `reactNavigationIntegration` / `expoRouterIntegration`, or a user's own `Sentry.startSpan(...)`), the integration writes `turbo_module...{call_count,duration_ms,error_count}` attributes plus summary keys (`turbo_module.total_call_count`, `turbo_module.total_duration_ms`, `turbo_module.top_module`). Async calls above `slowCallThresholdMs` (default 500ms) additionally record a `native.turbo_module` breadcrumb. Both surfaces enabled by default; new knobs `enableSpanAttribution`, `slowCallThresholdMs`, `maxTopModulesPerSpan` on `turboModuleContextIntegration`. + ### Fixes - Make `copySentryJsonConfiguration` and the `*_SentryUpload` Gradle tasks compatible with the Gradle Configuration Cache ([#6469](https://github.com/getsentry/sentry-react-native/pull/6469)) diff --git a/packages/core/etc/sentry-react-native.api.md b/packages/core/etc/sentry-react-native.api.md index 2c83a46489..222454a26c 100644 --- a/packages/core/etc/sentry-react-native.api.md +++ b/packages/core/etc/sentry-react-native.api.md @@ -872,12 +872,15 @@ export const turboModuleContextIntegration: (options?: TurboModuleContextOptions export interface TurboModuleContextOptions { aggregateFlushIntervalMs?: number; enableAggregateStats?: boolean; + enableSpanAttribution?: boolean; ignoreTurboModules?: ReadonlyArray; + maxTopModulesPerSpan?: number; modules?: Array<{ name: string; module: object | null | undefined; skipMethods?: ReadonlyArray; }>; + slowCallThresholdMs?: number; } // @public (undocumented) diff --git a/packages/core/src/js/integrations/turboModuleContext.ts b/packages/core/src/js/integrations/turboModuleContext.ts index 56f0eb21a3..7aa4773d95 100644 --- a/packages/core/src/js/integrations/turboModuleContext.ts +++ b/packages/core/src/js/integrations/turboModuleContext.ts @@ -1,104 +1,81 @@ -import type { Client, Event, Integration, TransactionEvent } from '@sentry/core'; +/* oxlint-disable eslint(max-lines) */ +import type { Client, Event, Integration, Span, TransactionEvent } from '@sentry/core'; -import { debug } from '@sentry/core'; +import { addBreadcrumb, debug, spanToJSON } from '@sentry/core'; -import { createSpanJSON } from '../tracing/utils'; import { - drainTurboModuleAggregate, - HISTOGRAM_BUCKET_LABELS, + addTurboModuleCallStartObserver, + addTurboModuleRecordObserver, hasTurboModuleAggregateData, + removeTurboModuleCallStartObserver, + removeTurboModuleRecordObserver, setAggregateRecordingEnabled, setIgnoredTurboModules, setOnFirstTurboModuleRecord, - type TurboModuleAggregate, + type TurboModuleCallStart, + type TurboModuleRecord, wrapTurboModule, } from '../turbomodule'; +import { isRootSpan } from '../utils/span'; import { getRNSentryModule } from '../wrapper'; +import { + attachAggregateToTransactionEvent, + flushPeriodicAggregate, + roundMs, + TURBO_MODULES_AGGREGATE_OP, + TURBO_MODULES_AGGREGATE_ORIGIN, +} from './turboModuleContextFlush'; -export const INTEGRATION_NAME = 'TurboModuleContext'; - -/** Op for the synthetic child span that carries the aggregate breakdown. */ -export const TURBO_MODULES_AGGREGATE_OP = 'turbo_modules.aggregate'; +export { TURBO_MODULES_AGGREGATE_OP, TURBO_MODULES_AGGREGATE_ORIGIN }; -/** Origin string set on the aggregate span so it shows up as auto-instrumented. */ -export const TURBO_MODULES_AGGREGATE_ORIGIN = 'auto.tracing.turbo_modules'; +export const INTEGRATION_NAME = 'TurboModuleContext'; /** Default flush cadence for the periodic timer, in milliseconds. */ export const DEFAULT_AGGREGATE_FLUSH_INTERVAL_MS = 30_000; -/** - * Maximum number of `(module, method, kind)` triplets serialised as span - * attributes on a single flush. Beyond this, the long tail is dropped from - * the attribute payload — the headline measurements still reflect the totals. - */ -const MAX_AGGREGATE_ATTRIBUTE_ROWS = 64; +/** Default duration above which an async TurboModule call becomes a breadcrumb. */ +export const DEFAULT_SLOW_CALL_THRESHOLD_MS = 500; + +export const DEFAULT_MAX_TOP_MODULES_PER_SPAN = 16; + +export const TURBO_MODULE_BREADCRUMB_CATEGORY = 'native.turbo_module'; + +/** Cap so abandoned (never-settling) promises can't pin `WindowState` forever. */ +export const MAX_PENDING_CALL_WINDOWS = 1024; + +/** Cap so sampled-out transactions can't leak their buffered attributes. */ +export const MAX_PENDING_SPAN_ATTRIBUTES = 256; export interface TurboModuleContextOptions { - /** - * Additional TurboModules to track. Each entry's methods will be wrapped so - * that any native crash happening inside a method call gets `contexts.turbo_module` - * + `turbo_module.name` / `turbo_module.method` attached to the crash report, - * and so the calls are recorded into the aggregator (subject to - * `ignoreTurboModules`). - * - * The built-in `RNSentry` TurboModule is always tracked. - */ + /** Additional TurboModules to wrap. `RNSentry` is always tracked. */ modules?: Array<{ name: string; module: object | null | undefined; skipMethods?: ReadonlyArray }>; - /** - * Per-(module, method, kind) call-count / latency aggregation. When enabled, - * each wrapped TurboModule invocation contributes to a small fixed set of - * counters that flush: - * - on every transaction finish, as a synthetic `turbo_modules.aggregate` - * child span (per-call data in span attributes) plus headline - * measurements on the root span; - * - on a periodic timer (see `aggregateFlushIntervalMs`) so - * long-running sessions without transactions still emit a signal. - * - * Default: `true`. - * - * See https://github.com/getsentry/sentry-react-native/issues/6164. - */ + /** Per-(module, method, kind) counters, flushed on transaction finish and on a periodic timer. Default: `true`. */ enableAggregateStats?: boolean; - /** - * Interval in milliseconds for the periodic aggregate flush. Only used when - * `enableAggregateStats` is enabled. The periodic flush emits a custom - * Sentry event so the data survives sessions that never produce a transaction. - * - * Default: 30000 (30s). Set to `0` to disable the periodic timer (data is - * still flushed on transaction finish). - */ + /** Periodic aggregate flush interval, ms. `0` disables the periodic timer. Default: `30000`. */ aggregateFlushIntervalMs?: number; /** - * TurboModules whose calls should NOT be counted in the aggregate. - * - * Default: `['RNSentry']`. The SDK's own transport call - * (`RNSentry.captureEnvelope`) fires from every `captureEvent`, so leaving - * `RNSentry` in the aggregate would (a) pollute app-level TurboModule - * signals with SDK internal noise and (b) allow the periodic flush's own - * `captureEvent` to record back into the aggregator and perpetually re-arm - * the flush timer in idle sessions. Pass `[]` to opt back in. - * - * Note: this does NOT disable wrapping — crashes during those calls still - * get attributed via `contexts.turbo_module`. It only opts the module out - * of the per-(module, method, kind) counters. + * Modules opted out of the aggregate (still wrapped for crash context). + * Default `['RNSentry']` — the SDK's own transport calls would otherwise + * pollute the signal and self-re-arm the periodic timer indefinitely. */ ignoreTurboModules?: ReadonlyArray; + + /** Per-`(module, method)` breakdown on root-span `spanEnd`. Default: `true`. */ + enableSpanAttribution?: boolean; + + /** Async-call duration above which a `native.turbo_module` breadcrumb fires. `0` disables. Default: `500`. */ + slowCallThresholdMs?: number; + + /** Cap on per-`(module, method)` rows attributed to a single span. Default: `16`. */ + maxTopModulesPerSpan?: number; } -// Methods on RNSentry that must NOT be tracked: -// -// - `addListener` / `removeListeners` are RN event-emitter stubs that fire on -// every subscriber registration — tracking them would just churn the scope. -// -// - The scope-sync methods (`setContext`, `setTag`, `setExtra`, `setUser`, -// `addBreadcrumb`, `clearBreadcrumbs`, `setAttribute`, `setAttributes`, -// `removeAttribute`) are called by our own `enableSyncToNative` hook every -// time anything writes to a JS Scope. Tracking them would cause infinite -// recursion: `pushTurboModuleCall` -> `scope.setContext` -> `NATIVE.setContext` -// -> `RNSentry.setContext` (wrapped) -> `pushTurboModuleCall` -> ... . +// Scope-sync methods must NOT be tracked — `enableSyncToNative` calls them on +// every Scope write, so wrapping them would recurse infinitely via +// `pushTurboModuleCall` -> `scope.setContext` -> `RNSentry.setContext`. const RNSENTRY_SKIP = [ 'addListener', 'removeListeners', @@ -114,33 +91,35 @@ const RNSENTRY_SKIP = [ ] as const; /** - * Attaches the currently-executing TurboModule method to the Sentry scope so - * that native crashes can be attributed to the high-level RN module + method - * (e.g. `RNSentry.captureEnvelope`) on top of the native stack trace. - * - * Additionally aggregates per-(module, method, kind) call-count / latency - * counters and flushes them on transaction finish (as a synthetic - * `turbo_modules.aggregate` child span with headline measurements on the root - * span) and on a periodic timer (as a custom Sentry event) — see - * https://github.com/getsentry/sentry-react-native/issues/6164. - * - * See https://github.com/getsentry/sentry-react-native/issues/6163 for the - * crash-attribution side of this integration. + * Attributes TurboModule invocations to the Sentry scope for crash context, + * aggregates per-`(module, method, kind)` counters into transaction events, + * attaches a per-span breakdown on `spanEnd`, and emits slow-call breadcrumbs. */ export const turboModuleContextIntegration = (options: TurboModuleContextOptions = {}): Integration => { const enableAggregate = options.enableAggregateStats !== false; + const enableSpanAttribution = options.enableSpanAttribution !== false; const flushIntervalMs = options.aggregateFlushIntervalMs ?? DEFAULT_AGGREGATE_FLUSH_INTERVAL_MS; + const slowCallThresholdMs = options.slowCallThresholdMs ?? DEFAULT_SLOW_CALL_THRESHOLD_MS; + const maxTopModulesPerSpan = options.maxTopModulesPerSpan ?? DEFAULT_MAX_TOP_MODULES_PER_SPAN; let pendingFlushHandle: ReturnType | undefined; let closed = false; + // WeakMap: O(1) lookup in spanEnd. Array: hot-path iteration in recordObserver. + const openWindows: WeakMap = new WeakMap(); + const openWindowList: WindowState[] = []; + // Keyed by `recordId` so a call that settles after its originating span + // ended still credits that span. + const pendingCallWindows: Map = new Map(); + // Buffer for `processEvent` merging: `Span#setAttributes` on a frozen span + // is a no-op, so late records after `spanEnd` can only land via the event. + const pendingSpanAttributes: Map> = new Map(); + let recordObserver: ((record: TurboModuleRecord) => void) | undefined; + let startObserver: ((start: TurboModuleCallStart) => void) | undefined; + return { name: INTEGRATION_NAME, setupOnce() { - // Wrap the live RNSentry TurboModule. Other integrations import the same - // instance by reference, so wrapping here transparently tracks every call - // made from JS — including the SDK's own internal envelope/scope sync - // calls, which are the most likely entry points for native crashes. wrapTurboModule('RNSentry', getRNSentryModule(), { skip: RNSENTRY_SKIP }); for (const entry of options.modules ?? []) { @@ -148,27 +127,13 @@ export const turboModuleContextIntegration = (options: TurboModuleContextOptions } setAggregateRecordingEnabled(enableAggregate); - if (enableAggregate) { + if (enableAggregate || enableSpanAttribution || slowCallThresholdMs > 0) { setIgnoredTurboModules(options.ignoreTurboModules ?? ['RNSentry']); } }, setup(client: Client): void { - if (!enableAggregate) { - return; - } - - // Flush on transaction finish is handled in `processEvent` below — by - // the time `processEvent` runs the root span has already been built up - // and we get a chance to mutate the serialised transaction directly, - // avoiding a race with the root span's `end()`. - - // Periodic flush keeps the signal alive in sessions that never produce - // a transaction (e.g. background JS work, long idle sessions with no - // navigation). We arm a one-shot timer lazily — only when the - // aggregator transitions from empty to non-empty — so idle sessions - // don't churn a recurring timer. The next record after a flush - // re-arms it. - if (flushIntervalMs > 0) { + if (enableAggregate && flushIntervalMs > 0) { + // Lazy re-arm keeps idle sessions from churning a recurring timer. setOnFirstTurboModuleRecord(() => { if (closed || pendingFlushHandle !== undefined) { return; @@ -180,6 +145,94 @@ export const turboModuleContextIntegration = (options: TurboModuleContextOptions }); } + // Snapshot on every start (any kind): `wrapTurboModule` always calls + // `notifyTurboModuleCallStart` with `'sync'` and only relabels to + // `'async'` after the return value proves thenable, so gating by kind + // here would silently drop all async attribution. + if (enableSpanAttribution) { + startObserver = (start: TurboModuleCallStart): void => { + if (pendingCallWindows.size >= MAX_PENDING_CALL_WINDOWS) { + const oldest = pendingCallWindows.keys().next().value; + if (oldest !== undefined) { + pendingCallWindows.delete(oldest); + } + } + pendingCallWindows.set(start.recordId, openWindowList.slice()); + }; + addTurboModuleCallStartObserver(startObserver); + } + + const wantsBreadcrumbs = slowCallThresholdMs > 0; + if (enableSpanAttribution || wantsBreadcrumbs) { + recordObserver = (record: TurboModuleRecord): void => { + if (enableSpanAttribution) { + if (record.recordId !== undefined) { + const windows = pendingCallWindows.get(record.recordId); + pendingCallWindows.delete(record.recordId); + // Empty `windows` means no spans were open at call start — + // don't fall back to `openWindowList` or we'd credit a later span. + if (windows) { + for (const window of windows) { + recordIntoWindow(window, record); + if (window.closed) { + attachWindowToSpan(window.span, window, maxTopModulesPerSpan, pendingSpanAttributes); + } + } + } + } else { + for (const window of openWindowList) { + recordIntoWindow(window, record); + } + } + } + + if (wantsBreadcrumbs && record.kind === 'async' && record.durationMs >= slowCallThresholdMs) { + addBreadcrumb({ + category: TURBO_MODULE_BREADCRUMB_CATEGORY, + level: 'info', + type: 'default', + message: `${record.name}.${record.method} took ${roundMs(record.durationMs)}ms`, + data: { + module: record.name, + method: record.method, + kind: record.kind, + duration_ms: roundMs(record.durationMs), + errored: record.errored, + }, + }); + } + }; + addTurboModuleRecordObserver(recordObserver); + } + + if (enableSpanAttribution) { + client.on?.('spanStart', (span: Span) => { + if (!isRootSpan(span)) { + return; + } + if (openWindows.has(span)) { + return; + } + const window: WindowState = { span, closed: false, counters: new Map() }; + openWindows.set(span, window); + openWindowList.push(window); + }); + + client.on?.('spanEnd', (span: Span) => { + const window = openWindows.get(span); + if (!window) { + return; + } + openWindows.delete(span); + const idx = openWindowList.indexOf(window); + if (idx >= 0) { + openWindowList.splice(idx, 1); + } + window.closed = true; + attachWindowToSpan(span, window, maxTopModulesPerSpan, pendingSpanAttributes); + }); + } + client.on?.('close', () => { closed = true; setOnFirstTurboModuleRecord(undefined); @@ -187,198 +240,192 @@ export const turboModuleContextIntegration = (options: TurboModuleContextOptions clearTimeout(pendingFlushHandle); pendingFlushHandle = undefined; } + if (recordObserver) { + removeTurboModuleRecordObserver(recordObserver); + recordObserver = undefined; + } + if (startObserver) { + removeTurboModuleCallStartObserver(startObserver); + startObserver = undefined; + } + openWindowList.length = 0; + pendingCallWindows.clear(); + pendingSpanAttributes.clear(); }); }, processEvent(event: Event): Event { - if (!enableAggregate || event.type !== 'transaction') { + if (event.type !== 'transaction') { return event; } - if (!hasTurboModuleAggregateData()) { - return event; + const txEvent = event as TransactionEvent; + + if (enableAggregate && hasTurboModuleAggregateData()) { + attachAggregateToTransactionEvent(txEvent); } - attachAggregateToTransactionEvent(event as TransactionEvent); + + // Guaranteed-delivery path for span attributes: `setAttributes` on the + // frozen span is a no-op, so late-settling records can only land here. + if (enableSpanAttribution) { + const rootSpanId = txEvent.contexts?.trace?.span_id; + if (rootSpanId) { + const pending = pendingSpanAttributes.get(rootSpanId); + if (pending) { + pendingSpanAttributes.delete(rootSpanId); + mergeAttributesIntoTraceData(txEvent, pending); + } + } + } + return event; }, }; }; -/** - * Mutates a transaction event in place to add the aggregate breakdown as a - * synthetic child span plus a few headline measurements on the root span. - * - * Draining here runs before `beforeSendTransaction`, so if a user hook drops - * this transaction, the drained batch is lost. Trade-off is intentional: - * peeking without draining would require send-confirmation bookkeeping across - * events and multiple transactions in flight would double-count. Data loss - * from a dropped transaction is bounded (one interval) and self-heals — the - * next transaction or periodic flush picks up fresh activity. - */ -function attachAggregateToTransactionEvent(event: TransactionEvent): void { - const trace = event.contexts?.trace; - if (!trace?.trace_id || !trace.span_id) { - return; +interface WindowRow { + name: string; + method: string; + callCount: number; + errorCount: number; + totalDurationMs: number; +} + +interface WindowState { + span: Span; + /** `true` after `spanEnd` — late records still credit and re-emit. */ + closed: boolean; + counters: Map>; + /** Previously-written top-N keys, used to clear stale ones on re-emit. */ + writtenPerMethodKeys?: Set; +} + +function recordIntoWindow(window: WindowState, record: TurboModuleRecord): void { + let byMethod = window.counters.get(record.name); + if (!byMethod) { + byMethod = new Map(); + window.counters.set(record.name, byMethod); } - const startTs = event.start_timestamp; - const endTs = event.timestamp; - if (typeof startTs !== 'number' || typeof endTs !== 'number') { - return; + let row = byMethod.get(record.method); + if (!row) { + row = { + name: record.name, + method: record.method, + callCount: 0, + errorCount: 0, + totalDurationMs: 0, + }; + byMethod.set(record.method, row); + } + row.callCount += 1; + row.totalDurationMs += record.durationMs; + if (record.errored) { + row.errorCount += 1; } +} - const snapshot = drainTurboModuleAggregate(); - if (snapshot.length === 0) { +function attachWindowToSpan( + span: Span, + window: WindowState, + topN: number, + pendingSpanAttributes: Map>, +): void { + if (window.counters.size === 0) { return; } - const totals = summarise(snapshot); - const topByTotalMs = [...snapshot].sort((a, b) => b.totalDurationMs - a.totalDurationMs); - - const aggregateSpan = createSpanJSON({ - op: TURBO_MODULES_AGGREGATE_OP, - description: 'TurboModule call aggregate', - start_timestamp: startTs, - timestamp: endTs, - trace_id: trace.trace_id, - parent_span_id: trace.span_id, - origin: TURBO_MODULES_AGGREGATE_ORIGIN, - data: { - 'turbo_modules.total_call_count': totals.callCount, - 'turbo_modules.total_error_count': totals.errorCount, - 'turbo_modules.total_duration_ms': roundMs(totals.totalDurationMs), - 'turbo_modules.unique_methods': snapshot.length, - ...serialiseRows(topByTotalMs.slice(0, MAX_AGGREGATE_ATTRIBUTE_ROWS)), - }, - }); - - event.spans = event.spans ?? []; - event.spans.push(aggregateSpan); - - event.measurements = event.measurements ?? {}; - event.measurements['turbo_modules.call_count'] = { value: totals.callCount, unit: 'none' }; - event.measurements['turbo_modules.error_count'] = { value: totals.errorCount, unit: 'none' }; - event.measurements['turbo_modules.total_ms'] = { value: roundMs(totals.totalDurationMs), unit: 'millisecond' }; + const rows: WindowRow[] = []; + let totalCallCount = 0; + let totalErrorCount = 0; + let totalDurationMs = 0; + for (const byMethod of window.counters.values()) { + for (const row of byMethod.values()) { + rows.push(row); + totalCallCount += row.callCount; + totalErrorCount += row.errorCount; + totalDurationMs += row.totalDurationMs; + } + } + rows.sort((a, b) => b.totalDurationMs - a.totalDurationMs); - const top = topByTotalMs[0]; + const attributes: Record = { + 'turbo_module.total_call_count': totalCallCount, + 'turbo_module.total_error_count': totalErrorCount, + 'turbo_module.total_duration_ms': roundMs(totalDurationMs), + 'turbo_module.unique_methods': rows.length, + }; + const top = rows[0]; if (top) { - event.measurements['turbo_modules.top_module_ms'] = { - value: roundMs(top.totalDurationMs), - unit: 'millisecond', - }; + attributes['turbo_module.top_module'] = `${top.name}.${top.method}`; + attributes['turbo_module.top_module_duration_ms'] = roundMs(top.totalDurationMs); + } + const capped = rows.slice(0, topN); + const nextKeys = new Set(); + for (const row of capped) { + const prefix = `turbo_module.${safeKeyPart(row.name)}.${safeKeyPart(row.method)}`; + const callCountKey = `${prefix}.call_count`; + const durationKey = `${prefix}.duration_ms`; + const errorCountKey = `${prefix}.error_count`; + attributes[callCountKey] = row.callCount; + attributes[durationKey] = roundMs(row.totalDurationMs); + attributes[errorCountKey] = row.errorCount; + nextKeys.add(callCountKey); + nextKeys.add(durationKey); + nextKeys.add(errorCountKey); + } + // `setAttributes` merges, so keys dropped from top-N must be explicitly + // cleared with `undefined` or they linger from a previous emit. + if (window.writtenPerMethodKeys) { + for (const key of window.writtenPerMethodKeys) { + if (!nextKeys.has(key)) { + attributes[key] = undefined; + } + } } + window.writtenPerMethodKeys = nextKeys; - if (snapshot.length > MAX_AGGREGATE_ATTRIBUTE_ROWS) { + if (rows.length > topN) { + const spanId = spanToJSON(span).span_id; debug.log( - `[TurboModuleContext] Aggregate has ${snapshot.length} rows, truncated to top ${MAX_AGGREGATE_ATTRIBUTE_ROWS} ` + - `by total_ms on the aggregate span. Headline measurements still reflect the full totals.`, + `[TurboModuleContext] Span ${spanId ?? '(unknown)'} touched ${rows.length} unique TurboModule methods, ` + + `truncated to top ${topN} by duration. Summary attributes still reflect the full totals.`, ); } -} - -/** - * Emits the current aggregate as a custom Sentry event so long-running - * sessions without a transaction still produce a signal. No-op when there's - * nothing to flush. - * - * `client.captureEvent` reaches wrapped `RNSentry.captureEnvelope` via the - * native transport — so if `RNSentry` were aggregated, the flush's own send - * would re-arm the lazy timer indefinitely. `ignoreTurboModules` defaults - * to `['RNSentry']` for exactly this reason. - */ -function flushPeriodicAggregate(client: Client): void { - if (!hasTurboModuleAggregateData()) { - return; - } - const snapshot = drainTurboModuleAggregate(); - const totals = summarise(snapshot); - const topByTotalMs = [...snapshot].sort((a, b) => b.totalDurationMs - a.totalDurationMs); - - client.captureEvent?.({ - message: 'TurboModule aggregate (periodic)', - level: 'info', - tags: { - 'event.kind': 'turbo_modules.aggregate', - }, - extra: { - total_call_count: totals.callCount, - total_error_count: totals.errorCount, - total_duration_ms: roundMs(totals.totalDurationMs), - unique_methods: snapshot.length, - modules: topByTotalMs.slice(0, MAX_AGGREGATE_ATTRIBUTE_ROWS).map(serialiseRowAsObject), - }, - }); -} -function summarise(snapshot: ReadonlyArray): { - callCount: number; - errorCount: number; - totalDurationMs: number; -} { - let callCount = 0; - let errorCount = 0; - let totalDurationMs = 0; - for (const row of snapshot) { - callCount += row.callCount; - errorCount += row.errorCount; - totalDurationMs += row.totalDurationMs; - } - return { callCount, errorCount, totalDurationMs }; -} + span.setAttributes(attributes); -/** - * Serialises an aggregate row into a flat set of span-attribute keys, prefixed - * with the `(name.method.kind)` triplet. Span attributes are flat key→scalar - * pairs so nested objects aren't an option here. - */ -function serialiseRows(rows: ReadonlyArray): Record { - const out: Record = {}; - for (const row of rows) { - const prefix = `turbo_modules.${row.name}.${row.method}.${row.kind}`; - out[`${prefix}.count`] = row.callCount; - out[`${prefix}.error_count`] = row.errorCount; - out[`${prefix}.total_ms`] = roundMs(row.totalDurationMs); - out[`${prefix}.max_ms`] = roundMs(row.maxDurationMs); - for (let i = 0; i < row.buckets.length; i++) { - const label = HISTOGRAM_BUCKET_LABELS[i]; - const count = row.buckets[i]; - if (label !== undefined && count !== undefined) { - out[`${prefix}.${label}`] = count; + const spanId = spanToJSON(span).span_id; + if (spanId) { + if (!pendingSpanAttributes.has(spanId) && pendingSpanAttributes.size >= MAX_PENDING_SPAN_ATTRIBUTES) { + const oldest = pendingSpanAttributes.keys().next().value; + if (oldest !== undefined) { + pendingSpanAttributes.delete(oldest); } } + pendingSpanAttributes.set(spanId, attributes); } - return out; } -function serialiseRowAsObject(row: TurboModuleAggregate): { - name: string; - method: string; - kind: string; - call_count: number; - error_count: number; - total_ms: number; - max_ms: number; - histogram: Record; -} { - const histogram: Record = {}; - for (let i = 0; i < row.buckets.length; i++) { - const label = HISTOGRAM_BUCKET_LABELS[i]; - const count = row.buckets[i]; - if (label !== undefined && count !== undefined) { - histogram[label] = count; - } - } - return { - name: row.name, - method: row.method, - kind: row.kind, - call_count: row.callCount, - error_count: row.errorCount, - total_ms: roundMs(row.totalDurationMs), - max_ms: roundMs(row.maxDurationMs), - histogram, - }; +/** `.` is the attribute-key delimiter — escape it in name/method to avoid collisions. */ +function safeKeyPart(s: string): string { + return s.replace(/\./g, '_'); } -function roundMs(value: number): number { - // Two-decimal precision is more than enough for human-readable totals - // and keeps the JSON payload terse. - return Math.round(value * 100) / 100; +function mergeAttributesIntoTraceData( + event: TransactionEvent, + attributes: Record, +): void { + const trace = event.contexts?.trace; + if (!trace) { + return; + } + const data = { ...((trace.data as Record | undefined) ?? {}) }; + for (const key of Object.keys(attributes)) { + const value = attributes[key]; + if (value === undefined) { + // oxlint-disable-next-line typescript-eslint(no-dynamic-delete) + delete data[key]; + } else { + data[key] = value; + } + } + trace.data = data; } diff --git a/packages/core/src/js/integrations/turboModuleContextFlush.ts b/packages/core/src/js/integrations/turboModuleContextFlush.ts new file mode 100644 index 0000000000..7362cdded6 --- /dev/null +++ b/packages/core/src/js/integrations/turboModuleContextFlush.ts @@ -0,0 +1,179 @@ +import type { Client, TransactionEvent } from '@sentry/core'; + +import { debug } from '@sentry/core'; + +import { createSpanJSON } from '../tracing/utils'; +import { + drainTurboModuleAggregate, + HISTOGRAM_BUCKET_LABELS, + hasTurboModuleAggregateData, + type TurboModuleAggregate, +} from '../turbomodule'; + +export const TURBO_MODULES_AGGREGATE_OP = 'turbo_modules.aggregate'; +export const TURBO_MODULES_AGGREGATE_ORIGIN = 'auto.tracing.turbo_modules'; + +const MAX_AGGREGATE_ATTRIBUTE_ROWS = 64; + +/** + * Drains the aggregate into the transaction event as a synthetic child span + * plus headline measurements. Runs before `beforeSendTransaction`, so a + * user-dropped transaction loses its interval — bounded and self-healing. + */ +export function attachAggregateToTransactionEvent(event: TransactionEvent): void { + const trace = event.contexts?.trace; + if (!trace?.trace_id || !trace.span_id) { + return; + } + const startTs = event.start_timestamp; + const endTs = event.timestamp; + if (typeof startTs !== 'number' || typeof endTs !== 'number') { + return; + } + + const snapshot = drainTurboModuleAggregate(); + if (snapshot.length === 0) { + return; + } + + const totals = summarise(snapshot); + const topByTotalMs = [...snapshot].sort((a, b) => b.totalDurationMs - a.totalDurationMs); + + const aggregateSpan = createSpanJSON({ + op: TURBO_MODULES_AGGREGATE_OP, + description: 'TurboModule call aggregate', + start_timestamp: startTs, + timestamp: endTs, + trace_id: trace.trace_id, + parent_span_id: trace.span_id, + origin: TURBO_MODULES_AGGREGATE_ORIGIN, + data: { + 'turbo_modules.total_call_count': totals.callCount, + 'turbo_modules.total_error_count': totals.errorCount, + 'turbo_modules.total_duration_ms': roundMs(totals.totalDurationMs), + 'turbo_modules.unique_methods': snapshot.length, + ...serialiseRows(topByTotalMs.slice(0, MAX_AGGREGATE_ATTRIBUTE_ROWS)), + }, + }); + + event.spans = event.spans ?? []; + event.spans.push(aggregateSpan); + + event.measurements = event.measurements ?? {}; + event.measurements['turbo_modules.call_count'] = { value: totals.callCount, unit: 'none' }; + event.measurements['turbo_modules.error_count'] = { value: totals.errorCount, unit: 'none' }; + event.measurements['turbo_modules.total_ms'] = { value: roundMs(totals.totalDurationMs), unit: 'millisecond' }; + + const top = topByTotalMs[0]; + if (top) { + event.measurements['turbo_modules.top_module_ms'] = { + value: roundMs(top.totalDurationMs), + unit: 'millisecond', + }; + } + + if (snapshot.length > MAX_AGGREGATE_ATTRIBUTE_ROWS) { + debug.log( + `[TurboModuleContext] Aggregate has ${snapshot.length} rows, truncated to top ${MAX_AGGREGATE_ATTRIBUTE_ROWS} ` + + `by total_ms on the aggregate span. Headline measurements still reflect the full totals.`, + ); + } +} + +/** Custom Sentry event so long-running sessions without a transaction still emit a signal. */ +export function flushPeriodicAggregate(client: Client): void { + if (!hasTurboModuleAggregateData()) { + return; + } + const snapshot = drainTurboModuleAggregate(); + const totals = summarise(snapshot); + const topByTotalMs = [...snapshot].sort((a, b) => b.totalDurationMs - a.totalDurationMs); + + client.captureEvent?.({ + message: 'TurboModule aggregate (periodic)', + level: 'info', + tags: { + 'event.kind': 'turbo_modules.aggregate', + }, + extra: { + total_call_count: totals.callCount, + total_error_count: totals.errorCount, + total_duration_ms: roundMs(totals.totalDurationMs), + unique_methods: snapshot.length, + modules: topByTotalMs.slice(0, MAX_AGGREGATE_ATTRIBUTE_ROWS).map(serialiseRowAsObject), + }, + }); +} + +function summarise(snapshot: ReadonlyArray): { + callCount: number; + errorCount: number; + totalDurationMs: number; +} { + let callCount = 0; + let errorCount = 0; + let totalDurationMs = 0; + for (const row of snapshot) { + callCount += row.callCount; + errorCount += row.errorCount; + totalDurationMs += row.totalDurationMs; + } + return { callCount, errorCount, totalDurationMs }; +} + +function serialiseRows(rows: ReadonlyArray): Record { + const out: Record = {}; + for (const row of rows) { + const prefix = `turbo_modules.${safeKeyPart(row.name)}.${safeKeyPart(row.method)}.${row.kind}`; + out[`${prefix}.count`] = row.callCount; + out[`${prefix}.error_count`] = row.errorCount; + out[`${prefix}.total_ms`] = roundMs(row.totalDurationMs); + out[`${prefix}.max_ms`] = roundMs(row.maxDurationMs); + for (let i = 0; i < row.buckets.length; i++) { + const label = HISTOGRAM_BUCKET_LABELS[i]; + const count = row.buckets[i]; + if (label !== undefined && count !== undefined) { + out[`${prefix}.${label}`] = count; + } + } + } + return out; +} + +function serialiseRowAsObject(row: TurboModuleAggregate): { + name: string; + method: string; + kind: string; + call_count: number; + error_count: number; + total_ms: number; + max_ms: number; + histogram: Record; +} { + const histogram: Record = {}; + for (let i = 0; i < row.buckets.length; i++) { + const label = HISTOGRAM_BUCKET_LABELS[i]; + const count = row.buckets[i]; + if (label !== undefined && count !== undefined) { + histogram[label] = count; + } + } + return { + name: row.name, + method: row.method, + kind: row.kind, + call_count: row.callCount, + error_count: row.errorCount, + total_ms: roundMs(row.totalDurationMs), + max_ms: roundMs(row.maxDurationMs), + histogram, + }; +} + +export function roundMs(value: number): number { + return Math.round(value * 100) / 100; +} + +function safeKeyPart(s: string): string { + return s.replace(/\./g, '_'); +} diff --git a/packages/core/src/js/turbomodule/index.ts b/packages/core/src/js/turbomodule/index.ts index 272d24c6f1..03be558a7e 100644 --- a/packages/core/src/js/turbomodule/index.ts +++ b/packages/core/src/js/turbomodule/index.ts @@ -6,14 +6,25 @@ export { } from './turboModuleTracker'; export type { TurboModuleCall, TurboModuleCallKind } from './turboModuleTracker'; export { + addTurboModuleCallStartObserver, + addTurboModuleRecordObserver, drainTurboModuleAggregate, HISTOGRAM_BUCKET_LABELS, HISTOGRAM_BUCKETS_MS, hasTurboModuleAggregateData, + notifyTurboModuleCallStart, recordTurboModuleCall, + removeTurboModuleCallStartObserver, + removeTurboModuleRecordObserver, setAggregateRecordingEnabled, setIgnoredTurboModules, setOnFirstTurboModuleRecord, } from './turboModuleAggregator'; -export type { TurboModuleAggregate } from './turboModuleAggregator'; +export type { + TurboModuleAggregate, + TurboModuleCallStart, + TurboModuleCallStartObserver, + TurboModuleRecord, + TurboModuleRecordObserver, +} from './turboModuleAggregator'; export { wrapTurboModule } from './wrapTurboModule'; diff --git a/packages/core/src/js/turbomodule/turboModuleAggregator.ts b/packages/core/src/js/turbomodule/turboModuleAggregator.ts index 842c3f5ff9..73ed53935e 100644 --- a/packages/core/src/js/turbomodule/turboModuleAggregator.ts +++ b/packages/core/src/js/turbomodule/turboModuleAggregator.ts @@ -54,9 +54,36 @@ interface MutableAggregate extends TurboModuleAggregate { buckets: number[]; } +export interface TurboModuleRecord { + name: string; + method: string; + kind: TurboModuleCallKind; + durationMs: number; + errored: boolean; + /** + * Correlator returned by {@link notifyTurboModuleCallStart}. Present when the + * wrap layer paired the record with a start notification; missing when a + * caller invokes `recordTurboModuleCall` directly (tests, external hooks). + */ + recordId?: number; +} + +export interface TurboModuleCallStart { + recordId: number; + name: string; + method: string; + kind: TurboModuleCallKind; +} + +export type TurboModuleRecordObserver = (record: TurboModuleRecord) => void; +export type TurboModuleCallStartObserver = (start: TurboModuleCallStart) => void; + const aggregates = new Map(); const ignoredModules = new Set(); let onFirstRecordAfterEmpty: (() => void) | undefined; +const observers: Set = new Set(); +const startObservers: Set = new Set(); +let nextRecordId = 0; // When `false`, `recordTurboModuleCall` is a no-op. The integration flips // this off when `enableAggregateStats: false` so wrapped TurboModule calls // don't accumulate into a map that nothing ever drains. @@ -109,55 +136,121 @@ export function recordTurboModuleCall(args: { kind: TurboModuleCallKind; durationMs: number; errored: boolean; + recordId?: number; }): void { - if (!recordingEnabled) { - return; - } if (ignoredModules.has(args.name)) { return; } - const wasEmpty = aggregates.size === 0; const duration = args.durationMs > 0 ? args.durationMs : 0; - const key = makeKey(args.name, args.method, args.kind); - let entry = aggregates.get(key); - if (!entry) { - entry = { + if (recordingEnabled) { + const wasEmpty = aggregates.size === 0; + const key = makeKey(args.name, args.method, args.kind); + + let entry = aggregates.get(key); + if (!entry) { + entry = { + name: args.name, + method: args.method, + kind: args.kind, + callCount: 0, + errorCount: 0, + totalDurationMs: 0, + maxDurationMs: 0, + buckets: new Array(HISTOGRAM_BUCKETS_MS.length + 1).fill(0) as number[], + }; + aggregates.set(key, entry); + } + + entry.callCount += 1; + if (args.errored) { + entry.errorCount += 1; + } + entry.totalDurationMs += duration; + if (duration > entry.maxDurationMs) { + entry.maxDurationMs = duration; + } + + const bucket = bucketIndexForDuration(duration); + entry.buckets[bucket] = (entry.buckets[bucket] ?? 0) + 1; + + if (wasEmpty && onFirstRecordAfterEmpty) { + try { + onFirstRecordAfterEmpty(); + } catch { + // intentionally swallowed + } + } + } + + // Observers fire regardless of `recordingEnabled` so span attribution and + // slow-call breadcrumbs work even when aggregate stats are opted out. + if (observers.size > 0) { + const record: TurboModuleRecord = { name: args.name, method: args.method, kind: args.kind, - callCount: 0, - errorCount: 0, - totalDurationMs: 0, - maxDurationMs: 0, - buckets: new Array(HISTOGRAM_BUCKETS_MS.length + 1).fill(0) as number[], + durationMs: duration, + errored: args.errored, + recordId: args.recordId, }; - aggregates.set(key, entry); + for (const observer of observers) { + try { + observer(record); + } catch { + // A misbehaving observer must not drop records for others. + } + } } +} - entry.callCount += 1; - if (args.errored) { - entry.errorCount += 1; - } - entry.totalDurationMs += duration; - if (duration > entry.maxDurationMs) { - entry.maxDurationMs = duration; - } +/** + * Subscribes to per-record notifications. Fires for records that survive the + * `setAggregateRecordingEnabled` / `setIgnoredTurboModules` filters — the same + * set that reaches the aggregate map. Observers run synchronously on the wrap + * hot path, so must be O(1); thrown errors are swallowed. + */ +export function addTurboModuleRecordObserver(observer: TurboModuleRecordObserver): void { + observers.add(observer); +} - const bucket = bucketIndexForDuration(duration); - // Bucket index is bounded by `bucketIndexForDuration`; `?? 0` here only - // exists to satisfy `noUncheckedIndexedAccess`. - entry.buckets[bucket] = (entry.buckets[bucket] ?? 0) + 1; +export function removeTurboModuleRecordObserver(observer: TurboModuleRecordObserver): void { + observers.delete(observer); +} - if (wasEmpty && onFirstRecordAfterEmpty) { - // Don't let a misbehaving observer corrupt the aggregate. +/** + * Notifies start observers that a TurboModule call is about to run and returns + * a `recordId` correlator. The paired {@link recordTurboModuleCall} passes the + * same id back so consumers (e.g. per-span attribution) can associate the + * settle-time record with state captured at call-start time — matters for + * async calls that outlive the span they started in. + * + * Returns the `recordId` even for ignored modules so the wrap layer never has + * to branch — the paired record for an ignored module will be filtered out. + */ +export function notifyTurboModuleCallStart(name: string, method: string, kind: TurboModuleCallKind): number { + const recordId = nextRecordId++; + if (ignoredModules.has(name) || startObservers.size === 0) { + return recordId; + } + const event: TurboModuleCallStart = { recordId, name, method, kind }; + for (const observer of startObservers) { try { - onFirstRecordAfterEmpty(); + observer(event); } catch { - // intentionally swallowed + // A misbehaving observer must not drop the start signal for others. } } + return recordId; +} + +export function addTurboModuleCallStartObserver(observer: TurboModuleCallStartObserver): void { + startObservers.add(observer); +} + +export function removeTurboModuleCallStartObserver(observer: TurboModuleCallStartObserver): void { + startObservers.delete(observer); } /** @@ -230,5 +323,8 @@ export function _resetTurboModuleAggregator(): void { aggregates.clear(); ignoredModules.clear(); onFirstRecordAfterEmpty = undefined; + observers.clear(); + startObservers.clear(); + nextRecordId = 0; recordingEnabled = true; } diff --git a/packages/core/src/js/turbomodule/wrapTurboModule.ts b/packages/core/src/js/turbomodule/wrapTurboModule.ts index 26f5e8f7cf..a2ae9afa2c 100644 --- a/packages/core/src/js/turbomodule/wrapTurboModule.ts +++ b/packages/core/src/js/turbomodule/wrapTurboModule.ts @@ -2,7 +2,7 @@ import { logger } from '@sentry/core'; import type { TurboModuleCallKind } from './turboModuleTracker'; -import { recordTurboModuleCall } from './turboModuleAggregator'; +import { notifyTurboModuleCallStart, recordTurboModuleCall } from './turboModuleAggregator'; import { popTurboModuleCall, pushTurboModuleCall, relabelTurboModuleCallKind } from './turboModuleTracker'; /** @@ -85,18 +85,24 @@ export function wrapTurboModule( // as sync, relabel to 'async' if the result turns out to be thenable. let callId: number | undefined; const startedAtMs = Date.now(); + let recordId: number | undefined; try { callId = pushTurboModuleCall({ name, method: key, kind: 'sync' }); } catch (e) { logger.warn(`[TurboModuleTracker] push failed for ${name}.${key}: ${String(e)}`); } + try { + recordId = notifyTurboModuleCallStart(name, key, 'sync'); + } catch (e) { + logger.warn(`[TurboModuleTracker] notifyStart failed for ${name}.${key}: ${String(e)}`); + } let result: unknown; try { result = originalFn.apply(this, args); } catch (e) { safePop(callId, name, key); - safeRecord(name, key, 'sync', startedAtMs, true); + safeRecord(name, key, 'sync', startedAtMs, true, recordId); throw e; } @@ -105,19 +111,19 @@ export function wrapTurboModule( return (result as Promise).then( value => { safePop(callId, name, key); - safeRecord(name, key, 'async', startedAtMs, false); + safeRecord(name, key, 'async', startedAtMs, false, recordId); return value; }, err => { safePop(callId, name, key); - safeRecord(name, key, 'async', startedAtMs, true); + safeRecord(name, key, 'async', startedAtMs, true, recordId); throw err; }, ); } safePop(callId, name, key); - safeRecord(name, key, 'sync', startedAtMs, false); + safeRecord(name, key, 'sync', startedAtMs, false, recordId); return result; }; @@ -199,6 +205,7 @@ function safeRecord( kind: TurboModuleCallKind, startedAtMs: number, errored: boolean, + recordId: number | undefined, ): void { try { recordTurboModuleCall({ @@ -207,6 +214,7 @@ function safeRecord( kind, durationMs: Date.now() - startedAtMs, errored, + recordId, }); } catch (e) { logger.warn(`[TurboModuleTracker] record failed for ${name}.${method}: ${String(e)}`); diff --git a/packages/core/test/integrations/turboModuleContext.test.ts b/packages/core/test/integrations/turboModuleContext.test.ts index c6d86425f4..54cc6244df 100644 --- a/packages/core/test/integrations/turboModuleContext.test.ts +++ b/packages/core/test/integrations/turboModuleContext.test.ts @@ -1,19 +1,24 @@ -import type { Client, TransactionEvent } from '@sentry/core'; +import type { Client, Span, TransactionEvent } from '@sentry/core'; import { Scope } from '@sentry/core'; import * as SentryCore from '@sentry/core'; import { DEFAULT_AGGREGATE_FLUSH_INTERVAL_MS, + DEFAULT_SLOW_CALL_THRESHOLD_MS, + MAX_PENDING_CALL_WINDOWS, turboModuleContextIntegration, + TURBO_MODULE_BREADCRUMB_CATEGORY, TURBO_MODULES_AGGREGATE_OP, } from '../../src/js/integrations/turboModuleContext'; import * as turboModule from '../../src/js/turbomodule'; import { _resetTurboModuleAggregator, hasTurboModuleAggregateData, + notifyTurboModuleCallStart, recordTurboModuleCall, } from '../../src/js/turbomodule/turboModuleAggregator'; +import * as spanUtils from '../../src/js/utils/span'; import * as wrapper from '../../src/js/wrapper'; function makeTransactionEvent(overrides: Partial = {}): TransactionEvent { @@ -38,6 +43,54 @@ function makeMockClient(): Client & { on: jest.Mock; captureEvent: jest.Mock } { } as unknown as Client & { on: jest.Mock; captureEvent: jest.Mock }; } +type ClientHandler = (arg: unknown) => void; + +function makeClientWithSpanHooks(): { + client: Client & { on: jest.Mock; captureEvent: jest.Mock }; + handlers: Map; + emit: (event: string, arg: unknown) => void; +} { + const handlers = new Map(); + const client = { + on: jest.fn((event: string, cb: ClientHandler) => { + const list = handlers.get(event) ?? []; + list.push(cb); + handlers.set(event, list); + }), + captureEvent: jest.fn(), + } as unknown as Client & { on: jest.Mock; captureEvent: jest.Mock }; + return { + client, + handlers, + emit: (event: string, arg: unknown) => { + for (const cb of handlers.get(event) ?? []) { + cb(arg); + } + }, + }; +} + +function makeFakeSpan(overrides: { spanId?: string } = {}): Span & { + setAttributes: jest.Mock; + spanContext: () => { spanId: string; traceId: string; traceFlags: number }; +} { + const attributes: Record = {}; + return { + setAttributes: jest.fn((next: Record) => { + Object.assign(attributes, next); + }), + spanContext: () => ({ + spanId: overrides.spanId ?? 'span-id', + traceId: 't'.repeat(32), + traceFlags: 1, + }), + __attributes: attributes, + } as unknown as Span & { + setAttributes: jest.Mock; + spanContext: () => { spanId: string; traceId: string; traceFlags: number }; + }; +} + describe('turboModuleContextIntegration', () => { let scope: Scope; @@ -296,4 +349,467 @@ describe('turboModuleContextIntegration', () => { expect(out.measurements ?? {}).toEqual({}); }); }); + + describe('span attribution', () => { + let addBreadcrumbSpy: jest.SpyInstance; + + beforeEach(() => { + jest.spyOn(wrapper, 'getRNSentryModule').mockReturnValue(undefined); + jest.spyOn(spanUtils, 'isRootSpan').mockReturnValue(true); + addBreadcrumbSpy = jest.spyOn(SentryCore, 'addBreadcrumb').mockImplementation(() => {}); + }); + + it('attaches per-(module, method) attributes to root spans on spanEnd', () => { + const integration = turboModuleContextIntegration({ aggregateFlushIntervalMs: 0 }); + integration.setupOnce?.(); + const { client, emit } = makeClientWithSpanHooks(); + integration.setup?.(client); + + const span = makeFakeSpan(); + emit('spanStart', span); + + recordTurboModuleCall({ name: 'UserMod', method: 'work', kind: 'async', durationMs: 12, errored: false }); + recordTurboModuleCall({ name: 'UserMod', method: 'work', kind: 'async', durationMs: 8, errored: true }); + recordTurboModuleCall({ name: 'Other', method: 'ping', kind: 'sync', durationMs: 1, errored: false }); + + emit('spanEnd', span); + + expect(span.setAttributes).toHaveBeenCalledTimes(1); + const attributes = span.setAttributes.mock.calls[0]?.[0] as Record; + expect(attributes).toMatchObject({ + 'turbo_module.UserMod.work.call_count': 2, + 'turbo_module.UserMod.work.duration_ms': 20, + 'turbo_module.UserMod.work.error_count': 1, + 'turbo_module.Other.ping.call_count': 1, + 'turbo_module.total_call_count': 3, + 'turbo_module.total_error_count': 1, + 'turbo_module.top_module': 'UserMod.work', + }); + }); + + it('caps the per-row attribute payload to maxTopModulesPerSpan', () => { + const integration = turboModuleContextIntegration({ + aggregateFlushIntervalMs: 0, + maxTopModulesPerSpan: 2, + }); + integration.setupOnce?.(); + const { client, emit } = makeClientWithSpanHooks(); + integration.setup?.(client); + + const span = makeFakeSpan(); + emit('spanStart', span); + + recordTurboModuleCall({ name: 'A', method: 'x', kind: 'sync', durationMs: 100, errored: false }); + recordTurboModuleCall({ name: 'B', method: 'x', kind: 'sync', durationMs: 50, errored: false }); + recordTurboModuleCall({ name: 'C', method: 'x', kind: 'sync', durationMs: 10, errored: false }); + + emit('spanEnd', span); + + const attributes = span.setAttributes.mock.calls[0]?.[0] as Record; + expect(attributes['turbo_module.A.x.call_count']).toBe(1); + expect(attributes['turbo_module.B.x.call_count']).toBe(1); + expect(attributes['turbo_module.C.x.call_count']).toBeUndefined(); + expect(attributes['turbo_module.total_call_count']).toBe(3); + expect(attributes['turbo_module.unique_methods']).toBe(3); + }); + + it('credits async calls that started inside the span but settled after it ended', () => { + const integration = turboModuleContextIntegration({ aggregateFlushIntervalMs: 0 }); + integration.setupOnce?.(); + const { client, emit } = makeClientWithSpanHooks(); + integration.setup?.(client); + + const span = makeFakeSpan(); + emit('spanStart', span); + + // Async call starts during the span, settles after — mirrors what + // `wrapTurboModule` does when a promise-returning method is invoked. + const recordId = notifyTurboModuleCallStart('Late', 'load', 'async'); + emit('spanEnd', span); + recordTurboModuleCall({ name: 'Late', method: 'load', kind: 'async', durationMs: 42, errored: false, recordId }); + + // Only the late record has data — spanEnd's best-effort attach is a + // no-op with nothing to serialise. The record's own attach carries it. + expect(span.setAttributes).toHaveBeenCalledTimes(1); + const attributes = span.setAttributes.mock.calls[0]?.[0] as Record; + expect(attributes['turbo_module.Late.load.call_count']).toBe(1); + expect(attributes['turbo_module.Late.load.duration_ms']).toBe(42); + }); + + it('does not credit a later span for an async call that started before any span was open', () => { + const integration = turboModuleContextIntegration({ aggregateFlushIntervalMs: 0 }); + integration.setupOnce?.(); + const { client, emit } = makeClientWithSpanHooks(); + integration.setup?.(client); + + // Async call starts with no span open — snapshot must capture "no + // windows" rather than nothing. + const recordId = notifyTurboModuleCallStart('Boot', 'init', 'async'); + + // Span opens *after* the call started. + const span = makeFakeSpan(); + emit('spanStart', span); + + // Call settles into the recordObserver — must not credit `span`. + recordTurboModuleCall({ name: 'Boot', method: 'init', kind: 'async', durationMs: 10, errored: false, recordId }); + + emit('spanEnd', span); + + expect(span.setAttributes).not.toHaveBeenCalled(); + }); + + it('clears stale per-method keys on re-emit after a late-settling async re-ranks the top-N', () => { + const integration = turboModuleContextIntegration({ + aggregateFlushIntervalMs: 0, + maxTopModulesPerSpan: 2, + }); + integration.setupOnce?.(); + const { client, emit } = makeClientWithSpanHooks(); + integration.setup?.(client); + + const span = makeFakeSpan(); + emit('spanStart', span); + + // A and B fit within maxTopModulesPerSpan=2 at spanEnd. + recordTurboModuleCall({ name: 'A', method: 'x', kind: 'sync', durationMs: 100, errored: false }); + recordTurboModuleCall({ name: 'B', method: 'x', kind: 'sync', durationMs: 50, errored: false }); + + // Async C starts before spanEnd so it captures the window and can credit + // it after spanEnd via `pendingCallWindows`. + const recordId = notifyTurboModuleCallStart('C', 'x', 'async'); + emit('spanEnd', span); + + // Late-settling async C outweighs B and takes B's slot in the top-2. + // Without clearing, B's stale per-method keys would linger on the span + // because `setAttributes` merges. + recordTurboModuleCall({ + name: 'C', + method: 'x', + kind: 'async', + durationMs: 1000, + errored: false, + recordId, + }); + + expect(span.setAttributes).toHaveBeenCalledTimes(2); + const secondCall = span.setAttributes.mock.calls[1]?.[0] as Record; + // The re-emit must explicitly pass undefined for B's per-method keys so + // the merge clears them from the span. Use array form of toHaveProperty + // to match keys that contain dots. + expect(secondCall).toHaveProperty(['turbo_module.B.x.call_count'], undefined); + expect(secondCall).toHaveProperty(['turbo_module.B.x.duration_ms'], undefined); + expect(secondCall).toHaveProperty(['turbo_module.B.x.error_count'], undefined); + // Top-2 now reflects C and A. + expect(secondCall['turbo_module.C.x.duration_ms']).toBe(1000); + expect(secondCall['turbo_module.A.x.call_count']).toBe(1); + }); + + it('caps pendingCallWindows so unresolved async calls do not leak', () => { + const integration = turboModuleContextIntegration({ aggregateFlushIntervalMs: 0 }); + integration.setupOnce?.(); + const { client, emit } = makeClientWithSpanHooks(); + integration.setup?.(client); + + const span = makeFakeSpan(); + emit('spanStart', span); + + // Start MAX_PENDING_CALL_WINDOWS + 1 async calls. The very first entry + // must be evicted (oldest-first eviction). + const firstRecordId = notifyTurboModuleCallStart('First', 'work', 'async'); + const fillerIds: number[] = []; + for (let i = 0; i < MAX_PENDING_CALL_WINDOWS; i++) { + fillerIds.push(notifyTurboModuleCallStart('Filler', `m${i}`, 'async')); + } + + // Settle a filler so its window credit lands on the span — this drives + // `attachWindowToSpan` on `spanEnd` and gives us setAttributes calls to + // inspect below. + const survivor = fillerIds[0]; + if (survivor !== undefined) { + recordTurboModuleCall({ + name: 'Filler', + method: 'm0', + kind: 'async', + durationMs: 3, + errored: false, + recordId: survivor, + }); + } + + // Settle the evicted first call — its pending window entry is gone, so + // it must NOT credit `span`. + recordTurboModuleCall({ + name: 'First', + method: 'work', + kind: 'async', + durationMs: 5, + errored: false, + recordId: firstRecordId, + }); + + emit('spanEnd', span); + + // spanEnd must have flushed the window at least once, and none of the + // resulting payloads may contain the evicted `First.work` row. + expect(span.setAttributes.mock.calls.length).toBeGreaterThan(0); + for (const [attributes] of span.setAttributes.mock.calls) { + expect(attributes['turbo_module.First.work.call_count']).toBeUndefined(); + } + // The surviving filler *did* get credited — that's the positive control + // that keeps this test from silently passing on an empty payload. + const lastCall = span.setAttributes.mock.calls.at(-1)?.[0] as Record; + expect(lastCall['turbo_module.Filler.m0.call_count']).toBe(1); + }); + + it('merges the latest attribute payload onto the transaction event via processEvent', () => { + // The Sentry SDK freezes a span at `.end()`, so a late-settling async + // record after `spanEnd` can't reach the transaction through + // `span.setAttributes` alone. The integration also buffers the payload + // by span_id and merges it into `event.contexts.trace.data` on the + // paired transaction event — this test drives that path. + const integration = turboModuleContextIntegration({ aggregateFlushIntervalMs: 0 }); + integration.setupOnce?.(); + const { client, emit } = makeClientWithSpanHooks(); + integration.setup?.(client); + + const span = makeFakeSpan({ spanId: 'root-1' }); + emit('spanStart', span); + + const recordId = notifyTurboModuleCallStart('Late', 'load', 'async'); + emit('spanEnd', span); + recordTurboModuleCall({ + name: 'Late', + method: 'load', + kind: 'async', + durationMs: 42, + errored: false, + recordId, + }); + + const event = makeTransactionEvent({ + contexts: { trace: { trace_id: 'a'.repeat(32), span_id: 'root-1' } }, + }); + const out = integration.processEvent?.(event, {}, makeMockClient()) as TransactionEvent; + const data = out.contexts?.trace?.data as Record | undefined; + + expect(data).toBeDefined(); + expect(data?.['turbo_module.Late.load.call_count']).toBe(1); + expect(data?.['turbo_module.Late.load.duration_ms']).toBe(42); + expect(data?.['turbo_module.total_call_count']).toBe(1); + }); + + it('does not overwrite pre-existing trace.data keys when merging', () => { + const integration = turboModuleContextIntegration({ aggregateFlushIntervalMs: 0 }); + integration.setupOnce?.(); + const { client, emit } = makeClientWithSpanHooks(); + integration.setup?.(client); + + const span = makeFakeSpan({ spanId: 'root-2' }); + emit('spanStart', span); + recordTurboModuleCall({ name: 'Mod', method: 'op', kind: 'sync', durationMs: 1, errored: false }); + emit('spanEnd', span); + + const event = makeTransactionEvent({ + contexts: { + trace: { + trace_id: 'a'.repeat(32), + span_id: 'root-2', + data: { 'existing.key': 'kept' }, + }, + }, + }); + const out = integration.processEvent?.(event, {}, makeMockClient()) as TransactionEvent; + const data = out.contexts?.trace?.data as Record; + + expect(data['existing.key']).toBe('kept'); + expect(data['turbo_module.Mod.op.call_count']).toBe(1); + }); + + it('escapes dots in module and method names so distinct pairs never collapse', () => { + // `(name="a.b", method="c")` and `(name="a", method="b.c")` would both + // produce `turbo_module.a.b.c.*` without escaping and overwrite each + // other in the attribute payload. + const integration = turboModuleContextIntegration({ aggregateFlushIntervalMs: 0 }); + integration.setupOnce?.(); + const { client, emit } = makeClientWithSpanHooks(); + integration.setup?.(client); + + const span = makeFakeSpan(); + emit('spanStart', span); + recordTurboModuleCall({ name: 'a.b', method: 'c', kind: 'sync', durationMs: 5, errored: false }); + recordTurboModuleCall({ name: 'a', method: 'b.c', kind: 'sync', durationMs: 7, errored: false }); + emit('spanEnd', span); + + const attributes = span.setAttributes.mock.calls[0]?.[0] as Record; + // Two distinct keys must survive — no collision. + expect(attributes['turbo_module.a_b.c.call_count']).toBe(1); + expect(attributes['turbo_module.a.b_c.call_count']).toBe(1); + expect(attributes['turbo_module.unique_methods']).toBe(2); + }); + + it('does not attach attributes to non-root spans', () => { + (spanUtils.isRootSpan as jest.Mock).mockReturnValue(false); + + const integration = turboModuleContextIntegration({ aggregateFlushIntervalMs: 0 }); + integration.setupOnce?.(); + const { client, emit } = makeClientWithSpanHooks(); + integration.setup?.(client); + + const span = makeFakeSpan(); + emit('spanStart', span); + recordTurboModuleCall({ name: 'A', method: 'x', kind: 'sync', durationMs: 1, errored: false }); + emit('spanEnd', span); + + expect(span.setAttributes).not.toHaveBeenCalled(); + }); + + it('is inert when enableSpanAttribution is disabled', () => { + const integration = turboModuleContextIntegration({ + aggregateFlushIntervalMs: 0, + enableSpanAttribution: false, + }); + integration.setupOnce?.(); + const { client, handlers } = makeClientWithSpanHooks(); + integration.setup?.(client); + + expect(handlers.has('spanStart')).toBe(false); + expect(handlers.has('spanEnd')).toBe(false); + }); + + it('emits a native.turbo_module breadcrumb for async calls exceeding the threshold', () => { + const integration = turboModuleContextIntegration({ aggregateFlushIntervalMs: 0 }); + integration.setupOnce?.(); + const { client } = makeClientWithSpanHooks(); + integration.setup?.(client); + + recordTurboModuleCall({ + name: 'Slow', + method: 'blocking', + kind: 'async', + durationMs: DEFAULT_SLOW_CALL_THRESHOLD_MS + 50, + errored: false, + }); + + expect(addBreadcrumbSpy).toHaveBeenCalledTimes(1); + const breadcrumb = addBreadcrumbSpy.mock.calls[0]?.[0]; + expect(breadcrumb).toMatchObject({ + category: TURBO_MODULE_BREADCRUMB_CATEGORY, + level: 'info', + data: expect.objectContaining({ module: 'Slow', method: 'blocking', kind: 'async' }), + }); + }); + + it('does not emit a breadcrumb below the threshold or for sync calls', () => { + const integration = turboModuleContextIntegration({ aggregateFlushIntervalMs: 0 }); + integration.setupOnce?.(); + const { client } = makeClientWithSpanHooks(); + integration.setup?.(client); + + recordTurboModuleCall({ + name: 'Fast', + method: 'noop', + kind: 'async', + durationMs: DEFAULT_SLOW_CALL_THRESHOLD_MS - 1, + errored: false, + }); + recordTurboModuleCall({ + name: 'SlowSync', + method: 'block', + kind: 'sync', + durationMs: DEFAULT_SLOW_CALL_THRESHOLD_MS + 100, + errored: false, + }); + + expect(addBreadcrumbSpy).not.toHaveBeenCalled(); + }); + + it('emits slow-call breadcrumbs even when enableSpanAttribution is disabled', () => { + // `slowCallThresholdMs` is documented as an independent knob — turning + // span attribution off must not silently disable breadcrumbs. + const integration = turboModuleContextIntegration({ + aggregateFlushIntervalMs: 0, + enableSpanAttribution: false, + }); + integration.setupOnce?.(); + const { client } = makeClientWithSpanHooks(); + integration.setup?.(client); + + recordTurboModuleCall({ + name: 'Slow', + method: 'blocking', + kind: 'async', + durationMs: DEFAULT_SLOW_CALL_THRESHOLD_MS + 50, + errored: false, + }); + + expect(addBreadcrumbSpy).toHaveBeenCalledTimes(1); + }); + + it('does not register the record observer when both span attribution and breadcrumbs are off', () => { + const integration = turboModuleContextIntegration({ + aggregateFlushIntervalMs: 0, + enableSpanAttribution: false, + slowCallThresholdMs: 0, + }); + integration.setupOnce?.(); + const { client } = makeClientWithSpanHooks(); + integration.setup?.(client); + + // With every per-record surface disabled, a call must be a no-op — + // no breadcrumb, no attempt to touch a span. + recordTurboModuleCall({ + name: 'X', + method: 'y', + kind: 'async', + durationMs: DEFAULT_SLOW_CALL_THRESHOLD_MS + 100, + errored: false, + }); + + expect(addBreadcrumbSpy).not.toHaveBeenCalled(); + }); + + it('does not evict async pending entries when sync calls churn through the pending map', () => { + const integration = turboModuleContextIntegration({ aggregateFlushIntervalMs: 0 }); + integration.setupOnce?.(); + const { client, emit } = makeClientWithSpanHooks(); + integration.setup?.(client); + + const span = makeFakeSpan(); + emit('spanStart', span); + + // A legitimate long-running async call starts and holds a slot. + const asyncRecordId = notifyTurboModuleCallStart('Long', 'req', 'async'); + + // A burst of paired sync notify+record calls (what `wrapTurboModule` + // does for every wrapped invocation before it knows if the return is + // thenable). Each entry lives briefly then is removed by the paired + // record, so the map stays bounded by in-flight async count. + for (let i = 0; i < MAX_PENDING_CALL_WINDOWS + 5; i++) { + const syncId = notifyTurboModuleCallStart('SyncBurst', `m${i}`, 'sync'); + recordTurboModuleCall({ + name: 'SyncBurst', + method: `m${i}`, + kind: 'sync', + durationMs: 1, + errored: false, + recordId: syncId, + }); + } + + // `Long` settles after the burst — its window snapshot survived. + recordTurboModuleCall({ + name: 'Long', + method: 'req', + kind: 'async', + durationMs: 42, + errored: false, + recordId: asyncRecordId, + }); + emit('spanEnd', span); + + const attributes = span.setAttributes.mock.calls.at(-1)?.[0] as Record; + expect(attributes['turbo_module.Long.req.call_count']).toBe(1); + expect(attributes['turbo_module.Long.req.duration_ms']).toBe(42); + }); + }); }); diff --git a/packages/core/test/turbomodule/turboModuleAggregator.test.ts b/packages/core/test/turbomodule/turboModuleAggregator.test.ts index b791b8aba5..28251664cc 100644 --- a/packages/core/test/turbomodule/turboModuleAggregator.test.ts +++ b/packages/core/test/turbomodule/turboModuleAggregator.test.ts @@ -1,8 +1,10 @@ import { _resetTurboModuleAggregator, + addTurboModuleRecordObserver, drainTurboModuleAggregate, hasTurboModuleAggregateData, recordTurboModuleCall, + removeTurboModuleRecordObserver, setAggregateRecordingEnabled, setIgnoredTurboModules, setOnFirstTurboModuleRecord, @@ -77,6 +79,36 @@ describe('turboModuleAggregator', () => { expect(cb).toHaveBeenCalledTimes(2); }); + it('notifies per-record observers with the same set of records that reach the aggregate', () => { + const observer = jest.fn(); + addTurboModuleRecordObserver(observer); + + recordTurboModuleCall({ name: 'A', method: 'x', kind: 'sync', durationMs: 3, errored: false }); + setIgnoredTurboModules(['B']); + recordTurboModuleCall({ name: 'B', method: 'x', kind: 'sync', durationMs: 3, errored: false }); + recordTurboModuleCall({ name: 'A', method: 'y', kind: 'async', durationMs: 42, errored: true }); + + expect(observer).toHaveBeenCalledTimes(2); + expect(observer).toHaveBeenNthCalledWith(1, { + name: 'A', + method: 'x', + kind: 'sync', + durationMs: 3, + errored: false, + }); + expect(observer).toHaveBeenNthCalledWith(2, { + name: 'A', + method: 'y', + kind: 'async', + durationMs: 42, + errored: true, + }); + + removeTurboModuleRecordObserver(observer); + recordTurboModuleCall({ name: 'A', method: 'x', kind: 'sync', durationMs: 1, errored: false }); + expect(observer).toHaveBeenCalledTimes(2); + }); + it('drops all calls while recording is disabled and clears any existing entries', () => { // Populate the map first, then disable — the disable path must also // evict the existing entries so a subsequent enable/disable cycle