intermediate 3 min answer

A service's own latency histogram shows a 40-second p99 spike at 03:14 every few weeks, and its logs occasionally record negative request durations. Traces for the same window show every downstream call completing in under 50 ms. Where is the time going?

clocksntpmonotonicinstrumentationdebugging
Show the full answer Hide the answer

The first three signals

  1. The negative durations, which are not a rounding artefact and not possible for elapsed time. They are the whole answer and they are usually ignored because the dashboards clip at zero.
  2. Whether the spike exists downstream. It does not - traces are clean - so the time was never spent anywhere.
  3. The host's clock-adjustment history. ntpq, chronyc tracking or the kernel's time-sync log will show a step, not a slew, near 03:14.

The diagnosis

The service measures duration by subtracting two readings of the wall clock. The wall clock is not a stopwatch: it is a best current estimate of civil time, and it is allowed to jump backwards and forwards. When a time daemon finds the local clock far enough off, it steps the clock instead of slewing it, and every in-flight measurement that straddles the step is wrong by the size of the step - positive in one direction, negative in the other. A single 40-second step produces one 40-second "request" and, going the other way, a batch of negative ones.

The other consequences are worse than the metric: TTL and lease arithmetic computed on the wall clock can expire instantly or not expire at all, and rate limiters that divide by elapsed wall time can divide by zero or by a negative number.

The misleading clue

03:14 looks like a scheduled job, so the investigation goes to cron, batch load and backup windows. The time is simply when the sync daemon decided the offset had grown past its step threshold. A periodic symptom with no periodic cause in your own code is a hint to look at the platform's periodic behaviour, not at yours.

The fix

  • Measure elapsed time with a monotonic clock - CLOCK_MONOTONIC, System.nanoTime, time.monotonic(), Instant.now() only for timestamps. The monotonic clock never steps.
  • Keep the wall clock for things that are compared across machines or shown to people: log timestamps, event times, certificate validity.
  • Know the monotonic clock's own limits. It has no defined epoch, it is not comparable across hosts, and on some platforms it does not advance while the machine is suspended - so a lease held across a suspend-resume is unsafe either way.
  • Alert on the clock itself: offset magnitude and a counter of step adjustments. A host whose offset is growing is a host whose timestamps and leases will be wrong soon.

When the clock really is the outage

The 2012 leap-second insertion is the documented case where the time change itself, not the measurement of it, took hosts down: a Linux kernel defect turned the inserted second into a CPU-saturating loop on a wide range of machines at once. That is why large operators deliberately smear a leap second across hours rather than inserting it, and why "all our hosts get time from the same place" is a correlated-failure statement as much as a consistency one.

When this is the wrong answer

If the negative durations are absent and the spike reproduces in a trace, this is not a clock problem and the above is a distraction - go back to the slow dependency. The clock hypothesis earns its place only when the measurement is impossible, not merely large.