Conversation
![cursor[bot]](https://avatars.githubusercontent.com/in/1210556?s=60&v=4){kind=small}
size-limit report 📦
|
|
The two-origin divergence Bugbot flagged is real: Fixed in #23067, stacked on top of this PR, which exposes the corrected origin and switches over the consumers where the divergence persists (INP, replay, and profiling's Keeping it out of this PR so each change stays independently reviewable — this one is limited to how |
|
Confirmed on a real iPhone running React Native 0.86 with One structured log embedded its emission wall time in the message body:
The full structured-log stream was present under the older window with the same displacement, while error events remained wall-clock-correct. This matches the React Native Apple clock change in react-native#55977 and the symptom reported in getsentry/sentry-react-native#6510. We applied the same per-call re-anchoring shape downstream as a version-pinned patch. Package-level regression tests against the real One potentially useful addition to this PR's test suite: the current sleep test starts with an aligned first call and then accumulates drift. Our device also exercised the other entry condition, where |
|
This pull request has gone three weeks without activity. In another week, I will close it. But! If you comment or otherwise update it, I will reset the clock, and if you apply the label |
|
Getting the same issue, has this been closed permanently? |
|
@plgrazon no, this is still WIP but the change is non-trivial. I'm currently completely booked on the new JS major but I hope to get some time to pick this up next week again. |
|
@Lms24 no worries. thank you! |
456dd81 to
ded4f36
Compare
4ced6e1 to
3b14c70
Compare
![sentry[bot]](https://avatars.githubusercontent.com/in/12637?s=60&v=4){kind=small}
d2a74d9 to
a6e009b
Compare
Lms24
changed the title
timestampInSeconds call
JPeer264
left a comment
JPeer264
left a comment
There was a problem hiding this comment.
Quite intense, not entirely sure if I parsed and understood everything to 100%, but from what I've grasped it looks good.
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 that reproduction somewhere online to have a before / after comparison? Or something we have in the future?
| const getAbsoluteTime = (time: number | undefined): number | undefined => | ||
| // falsy values should be preserved so that we can later on drop undefined values and | ||
| // preserve 0 vals for cross-origin resources without proper `Timing-Allow-Origin` header. | ||
| time ? msToSec(timeOrigin + time) : time; |
There was a problem hiding this comment.
q: There is another getAbsoluteTime in ember (https://github.com/getsentry/sentry-javascript/pull/23054/changes#diff-73252b4c01e4f647d51fe02b507126d7af869092c786db502d96a6b3225fc4ecR88), but usesbrowserPerformanceTimeOrigin, like the previous implementation here. Is that on purpose?
There was a problem hiding this comment.
There is another getAbsoluteTime in ember
Sorry, maybe I'm missing something but I don't think there's a getAbsoluteTime in Ember at the moment (?)
There was a problem hiding this comment.
whoops, it looked like it was in ember, but it is in relay-internal: https://github.com/getsentry/sentry-javascript/pull/23054/changes#diff-73252b4c01e4f647d51fe02b507126d7af869092c786db502d96a6b3225fc4ecR88
antonis
left a comment
antonis
left a comment
There was a problem hiding this comment.
LGTM 🚀
I had a look at the changes and also tested that this would make the current React Native workaround obsolete.
logaretm
left a comment
logaretm
left a comment
There was a problem hiding this comment.
LGTM, Just a suggestion and a note.
| // See: https://github.com/getsentry/sentry-javascript/issues/2590 | ||
| // See: https://github.com/mdn/content/issues/4713 | ||
| // See: https://dev.to/noamr/when-a-millisecond-is-not-a-millisecond-3h6 | ||
| if (Math.abs(correctedTimeOrigin + performanceNow - dateNow) > CLOCK_DRIFT_THRESHOLD_MS) { |
There was a problem hiding this comment.
Because this is resolved to an absolute number, it can move the origin backward. A span could end before it starts.
Example (I used Claude to help me visualize this if condition):
- page is loaded at 10:00:00
- the example shows a page that is already open for 60s, but the time is set back 5 seconds at some point
① span.start() ② clock set back 5s ③ span.end()
performance.now() 60s 61s 62s
Date.now() 10:01:00 10:00:56 10:00:57
origin 10:00:00 09:59:55 (corrected) 09:59:55
timestamp 10:01:00 10:00:56 10:00:57
timestamp is: correctedTimeOrigin + performance.now()
duration (with this if condition) = 10:00:57 − 10:01:00 = −3s (real: 2s)
If we update the condition to: dateNow - (correctedTimeOrigin + performanceNow) > CLOCK_DRIFT_THRESHOLD_MS, we have this:
① span.start() ② clock set back 5s ③ span.end()
performance.now() 60s 61s 62s
Date.now() 10:01:00 10:00:56 10:00:57
drift (Date.now() − 0s −5s (no correction) −5s (no correction)
timestamp)
correctedTimeOrigin 10:00:00 10:00:00 10:00:00
timestamp 10:01:00 10:01:01 10:01:02
duration = 10:01:02 − 10:01:00 = 2s (real: 2s)
I think this would also fix what was fixed in #24903
But we should keep the tests.
There was a problem hiding this comment.
Because this is resolved to an absolute number, it can move the origin backward. A span could end before it starts.
With just this PR, that's correct but with #24903 in the stack, we guarantee that span end is calculated via the monotonic clock. That is, as long as span.end() is called without an explicit end timestamp. Which I think is a fair tradeoff.
The reason why this check uses Math.abs is because we want to detect drift in both directions. As you said, the wall clock (Date.now()) can be adjusted backwards as well, so ideally we can take both into account. Unless you see a concrete reason not to correct backwards, I'd leave this as-is. WDYT?
There was a problem hiding this comment.
I added a test though for backwards drift correction (5acd31d), since this wasn't covered before. good flag!
There was a problem hiding this comment.
I think we should correct backward, it's an edge case but the clock could be set back during timesaving-clock-shifts (or however this is called :D)
But with Math.abs here, you would get the wrong value because it's always a positive one (even when we have a backward shift). But I think it's also fine to just make sure we properly test this and maybe I'm missing something and the other PR is good enough for that.
There was a problem hiding this comment.
We only use Math.abs to detect the drift, which should work in both directions. When we then make the correction, (correctedTimeOrigin = dateNow - performanceNow) we also go back since we don't use the absolute value here.
The clock can get set back by NTP (though clankers tell me the case where it actually jumps back a few seconds is rare) and by users manually setting an earlier than actual time on their device. Daylight saving time should be fine since Date.now() returns a UTC timestamp.
I might still be missing something though if you have a concrete case in mind that fails here.
| const dateNow = safeDateNow(); | ||
| export function browserPerformanceTimeOrigin(monotonicTimeInMs = 0): number | undefined { | ||
| // Makes sure `_timeOriginSegments` is set up. | ||
| timestampInSeconds(); |
There was a problem hiding this comment.
Performance-related: Previously, this function used a cached value. This is useful e.g. in profiling because you loop through every sample and call this function.
Now, timestampInSeconds() is called every time, and will execute what createUnixTimestampInSecondsFunc() returns (it only creates it once because of the closure, but now also calls it every time). And this function is quite heavy as it does the drift check and reads different clocks.
We could split up setting up the time origin segments (code below, inserted here) and doing the drift check timestampInSeconds() only when needed?
| timestampInSeconds(); | |
| if (!_cachedTimestampInSecondsFn) { | |
| _cachedTimestampInSecondsFn = createUnixTimestampInSecondsFunc(); | |
| } |
Also feel free to put this in a resuable function, then we would need to do some 🍛-ing in timestampInSeconds():
function timestampInSeconds() {
return getTimestampInSecondsFn()();
}
…red with `timestampInSeconds` re-derives its time origin when it detects clock drift, so a single origin is only valid for part of a page's lifetime. Consumers that convert a `PerformanceEntry`'s monotonic `startTime` to wall clock time have no way to know which one applied to a given entry, and `browserPerformanceTimeOrigin` caches the origin resolved at SDK init and never revisits it. Adds `performanceTimeToSeconds`, which keeps the superseded origins around and picks the one that was in effect when the passed time was measured. Entries reported long after the fact — INP on pagehide, replay entries buffered until flush — therefore stay on the timeline they were recorded on instead of being retroactively shifted by a drift that happened afterwards. The correction boundary is the `performance.now()` value the drift was detected at, which is an upper bound on where it actually happened; that is as close as it can be pinned down without a second clock. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
… own time origin Routes the consumers that convert a monotonic `PerformanceEntry` time long after the entry was recorded through `performanceTimeToSeconds`, so a clock drift correction no longer shifts entries that were timed correctly: - INP and CLS report on pagehide, potentially hours after the interaction or layout shift they describe. LCP keeps the cached origin: it starts *at* the origin by construction, so moving it would detach it from its pageload parent. - Replay buffers raw entries and only converts them on flush, which for a long-running session can be minutes later. - Continuous profiling samples are `performance.timeOrigin`-relative like any other monotonic time. Also drops `adjustForOriginChange` from `convertJSSelfProfileToSampledFormat`. `elapsed_since_start_ns` is a difference between two raw monotonic values, so no origin belongs in it at all - the profile is anchored to the wall clock by the enclosing payload's `timestamp`. The term was harmless only because it evaluated to ~0 whenever the SDK origin matched `performance.timeOrigin`. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…igin `browserPerformanceTimeOrigin` was cached at init, so after a drift correction resource, long task, long animation frame, click and user timing spans landed a whole sleep before the navigation they belong to, and most were dropped by the "started before the navigation" checks. It now takes the monotonic time being converted and returns the origin in effect then, defaulting to the page load. Also: - Soft navigation LCP resolves against the origin at the navigation start. - A correction now applies from the previous check on, so the interaction that wakes the SDK up after a sleep lands on the corrected timeline. - The page load origin survives the segment cap. - Without `performance.timeOrigin`, monotonic times convert against `Date.now() - performance.now()` again instead of producing `NaN`. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
A drift correction applies from the last check at which both clocks agreed, so entries recorded between that check and the device going to sleep land on the wrong side of it. Devices usually hide the page before sleeping and show it again on wake, so checking the clocks on `visibilitychange` pins the correction to the sleep itself rather than to whenever the SDK next takes a timestamp. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
At 5 minutes, any sleep shorter than that left spans, logs and metrics behind the wall clock (and errors) for the rest of the page's life. 15 seconds is still far above `Date.now()` jitter and typical NTP adjustments, so it only catches real drift. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Drift from timer precision or NTP slewing stays well below 1s, so a lower threshold catches more real clock jumps without false resets. Also simplify the comments in the time utils. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
…gment If performance.timeOrigin is already wrong on the first timestamp call, we replace it. Pushing a second segment that also starts at 0 lets the segment cap drop the corrected origin later and keep the wrong one, so late-converted page load times would be off by the initial skew. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The initial load span used the page load time origin. Use the origin that was valid when the measure started instead, like all other performance entries, so a time origin correction in between does not shift it. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
A page needs many sleeps or clock jumps to reach the cap. The list is small, so a higher cap costs little and keeps more late entries correct. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
6f69246 to
60ae687
Compare
…ersion Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
There was a problem hiding this comment.
Cursor Bugbot has reviewed your changes and found 1 potential issue.
❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, enable autofix in the Cursor dashboard.
Reviewed by Cursor Bugbot for commit 5acd31d. Configure here.
| start_timestamp: (pageloadOriginMs + sleepDurationMs + resourceStartTime) / 1000, | ||
| end_timestamp: (pageloadOriginMs + sleepDurationMs + resourceStartTime + 100) / 1000, | ||
| attributes: expect.objectContaining({ | ||
| 'sentry.op': 'resource.script', |
There was a problem hiding this comment.
Test uses hard-coded span attribute
Low Severity
The new addPerformanceEntries test asserts 'sentry.op' as a string literal. Testing conventions require span attribute keys to use the @sentry/conventions constant (SENTRY_OP) so assertions stay aligned with production code. This was flagged because it was mentioned in the review rules file.
Triggered by project rule: PR Review Guidelines for Cursor Bot
Reviewed by Cursor Bugbot for commit 5acd31d. Configure here.
…oSeconds Add an optional entryStartTimeInMs parameter to performanceTimeToSeconds, so all timings of one entry can use the time origin from the entry's start. Use it instead of looking up the origin and converting by hand. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This branch has not been deployed
7 participants
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: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 aboveDate.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:
timestampInSecondsCallchecks the monotonic against the wall clock. If a threshold of difference is enocuntered, it corrects thetimeOriginso that we can keep using the precise monotonic clock, but anchor its relative time to a corrected time origin.browserPerformanceTimeOrigina 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.PerformanceEntryobjects carry relative times which are completely sleep-drift uncorrected. We usebrowserPerformanceTimeOriginto 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 originalwindow.timeOriginand therefore have all performance entry telemetry happen much "earlier" than its surrounding telemetry relying onDate.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()andperformance.now:Date.now()and at start time, they record aperformance.now()timestamp. On span end, they also takeperformance.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 fix(core): Compute span end time fromperformance.now()duration #24903In 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: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