I recently ran into an interesting quirk when using Performance.now() to measure long-ish intervals in Quip's web app. Since it does not seem to be broadly known, I thought I would document it.

To mitigate the possibility of self-induced DDoS attacks, I recently added duplicate request detection to Quip's model layer data loading mechanism. Since we pretty aggressively cache loaded data, repeated requests for the same objects would indicate that something is going wrong. I therefore added a client-side check for the exact same request being issued within 60 seconds of the first occurrence. If it triggered, it would send a diagnostic report to our error tracking system.

This turned up some legitimate bugs (e.g. two independent code paths racing to trigger loads) as well as some false positives (e.g. retries of requests that failed should be allowed). After pushing the fixes and tweaks to the detection system, I was left with a few puzzling reports. The report claimed that a duplicate request had occurred within a very short interval, but based on other events it looked like the requests had been several minutes (or even hours) apart.

When I looked at the reports more carefully, I saw that the long time interval was always bracketed by a disconnect and reconnect of the Web Socket that we use for sending real-time updates. I hypothesized that this may have been a laptop whose lid was closed and later re-opened. Taking a look at how I measured elapsed time between requests, I saw that this was computing the delta between to high-resolution timestamps returned by Performance.now(). I was then able to reproduce this scenario locally by comparing wall-clock elapsed time with high resolution elapsed time while my computer was asleep (to see it in action, see this simple test bed). I initially did this in Chrome, but Safari and Firefox seem to have the same behavior.

The fix was switch to using Date.now(), which otherwise worked equally well for this use-case. We didn't actually need the high-resolution guarantees of Performance.now() — the reason why it was used in the first place is because the code already had a timestamp with it in place that was used for measuring load request-to-response time. The same code runs in on our desktop app (where load times can be sub-millisecond) and so the high resolution was needed for that use case.

I am definitely not the first to run into this; I have found a few off-hand mentions of this behavior. For example, see this Stack Overflow comment and this post on elm-dev. Curiously, neither the currently published version of the time specification nor the latest draft seem to indicate that this may be a possibility. Per the spec, Peformance.now() is supposed to return the difference between the time of the call and the time origin, and presumably the origin is fixed.

As to the specifics of why this happens, I spelunked through Chrome's codebase a bit. The Performance.now implementation calls monotonicallyIncreasingTime which uses base::TimeTicks::Now which uses the CLOCK_MONOTONIC POSIX clock. I wasn't able to find any specific gotchas about macOS's implementation of that clock, but Apple does have a tech note that says that “timers are not accurate across a sleep and wake cycle of the hardware” so this is not a surprise at that low level. Within the Chrome project it is also known that base::TimeTicks is unreliable across sleep intervals. Though it's common to think of the browser environment as being very high level and abstracted away from the hardware and operating system, small nuances such as this one do sometimes leak through.