Repository navigation
hrTime() falls behind the wall clock after the host sleeps #7217
Description
What happened?
In browsers, performance.now() can stop advancing while the host sleeps (laptop lid closed, OS suspend, some mobile backgrounding). Date.now() keeps running. hrTime() in @opentelemetry/core returns performance.timeOrigin + performance.now(), so after a sleep every timestamp it produces is earlier than the real time by the length of the sleep.
I see this in production browser telemetry: after a sleep, timestamps from long-lived pages arrive minutes to hours in the past. I do not have a minimal reproduction, because it needs a real OS sleep. The mechanism is easy to see in the browser console:
- Open a page and run
setInterval(() => console.log(Date.now() - (performance.timeOrigin + performance.now())), 5000). - Sleep the machine for a few minutes, then wake it.
- In browsers whose monotonic clock pauses during sleep, the logged value jumps by about the length of the sleep.
Why this is still open after #852 and #3434
#852 reported this for spans. #3434 fixed the span path: Span takes its start from Date.now() and stores a per-span offset for performance timestamps.
Callers that use hrTime() directly do not get that fix. In this repository these include:
instrumentation-fetch: span data start time, and the end of the window that matchesPerformanceResourceTimingentriesinstrumentation-xml-http-request: send start time and the same matching windowsdk-metricsMetricReader: collection start and end timesotlp-exporter-baseExporterMetricsinstrumentation-httptimeInputToHrTime()for any number it classifies as a performance timestamp
Instrumentations outside this repository also call hrTime() and timeInputToHrTime().
Proposal
Correct the time origin inside hrTime(), so that every caller gets the same correction:
- On each call, compute
drift = Date.now() - (performance.timeOrigin + performance.now()). - If the new drift differs from the latest stored drift by more than a threshold (1 second in the draft), record
(performance.now(), drift)as the start of a new segment. hrTime()returnsperformance.timeOrigin + latestDrift + performance.now().hrTime(performanceNow)uses the drift of the segment that containsperformanceNow.performance.now()does not advance during the sleep, so a timestamp from before the sleep is earlier than the segment boundary and keeps the drift from before the sleep.
Properties:
- No change when the clocks agree. The first segment has a drift of 0. Until the clocks diverge past the threshold, the output is the same as today, with the same precision and the same monotonic behavior.
- One anchor for live and converted timestamps.
hrTime()andhrTime(performanceNow)use the same segments. This avoids the failure that caused the revert of feat: anchored clock #3134 (Revert #3134 - remove anchored clock #3359): there, live timestamps were anchored but performance-API timestamps were not, so instrumentations that took one from each produced invalid durations. - Small, rare corrections. Between corrections the clock follows
performance.now(), soDate.now()jitter and small NTP slews do not move timestamps. The correction happens only when the divergence is larger than the threshold. Spanbehavior does not change.Span._getTimealready adds its own offset before it callshrTime(inp + offset). The draft changes that line to convert directly, so the offset is not applied twice. Span start still comes fromDate.now(), and Span durations still come fromperformance.now().
Known limitations
- A new segment starts on the first
hrTime()call after the host wakes, not at the wake. A performance timestamp between the wake and that call gets the old drift. I do not know if a browser event fires on wake that the platform could use to check the drift earlier. - If the wall clock steps backward by more than the threshold,
hrTime()steps backward with it.Spanstart times already followDate.now(), so this keeps the two consistent. - Each
hrTime()call also callsDate.now().
Node.js
The change is in common/time.ts, so it also applies to Node.js. I do not know Node.js well enough to say whether it needs this fix. Questions for maintainers:
- Does
performance.now()in Node.js pause during system sleep on the supported platforms? - On servers that never sleep, the correction happens only if the wall clock diverges from the monotonic clock by more than the threshold (an NTP step, or a large slew over a long time). Is that acceptable, or should Node.js keep the current behavior through
#platform?
Open questions
- Threshold. The draft uses 1 second. A smaller value catches shorter sleeps. A larger value lets more wall-clock slew and
Date.now()jitter accumulate before a correction. I do not have data that prefers one value, and I would like maintainer input. - Segment list size. The draft caps the list at 16 segments to bound memory. When the list is full, the oldest segment is dropped, and its timestamps get the drift of the next segment. I do not have data on how many segments a long-lived page creates.
- Exported conversion. Browser SDKs also convert performance entries without
hrTime(). If core exports the segment-aware conversion, they can use the same anchor, and their timestamps agree with OTel after a sleep.
Alternatives
If a correction in common/time.ts for all runtimes is not acceptable, I would also accept either of these:
- Browser only. Put the correction behind
#platform, so Node.js keeps the current behavior. - Flag, do not correct. Keep timestamps as they are today, and add an attribute to telemetry that is recorded when the drift is larger than the threshold, as suggested in Sleeping computer causes span timings to be incorrect in browser #852. Backends can then filter or adjust the data.
Related
#852, #2705, #3279, #3134, #3359, #3355, #3434, #5803, #6816
PR with tests: #7218
Activity