Skip to content

Commit 45df559

Browse files
antonisclaude
andauthored
fix(tracing): Fix native frames measurements dropped for idle transactions (#5813)
* fix(tracing): Fix native frames measurements dropped for idle transactions --------- Co-authored-by: Claude Opus 4.6 <noreply@anthropic.com>
1 parent 2b68628 commit 45df559

File tree

3 files changed

+176
-19
lines changed

3 files changed

+176
-19
lines changed

CHANGELOG.md

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,10 @@
1212

1313
- Support `SENTRY_ENVIRONMENT` in bare React Native builds ([#5823](https://github.com/getsentry/sentry-react-native/pull/5823))
1414

15+
### Fixes
16+
17+
- Fix native frames measurements being dropped due to race condition ([#5813](https://github.com/getsentry/sentry-react-native/pull/5813))
18+
1519
## 8.4.0
1620

1721
### Fixes

packages/core/src/js/tracing/integrations/nativeFrames.ts

Lines changed: 34 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
import type { Client, Event, Integration, Measurements, MeasurementUnit, Span } from '@sentry/core';
2-
import { debug, timestampInSeconds } from '@sentry/core';
2+
import { debug, getRootSpan, spanToJSON, timestampInSeconds } from '@sentry/core';
33
import type { NativeFramesResponse } from '../../NativeRNSentry';
44
import { AsyncExpiringMap } from '../../utils/AsyncExpiringMap';
55
import { isRootSpan } from '../../utils/span';
@@ -58,8 +58,11 @@ export const createNativeFramesIntegrations = (enable: boolean | undefined): Int
5858
* and frame data (frames.total, frames.slow, frames.frozen) onto all spans.
5959
*/
6060
export const nativeFramesIntegration = (): Integration => {
61-
/** The native frames at the finish time of the most recent span. */
62-
let _lastChildSpanEndFrames: NativeFramesResponseWithTimestamp | null = null;
61+
/** The native frames at the finish time of the most recent child span, keyed by root span ID.
62+
* Stores promises so the data is available for processEvent to await even before
63+
* the async native bridge call completes. */
64+
const _lastChildSpanEndFramesByRootSpan: AsyncExpiringMap<string, NativeFramesResponseWithTimestamp | null> =
65+
new AsyncExpiringMap({ ttl: START_FRAMES_TIMEOUT_MS });
6366
const _spanToNativeFramesAtStartMap: AsyncExpiringMap<string, NativeFramesResponse | null> = new AsyncExpiringMap({
6467
ttl: START_FRAMES_TIMEOUT_MS,
6568
});
@@ -109,7 +112,6 @@ export const nativeFramesIntegration = (): Integration => {
109112
* produce incorrect deltas. The native bridge calls are async and non-blocking.
110113
*/
111114
const fetchEndFramesForSpan = async (span: Span): Promise<void> => {
112-
const timestamp = timestampInSeconds();
113115
const spanId = span.spanContext().spanId;
114116
const hasStartFrames = _spanToNativeFramesAtStartMap.has(spanId);
115117

@@ -118,8 +120,28 @@ export const nativeFramesIntegration = (): Integration => {
118120
return;
119121
}
120122

123+
// For child spans: immediately store a promise for fallback end frames before any awaits,
124+
// so processEvent can find and await it even if this async function hasn't completed yet.
125+
// Uses the actual span timestamp (not wall-clock time) so it matches the trimmed event.timestamp
126+
// for idle transactions. Scoped per root span to avoid concurrent transaction interference.
127+
let childEndFramesPromise: Promise<NativeFramesResponse> | undefined;
128+
if (!isRootSpan(span)) {
129+
const rootSpanId = getRootSpan(span).spanContext().spanId;
130+
const spanTimestamp = spanToJSON(span).timestamp;
131+
if (spanTimestamp) {
132+
childEndFramesPromise = fetchNativeFrames();
133+
_lastChildSpanEndFramesByRootSpan.set(
134+
rootSpanId,
135+
childEndFramesPromise
136+
.then(frames => ({ timestamp: spanTimestamp, nativeFrames: frames }))
137+
.then(undefined, () => null),
138+
);
139+
}
140+
}
141+
121142
if (isRootSpan(span)) {
122143
// Root spans: Store end frames for transaction measurements (backward compatibility)
144+
const timestamp = timestampInSeconds();
123145
debug.log(`[${INTEGRATION_NAME}] Fetch frames for root span end (${spanId}).`);
124146
_spanToNativeFramesAtEndMap.set(
125147
spanId,
@@ -147,10 +169,10 @@ export const nativeFramesIntegration = (): Integration => {
147169
return;
148170
}
149171

150-
// NOTE: For root spans, this is the second call to fetchNativeFrames() for the same span.
172+
// For child spans, reuse the already-kicked-off promise to avoid a redundant native bridge call.
173+
// For root spans, this is the second call to fetchNativeFrames() for the same span.
151174
// The calls are very close together (microseconds apart), so inconsistency is minimal.
152-
// Future optimization: reuse the first call's promise to avoid redundant native bridge call.
153-
const endFrames = await fetchNativeFrames();
175+
const endFrames = childEndFramesPromise ? await childEndFramesPromise : await fetchNativeFrames();
154176

155177
// Calculate deltas
156178
const totalFrames = endFrames.totalFrames - startFrames.totalFrames;
@@ -166,14 +188,6 @@ export const nativeFramesIntegration = (): Integration => {
166188
`[${INTEGRATION_NAME}] Attached frame data to span ${spanId}: total=${totalFrames}, slow=${slowFrames}, frozen=${frozenFrames}`,
167189
);
168190
}
169-
170-
// Update last child span end frames for root span fallback logic
171-
if (!isRootSpan(span)) {
172-
_lastChildSpanEndFrames = {
173-
timestamp,
174-
nativeFrames: endFrames,
175-
};
176-
}
177191
} catch (error) {
178192
debug.log(`[${INTEGRATION_NAME}] Error while capturing end frames for span ${spanId}.`, error);
179193
}
@@ -202,17 +216,18 @@ export const nativeFramesIntegration = (): Integration => {
202216
}
203217

204218
const endFrames = await _spanToNativeFramesAtEndMap.pop(spanId);
219+
const lastChildFrames = await _lastChildSpanEndFramesByRootSpan.pop(spanId);
205220
let finalEndFrames: NativeFramesResponse | undefined;
206221

207222
if (endFrames && isClose(endFrames.timestamp, event.timestamp)) {
208223
// Must be in the margin of error of the actual transaction finish time (finalEndTimestamp)
209224
debug.log(`[${INTEGRATION_NAME}] Using frames from root span end (spanId, ${spanId}).`);
210225
finalEndFrames = endFrames.nativeFrames;
211-
} else if (_lastChildSpanEndFrames && isClose(_lastChildSpanEndFrames.timestamp, event.timestamp)) {
212-
// Fallback to the last span finish if it is within the margin of error of the actual finish timestamp.
213-
// This should be the case for trimEnd.
226+
} else if (lastChildFrames && isClose(lastChildFrames.timestamp, event.timestamp)) {
227+
// Fallback to the last child span finish if it is within the margin of error of the actual finish timestamp.
228+
// This handles idle transactions where event.timestamp is trimmed to the last child span's end time.
214229
debug.log(`[${INTEGRATION_NAME}] Using native frames from last child span end (spanId, ${spanId}).`);
215-
finalEndFrames = _lastChildSpanEndFrames.nativeFrames;
230+
finalEndFrames = lastChildFrames.nativeFrames;
216231
} else {
217232
debug.warn(
218233
`[${INTEGRATION_NAME}] Frames were collected within larger than margin of error delay for spanId (${spanId}). Dropping the inaccurate values.`,

packages/core/test/tracing/integrations/nativeframes.test.ts

Lines changed: 138 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -332,6 +332,71 @@ describe('NativeFramesInstrumentation', () => {
332332
expect(childSpan!.data).not.toHaveProperty('frames.frozen');
333333
});
334334

335+
it('falls back to last child span end frames when root span end timestamp does not match event timestamp (idle transaction trim)', async () => {
336+
// Simulate idle transaction trimming: an event processor before NativeFrames shifts
337+
// event.timestamp back to the child span's end time. This makes the root span's end frames
338+
// timestamp (captured at idle timeout) no longer match within the 50ms margin of error,
339+
// forcing processEvent to fall back to the child span's end frames.
340+
let childEndTimestamp: number | undefined;
341+
asyncProcessorBeforeNativeFrames = async (event: Event) => {
342+
if (event.timestamp && childEndTimestamp) {
343+
event.timestamp = childEndTimestamp; // Trim to child span end time (simulates idle trimEnd)
344+
}
345+
return event;
346+
};
347+
348+
const rootStartFrames = { totalFrames: 100, slowFrames: 10, frozenFrames: 5 };
349+
const childStartFrames = { totalFrames: 110, slowFrames: 11, frozenFrames: 6 };
350+
const childEndFrames = { totalFrames: 160, slowFrames: 16, frozenFrames: 8 };
351+
const rootEndFrames = { totalFrames: 200, slowFrames: 20, frozenFrames: 10 };
352+
353+
mockFunction(NATIVE.fetchNativeFrames)
354+
.mockResolvedValueOnce(rootStartFrames) // root span start
355+
.mockResolvedValueOnce(childStartFrames) // child span start
356+
.mockResolvedValueOnce(childEndFrames) // child span end (fallback + span attributes)
357+
.mockResolvedValueOnce(rootEndFrames) // root span end (stored in endMap)
358+
.mockResolvedValueOnce(rootEndFrames); // root span end (for span attributes)
359+
360+
await startSpan({ name: 'idle-transaction' }, async () => {
361+
startSpan({ name: 'child-activity' }, () => {
362+
// Child span ends here at current mock time
363+
childEndTimestamp = Date.now() / 1000;
364+
});
365+
await Promise.resolve(); // Flush frame captures
366+
await Promise.resolve();
367+
await Promise.resolve();
368+
369+
// Advance time to simulate idle timeout gap (1 second > 50ms margin)
370+
global.Date.now = jest.fn(() => mockDate.getTime() + 1000);
371+
// Root span ends here at the advanced time
372+
});
373+
374+
await jest.runOnlyPendingTimersAsync();
375+
await client.flush();
376+
377+
// The root span end frames timestamp won't match event.timestamp (off by 1s > 50ms margin),
378+
// so processEvent falls back to the child span end frames.
379+
// measurements = childEndFrames - rootStartFrames
380+
expect(client.event!).toEqual(
381+
expect.objectContaining<Partial<Event>>({
382+
measurements: expect.objectContaining<Measurements>({
383+
frames_total: {
384+
value: 60, // 160 - 100
385+
unit: 'none',
386+
},
387+
frames_slow: {
388+
value: 6, // 16 - 10
389+
unit: 'none',
390+
},
391+
frames_frozen: {
392+
value: 3, // 8 - 5
393+
unit: 'none',
394+
},
395+
}),
396+
}),
397+
);
398+
});
399+
335400
it('attaches frame data to multiple child spans', async () => {
336401
const rootStartFrames = { totalFrames: 100, slowFrames: 10, frozenFrames: 5 };
337402
const child1StartFrames = { totalFrames: 100, slowFrames: 10, frozenFrames: 5 };
@@ -382,4 +447,77 @@ describe('NativeFramesInstrumentation', () => {
382447
}),
383448
);
384449
});
450+
451+
it('does not mix up child end frames between overlapping transactions', async () => {
452+
// During txn-1's event processing, txn-2 starts and its child ends,
453+
// writing to the per-root-span map. txn-1's processEvent should still
454+
// read its own child's end frames, not txn-2's.
455+
let txn1ChildEndTimestamp: number | undefined;
456+
457+
const txn2RootStart = { totalFrames: 900, slowFrames: 90, frozenFrames: 45 };
458+
const txn2ChildStart = { totalFrames: 910, slowFrames: 91, frozenFrames: 46 };
459+
const txn2ChildEnd = { totalFrames: 950, slowFrames: 95, frozenFrames: 48 };
460+
const txn2RootEnd = { totalFrames: 999, slowFrames: 99, frozenFrames: 49 };
461+
462+
asyncProcessorBeforeNativeFrames = async (event: Event) => {
463+
if (event.transaction === 'txn-1' && txn1ChildEndTimestamp) {
464+
event.timestamp = txn1ChildEndTimestamp; // Simulate idle trim
465+
466+
// Start and complete txn-2 during txn-1's event processing.
467+
// With a global variable (old code), txn-2's child end would overwrite txn-1's data.
468+
// Clear scope so txn-2 is a new root span, not a child of txn-1.
469+
getCurrentScope().clear();
470+
await startSpan({ name: 'txn-2' }, async () => {
471+
startSpan({ name: 'txn-2-child' }, () => {});
472+
await Promise.resolve();
473+
await Promise.resolve();
474+
});
475+
}
476+
return event;
477+
};
478+
479+
const txn1RootStart = { totalFrames: 100, slowFrames: 10, frozenFrames: 5 };
480+
const txn1ChildStart = { totalFrames: 110, slowFrames: 11, frozenFrames: 6 };
481+
const txn1ChildEnd = { totalFrames: 160, slowFrames: 16, frozenFrames: 8 };
482+
const txn1RootEnd = { totalFrames: 200, slowFrames: 20, frozenFrames: 10 };
483+
484+
mockFunction(NATIVE.fetchNativeFrames)
485+
.mockResolvedValueOnce(txn1RootStart) // txn-1 root start
486+
.mockResolvedValueOnce(txn1ChildStart) // txn-1 child start
487+
.mockResolvedValueOnce(txn1ChildEnd) // txn-1 child end
488+
.mockResolvedValueOnce(txn1RootEnd) // txn-1 root end (endMap)
489+
.mockResolvedValueOnce(txn1RootEnd) // txn-1 root end (span attributes)
490+
// txn-2 mocks (consumed during txn-1's async processor)
491+
.mockResolvedValueOnce(txn2RootStart) // txn-2 root start
492+
.mockResolvedValueOnce(txn2ChildStart) // txn-2 child start
493+
.mockResolvedValueOnce(txn2ChildEnd) // txn-2 child end
494+
.mockResolvedValueOnce(txn2RootEnd) // txn-2 root end (endMap)
495+
.mockResolvedValueOnce(txn2RootEnd); // txn-2 root end (span attributes)
496+
497+
await startSpan({ name: 'txn-1' }, async () => {
498+
startSpan({ name: 'txn-1-child' }, () => {
499+
txn1ChildEndTimestamp = Date.now() / 1000;
500+
});
501+
await Promise.resolve();
502+
await Promise.resolve();
503+
await Promise.resolve();
504+
// Advance time to simulate idle timeout (root end timestamp won't match child end)
505+
global.Date.now = jest.fn(() => mockDate.getTime() + 1000);
506+
});
507+
508+
await jest.runOnlyPendingTimersAsync();
509+
await client.flush();
510+
511+
// txn-1 should use its own child end frames, not txn-2's
512+
// measurements = txn1ChildEnd - txn1RootStart
513+
const txn1Event = client.eventQueue.find(e => e.transaction === 'txn-1');
514+
expect(txn1Event).toBeDefined();
515+
expect(txn1Event!.measurements).toEqual(
516+
expect.objectContaining<Measurements>({
517+
frames_total: { value: 60, unit: 'none' }, // 160 - 100
518+
frames_slow: { value: 6, unit: 'none' }, // 16 - 10
519+
frames_frozen: { value: 3, unit: 'none' }, // 8 - 5
520+
}),
521+
);
522+
});
385523
});

0 commit comments

Comments
 (0)