Skip to content

Commit 0201779

Browse files
Lms24claude
andauthored
fix(core): Correct sleep clock drift on telemetry timestamps (#23054)
This PR fixes* clock drift that occurs when devices go to sleep. After devices sleep for a few seconds, the browser's monotonic clock (accessed via `performance.now()`) stops counting. Once the sleep stops, the monotonic clock resumes right where it left off before the sleep, causing significant discrepancies between the actual time (wall clock) and the browser's monotonic clock time. Or in other words, there are two ways to get an absolute timestamp: - Using the monotonic clock via `peformance.timeOrigin + performance.now()` - has high, sub-millisecond precision and a guarantee that there are no time jumps or adjustments. But suffers from the sleep problem described above - Using the wall clock via `Date.now()` - lower millisecond precision, is known to be corrected (NTP or via users) and can even cause back jumps. But no sleep problem. With this fix, we make the following adjustments, to kinda get the best of both worlds: - Every `timestampInSecondsCall` checks the monotonic against the wall clock. If a threshold of difference is enocuntered, it corrects the `timeOrigin` so that we can keep using the precise monotonic clock, but anchor its relative time to a corrected time origin. - On every time origin correction, we remember the previous origin (up to 30 corrections). Needed for performance entries - Makes `browserPerformanceTimeOrigin` a time origin corrected helper function, where you pass in a relative time that comes from monotonic clock relative timestamps and it returns the time origin that was most accurate at that relative time point. - All spans and other telemetry we create from browsers `PerformanceEntry` objects carry relative times which are completely sleep-drift uncorrected. We use `browserPerformanceTimeOrigin` to return a corrected time stamp so that we can create an absolute timestamp and bring the performance entries to their respective actual time. ### FAQ If you think this sounds complicated, I agree. So let me answer the most obvious questions, because I asked myself these a lot, too: **Why not just always use `Date.now()` and avoid the complicated click drift detection and correction logic?** The main issue with this is that we still need to rely on relative monotonic clock timestamps for performance entries. We cannot correct them just with `Date.now()` alone but we still need to anchor them. So either we rely on the original `window.timeOrigin` and therefore have all performance entry telemetry happen much "earlier" than its surrounding telemetry relying on `Date.now()`, or we keep the time origin correction logic. But even in the second case (where we already pay the tax for drift detection and correction), telemetry would still have two different anchors: `Date.now()` for regular telemetry and the corrected time origin + monotonic time for performance entry telemetry. Another reason is that the monotonic clock gives us sun-millisecond precision while the wall clock stops at a millisecond resolution. **Why the reduction from a drift detection threshold of 5 minutes to just one second?** Because we keep everything centered around detection and origin offset correction, these timestamps need to be as accurate as possible. On phones, short frequent sleeps are very likely to happen. A lot of sleeps can accumulate until that 5 minutes threshold is reached. So it's really important we make these timestamps as accurate as possible. Fwiw, I reproduced this locally and the drift is already noticeable after just a few seconds of sleep. The 5 minutes threshold was arguably far too big beforehand. **Is there precedence for all of this stuff?** Somewhat, but I'd argue we're doing a bit more: OTel uses a mixture of `Date.now()` and `performance.now`: - Spans start at `Date.now()` and at start time, they record a `performance.now()` timestamp. On span end, they also take `performance.now()`, compute the diff and convert that to an end timestamp based on the start timestamp + diff. This is neat because it guarantees monotony in span durations. I stole this in #24903 In other places, OTel relies purely on Date.now(), and for performance entries, they simply take uncorrected timestamps. So our fix is more complete. \* **So... we're good now?** Well, not perfectly and we never will. With this choice we make another commitment (which we already did previously in less obvious cases) to `Date.now()`. This value can drift as well, just not for sleeps: - NTP adjustments: Can make hard correction of the wall clock, or make the clock tick just a bit faster or slower until the device wall clock synced with the network time. - User adjustments: Users can adjust the device time at any time into any direction. I think we'll have to live with both and I'm not particularly worried about them. My main objective is getting rid of the sleep drift. Fixes #2590 Supersedes #22488, #22585, #23067, #23068 --------- Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
1 parent fcb6cdf commit 0201779

19 files changed

Lines changed: 1015 additions & 326 deletions

File tree

‎packages/browser-utils/src/performance/entries.ts‎

Lines changed: 42 additions & 53 deletions
Original file line numberDiff line numberDiff line change
@@ -2,9 +2,9 @@
22
import type { Span, SpanAttributes } from '@sentry/core';
33
import {
44
BROWSER_NAVIGATION_TIMING_SPAN_NAMES,
5-
browserPerformanceTimeOrigin,
65
getActiveSpan,
76
parseUrl,
7+
_INTERNAL_performanceTimeToSeconds,
88
RESOURCE_SPAN_NAME_FALLBACK,
99
setMeasurement,
1010
spanToJSON,
@@ -108,7 +108,10 @@ export function startTrackingLongTasks(): void {
108108
const { attributes: parentAttributes, start_timestamp: parentStartTimestamp } = spanToJSON(parent);
109109

110110
for (const entry of entries) {
111-
const startTime = msToSec((browserPerformanceTimeOrigin() as number) + entry.startTime);
111+
const startTime = _INTERNAL_performanceTimeToSeconds(entry.startTime);
112+
if (!startTime) {
113+
continue;
114+
}
112115
const duration = msToSec(entry.duration);
113116

114117
if (parentAttributes[SENTRY_OP] === 'navigation' && parentStartTimestamp && startTime < parentStartTimestamp) {
@@ -143,12 +146,11 @@ export function startTrackingLongAnimationFrames(): void {
143146
return;
144147
}
145148
for (const entry of list.getEntries() as PerformanceLongAnimationFrameTiming[]) {
146-
if (!entry.scripts[0]) {
149+
const startTime = _INTERNAL_performanceTimeToSeconds(entry.startTime);
150+
if (!startTime || !entry.scripts[0]) {
147151
continue;
148152
}
149153

150-
const startTime = msToSec((browserPerformanceTimeOrigin() as number) + entry.startTime);
151-
152154
const {
153155
start_timestamp: parentStartTimestamp,
154156
attributes: { [SENTRY_OP]: parentOp },
@@ -209,22 +211,22 @@ interface AddPerformanceEntriesOptions {
209211
/** Add performance related spans to a transaction */
210212
export function addPerformanceEntries(span: Span, options: AddPerformanceEntriesOptions): void {
211213
const performance = getBrowserPerformanceAPI();
212-
const origin = browserPerformanceTimeOrigin();
213-
if (!performance?.getEntries || !origin) {
214+
if (!performance?.getEntries) {
214215
// Gatekeeper if performance API not available
215216
return;
216217
}
217218

218219
const { spanStreamingEnabled, ignoreResourceSpans } = options;
219220

220-
const timeOrigin = msToSec(origin);
221-
222221
const performanceEntries = performance.getEntries();
223222

224223
const { attributes, start_timestamp: transactionStartTime } = spanToJSON(span);
225224

226225
performanceEntries.slice(_performanceCursor).forEach(entry => {
227-
const startTime = msToSec(entry.startTime);
226+
const startTimestamp = _INTERNAL_performanceTimeToSeconds(entry.startTime);
227+
if (!startTimestamp) {
228+
return;
229+
}
228230
const duration = msToSec(
229231
// Inexplicably, Chrome sometimes emits a negative duration. We need to work around this.
230232
// There is a SO post attempting to explain this, but it leaves one with open questions: https://stackoverflow.com/questions/23191918/peformance-getentries-and-negative-duration-display
@@ -233,31 +235,26 @@ export function addPerformanceEntries(span: Span, options: AddPerformanceEntries
233235
Math.max(0, entry.duration),
234236
);
235237

236-
if (
237-
attributes[SENTRY_OP] === 'navigation' &&
238-
transactionStartTime &&
239-
timeOrigin + startTime < transactionStartTime
240-
) {
238+
if (attributes[SENTRY_OP] === 'navigation' && transactionStartTime && startTimestamp < transactionStartTime) {
241239
return;
242240
}
243241

244242
switch (entry.entryType) {
245243
case 'navigation': {
246-
_addNavigationSpans(span, entry as PerformanceNavigationTiming, timeOrigin, spanStreamingEnabled);
244+
_addNavigationSpans(span, entry as PerformanceNavigationTiming, spanStreamingEnabled);
247245
break;
248246
}
249247
case 'paint': {
250-
_addPaintSpan(span, entry, startTime, duration, timeOrigin);
248+
_addPaintSpan(span, entry, startTimestamp, duration);
251249
break;
252250
}
253251
case 'resource': {
254252
_addResourceSpans(
255253
span,
256254
entry as PerformanceResourceTiming,
257255
entry.name,
258-
startTime,
256+
startTimestamp,
259257
duration,
260-
timeOrigin,
261258
ignoreResourceSpans,
262259
spanStreamingEnabled,
263260
);
@@ -276,15 +273,7 @@ export function addPerformanceEntries(span: Span, options: AddPerformanceEntries
276273
* Create a span for a browser paint performance entry.
277274
* Exported only for tests.
278275
*/
279-
export function _addPaintSpan(
280-
span: Span,
281-
entry: PerformanceEntry,
282-
startTime: number,
283-
duration: number,
284-
timeOrigin: number,
285-
): void {
286-
const startTimestamp = timeOrigin + startTime;
287-
276+
export function _addPaintSpan(span: Span, entry: PerformanceEntry, startTimestamp: number, duration: number): void {
288277
startAndEndSpan(span, startTimestamp, startTimestamp + duration, {
289278
// The entry name (`first-paint`, `first-contentful-paint`) is already the low-cardinality name
290279
// the conventions ask for, so only the attribute backing it has to be added.
@@ -304,19 +293,27 @@ export function _addPaintSpan(
304293
export function _addNavigationSpans(
305294
span: Span,
306295
entry: PerformanceNavigationTiming,
307-
timeOrigin: number,
308296
spanStreamingEnabled?: boolean,
309297
): void {
310-
_addPerformanceNavigationTiming(span, entry, 'unloadEvent', timeOrigin, spanStreamingEnabled);
311-
_addPerformanceNavigationTiming(span, entry, 'redirect', timeOrigin, spanStreamingEnabled);
312-
_addPerformanceNavigationTiming(span, entry, 'domContentLoadedEvent', timeOrigin, spanStreamingEnabled);
313-
_addPerformanceNavigationTiming(span, entry, 'loadEvent', timeOrigin, spanStreamingEnabled);
314-
_addPerformanceNavigationTiming(span, entry, 'connect', timeOrigin, spanStreamingEnabled);
315-
_addPerformanceNavigationTiming(span, entry, 'secureConnection', timeOrigin, spanStreamingEnabled);
316-
_addPerformanceNavigationTiming(span, entry, 'fetch', timeOrigin, spanStreamingEnabled);
317-
_addPerformanceNavigationTiming(span, entry, 'domainLookup', timeOrigin, spanStreamingEnabled);
318-
319-
_addRequest(span, entry, timeOrigin, spanStreamingEnabled);
298+
_addPerformanceNavigationTiming(span, entry, 'unloadEvent', spanStreamingEnabled);
299+
_addPerformanceNavigationTiming(span, entry, 'redirect', spanStreamingEnabled);
300+
_addPerformanceNavigationTiming(span, entry, 'domContentLoadedEvent', spanStreamingEnabled);
301+
_addPerformanceNavigationTiming(span, entry, 'loadEvent', spanStreamingEnabled);
302+
_addPerformanceNavigationTiming(span, entry, 'connect', spanStreamingEnabled);
303+
_addPerformanceNavigationTiming(span, entry, 'secureConnection', spanStreamingEnabled);
304+
_addPerformanceNavigationTiming(span, entry, 'fetch', spanStreamingEnabled);
305+
_addPerformanceNavigationTiming(span, entry, 'domainLookup', spanStreamingEnabled);
306+
307+
_addRequest(span, entry, spanStreamingEnabled);
308+
}
309+
310+
/**
311+
* Navigations can happen long after page load, after the time origin was corrected for drift. We use the origin from
312+
* the entry's start for all its timings, so its duration stays correct.
313+
*/
314+
function _navigationTimeToSeconds(entry: PerformanceNavigationTiming, time: number): number {
315+
// The cast is safe: `addPerformanceEntries` only adds navigation spans if the time origin is available.
316+
return _INTERNAL_performanceTimeToSeconds(time, entry.startTime) as number;
320317
}
321318

322319
type StartEventName =
@@ -354,7 +351,6 @@ function _addPerformanceNavigationTiming(
354351
span: Span,
355352
entry: PerformanceNavigationTiming,
356353
event: StartEventName,
357-
timeOrigin: number,
358354
spanStreamingEnabled: boolean | undefined,
359355
): void {
360356
const eventEnd = _getEndPropertyNameForNavigationTiming(event) satisfies keyof PerformanceNavigationTiming;
@@ -364,7 +360,7 @@ function _addPerformanceNavigationTiming(
364360
return;
365361
}
366362
const op = NAVIGATION_TIMING_SPAN_OPS[event];
367-
startAndEndSpan(span, timeOrigin + msToSec(start), timeOrigin + msToSec(end), {
363+
startAndEndSpan(span, _navigationTimeToSeconds(entry, start), _navigationTimeToSeconds(entry, end), {
368364
// With span streaming, span names have to be low cardinality, so we can't fall back to the
369365
// document URL. `url.full` keeps it, and is what Relay derives the description from.
370366
name: spanStreamingEnabled ? BROWSER_NAVIGATION_TIMING_SPAN_NAMES[op] : entry.name,
@@ -388,15 +384,10 @@ function _getEndPropertyNameForNavigationTiming(event: StartEventName): EndEvent
388384
}
389385

390386
/** Create request and response related spans */
391-
function _addRequest(
392-
span: Span,
393-
entry: PerformanceNavigationTiming,
394-
timeOrigin: number,
395-
spanStreamingEnabled: boolean | undefined,
396-
): void {
397-
const requestStartTimestamp = timeOrigin + msToSec(entry.requestStart);
398-
const responseEndTimestamp = timeOrigin + msToSec(entry.responseEnd);
399-
const responseStartTimestamp = timeOrigin + msToSec(entry.responseStart);
387+
function _addRequest(span: Span, entry: PerformanceNavigationTiming, spanStreamingEnabled: boolean | undefined): void {
388+
const requestStartTimestamp = _navigationTimeToSeconds(entry, entry.requestStart);
389+
const responseEndTimestamp = _navigationTimeToSeconds(entry, entry.responseEnd);
390+
const responseStartTimestamp = _navigationTimeToSeconds(entry, entry.responseStart);
400391
if (entry.responseEnd) {
401392
// It is possible that we are collecting these metrics when the page hasn't finished loading yet, for example when the HTML slowly streams in.
402393
// In this case, ie. when the document request hasn't finished yet, `entry.responseEnd` will be 0.
@@ -435,9 +426,8 @@ export function _addResourceSpans(
435426
span: Span,
436427
entry: PerformanceResourceTiming,
437428
resourceUrl: string,
438-
startTime: number,
429+
startTimestamp: number,
439430
duration: number,
440-
timeOrigin: number,
441431
ignoredResourceSpanOps?: Array<string>,
442432
spanStreamingEnabled?: boolean,
443433
): void {
@@ -497,7 +487,6 @@ export function _addResourceSpans(
497487

498488
const attributesWithResourceTiming: SpanAttributes = { ...attributes, ...resourceTimingToSpanAttributes(entry) };
499489

500-
const startTimestamp = timeOrigin + startTime;
501490
const endTimestamp = startTimestamp + duration;
502491

503492
startAndEndSpan(span, startTimestamp, endTimestamp, {

‎packages/browser-utils/src/performance/interactions.ts‎

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -16,13 +16,13 @@ import {
1616
import { UI_ACTION_CLICK, UI_INTERACTION_CLICK } from '@sentry/conventions/op';
1717
import type { Client, IntegrationFn, Span, StartSpanOptions, TransactionSource } from '@sentry/core';
1818
import {
19-
browserPerformanceTimeOrigin,
2019
debug,
2120
defineIntegration,
2221
filterCollectedUrl,
2322
getActiveSpan,
2423
getRootSpan,
2524
hasSpanStreamingEnabled,
25+
_INTERNAL_performanceTimeToSeconds,
2626
spanToJSON,
2727
UI_ACTION_CLICK_SPAN_NAME_FALLBACK,
2828
UI_INTERACTION_CLICK_SPAN_NAME_FALLBACK,
@@ -242,7 +242,10 @@ function trackInteractionsAsSpans(client: Client): void {
242242
}
243243
for (const entry of entries) {
244244
if (entry.name === 'click') {
245-
const startTime = msToSec((browserPerformanceTimeOrigin() as number) + entry.startTime);
245+
const startTime = _INTERNAL_performanceTimeToSeconds(entry.startTime);
246+
if (!startTime) {
247+
continue;
248+
}
246249
const duration = msToSec(entry.duration);
247250

248251
const selector = htmlTreeAsString(entry.target);

‎packages/browser-utils/src/performance/resourceTiming.ts‎

Lines changed: 10 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -1,12 +1,6 @@
11
import type { SpanAttributes } from '@sentry/core';
2-
import { browserPerformanceTimeOrigin } from '@sentry/core';
3-
import { extractNetworkProtocol, getBrowserPerformanceAPI } from './utils';
4-
5-
function getAbsoluteTime(time: number | undefined): number | undefined {
6-
// falsy values should be preserved so that we can later on drop undefined values and
7-
// preserve 0 vals for cross-origin resources without proper `Timing-Allow-Origin` header.
8-
return time ? ((browserPerformanceTimeOrigin() || performance.timeOrigin) + time) / 1000 : time;
9-
}
2+
import { _INTERNAL_performanceTimeToSeconds } from '@sentry/core';
3+
import { extractNetworkProtocol, msToSec } from './utils';
104

115
/**
126
* Converts a PerformanceResourceTiming entry to span data for the resource span. Most importantly,
@@ -28,10 +22,16 @@ export function resourceTimingToSpanAttributes(resourceTiming: PerformanceResour
2822
timingSpanData['network.protocol.name'] = name;
2923
}
3024

31-
if (!(browserPerformanceTimeOrigin() || getBrowserPerformanceAPI()?.timeOrigin)) {
25+
if (_INTERNAL_performanceTimeToSeconds(resourceTiming.startTime) === undefined) {
3226
return timingSpanData;
3327
}
3428

29+
// Use the origin from the request start for all timings, so the durations between them stay correct.
30+
const getAbsoluteTime = (time: number | undefined): number | undefined =>
31+
// falsy values should be preserved so that we can later on drop undefined values and
32+
// preserve 0 vals for cross-origin resources without proper `Timing-Allow-Origin` header.
33+
time ? _INTERNAL_performanceTimeToSeconds(time, resourceTiming.startTime) : time;
34+
3535
return dropUndefinedKeysFromObject({
3636
...timingSpanData,
3737

@@ -58,7 +58,7 @@ export function resourceTimingToSpanAttributes(resourceTiming: PerformanceResour
5858
// This way, TTFB always measures the "first page load" experience.
5959
// see: https://web.dev/articles/ttfb#measure-resource-requests
6060
'http.request.time_to_first_byte':
61-
resourceTiming.responseStart != null ? resourceTiming.responseStart / 1000 : undefined,
61+
resourceTiming.responseStart != null ? msToSec(resourceTiming.responseStart) : undefined,
6262
});
6363
}
6464

0 commit comments

Comments
 (0)