Linux outage 2012: One leap second, and Linux timers started firing a second early

At 23:59:60 UTC on Saturday 30 June 2012, the world’s clocks added a second. Straight afterwards, Linux servers all over the internet went to 100% CPU for no visible reason. The load came from Java programs, MySQL, Hadoop and Cassandra, and on desktops even Firefox and Thunderbird. Reddit, Mozilla and LinkedIn had problems, and in Australia the Amadeus system that Qantas uses for check-in went down, leaving staff to check passengers in by hand. The machines stayed like that until someone reset their clocks or rebooted them.

How the kernel applies a leap second

The Earth does not turn at a perfectly steady rate, and atomic clocks do not care. To keep Coordinated Universal Time (UTC) within a second of the Earth’s rotation, the timekeeping authorities occasionally add a leap second, usually at the end of 30 June or 31 December, so the last minute of the day runs 23:59:58, 23:59:59, 23:59:60, then 00:00:00. The one in June 2012 was the 25th since 1972, and the first since the end of 2008.

Computers mostly can’t represent that second. Unix time counts seconds since 1970 as if every day had exactly 86,400 of them, so there is no number for 23:59:60. The system has to fake it. On Linux, the NTP daemon (ntpd), which keeps the clock in step with time servers, learns that a leap second is coming and tells the kernel through the adjtimex() system call. When the day ends, the kernel’s timekeeping code sets the wall clock back by one second, so 23:59:59 happens twice, and logs a message you may still find in old logs: Clock: inserting leap second 23:59:60 UTC.

Linux keeps more than one clock, and the difference matters here:

CLOCK_REALTIME is wall-clock time. It can be set, stepped by NTP, and moved back a second for a leap.
CLOCK_MONOTONIC only moves forward at a steady rate. The kernel adjusts its offset during a leap so it doesn’t jump.

Timers in the kernel are handled by the hrtimer (high-resolution timer) code. It keeps its own per-CPU record of the offset between the monotonic clock and wall-clock time, so it can quickly turn a wall-clock deadline, such as 00:00:00.5, into a point on the monotonic clock. Whenever wall-clock time is changed, a function called clock_was_set() has to run and update those offsets on every CPU. As long as every change to the clock is followed by that call, all is well.

The last piece is how programs wait. Threads in Java, MySQL and many other programs wait for work using condition variables, which sit on the kernel’s futex (fast userspace mutex) mechanism. A timed wait usually takes an absolute wall-clock deadline: wait until now plus 100 ms, then wake up, check for work, and wait again. By default that deadline is on CLOCK_REALTIME.

The wall clock stepped back a second, but the timer code's copy of the offset did not.Open in topo ↗

What happened

At the end of 30 June the kernel inserted the leap second exactly as designed and set CLOCK_REALTIME back one second. What it did not do was call clock_was_set(). The hrtimer offsets stayed as they were, so from that moment the timer code’s idea of wall-clock time was one second ahead of the real wall clock.

John Stultz, who worked on the kernel’s timekeeping code at IBM, later laid out the consequences. Every timer set for an absolute wall-clock time now expired a second early. Worse, every such timer set for less than a second in the future expired immediately, because as far as the timer code was concerned its deadline had already passed. A thread that asked to sleep until now plus 100 ms returned at once, found no work, asked again, returned at once again, and so on. Multiply that by hundreds of threads in a JVM or a database server and the CPUs fill up. The state lasted until something called clock_was_set() or the machine rebooted.

It showed up at once. At 00:49 UTC a Mozilla engineer filed a bug: servers running Java applications such as Hadoop and Elasticsearch had stopped working, apparently at midnight GMT, exactly when the leap second fell. It was raised to a blocker a minute later. By 02:01 Mozilla was updating kernels and rebooting its HBase clusters.

In Australia, where it was Sunday morning, Amadeus’s Altea system, which handles reservations and check-in for Qantas, Virgin Australia and many other airlines, went down soon after the leap second. At 01:25 UTC Qantas tweeted that global issues with Altea were affecting check-in, and staff checked passengers in by hand. Amadeus later confirmed that the outage was caused by the Linux bug triggered by the leap second and said a workaround had it back within an hour.

At 01:41 UTC Reddit’s status account tweeted that it was having Java and Cassandra problems related to the leap second. LinkedIn, Yelp, Foursquare and StumbleUpon were reported to have been hit too.

The fix that spread that night looked like a joke: set the system clock to the time it already shows, with date -s "$(date)" or equivalent, and the load vanished at once. The workaround was published that evening in a post by Sheeri Cabral on Mozilla’s IT blog and credited in the eventual kernel fix. At 02:55 Mozilla was pushing it to every server through Puppet: stop ntpd, then set the date. By 04:07 Socorro, Mozilla’s crash-reporting system, and most of the Hadoop services were back.

At 09:36 UTC on 1 July, John Stultz posted a first patch to the Linux kernel mailing list. He believed the leap second had been applied without calling clock_was_set(), and noted that the workaround worked precisely because setting the time calls it. Prarit Bhargava of Red Hat, who had been hit by the bug himself, tested it within hours and found it caused warnings and deadlocks: clock_was_set() has to run on every CPU, and that cannot be done from inside the timer interrupt where the leap second is applied. Later that day Stultz had a detailed diagnosis and had reproduced the problem on kernels from 2.6.32 to the 3.5 release candidates.

Why it hit so many at once

Every machine hit the same instant. A software bug usually surfaces machine by machine as traffic or data finds it. A leap second arrives at 23:59:60 UTC on every server running NTP, at the same time, all over the world. There were no healthy machines to fail over to.

The code path almost never ran. Before June 2012 the last leap second had been at the end of 2008. As LWN’s Jonathan Corbet pointed out, that left three and a half years in which the leap second code could break without anyone noticing, and no regular test exercised timers across a leap second.

The missing call had been removed on purpose. In 2007, in Linux 2.6.22, Thomas Gleixner took clock_was_set() out of the leap second code because calling it from there with interrupts disabled could deadlock. His commit message expected the only side effect to be a timer firing a second late, and only if a leap second were ever deleted: never early. Stultz later suspected the problem had been possible since that change.

A thread that waits in a loop for less than a second at a time never actually waits.Open in topo ↗

The symptoms pointed at the wrong layer. The CPU was being burned by Java, MySQL and Cassandra processes, so that is where people looked, and restarting them didn’t help, because the kernel’s timers were still wrong. DataStax’s Jonathan Ellis wrote that early reports blamed Java or Cassandra. Some of the same weekend’s trouble had other causes too: IDG noted that storm-related power outages in Northern Virginia may also have affected Reddit. Some machines hung outright instead of spinning, which Stultz could not reproduce at first, and early press reports pointed at a different leap second livelock that had been fixed in March.

How it was fixed

For a running machine, the fix was to call clock_was_set() by any means: set the date or reboot. Many operators did one or the other, server by server, through the night.

The kernel fix took Stultz, Gleixner and others about ten more days to get right. The final version adds a clock_was_set_delayed() that the timekeeping code calls when it applies a leap second; the actual update runs shortly afterwards in softirq context, where calling every CPU is allowed. A companion change makes the hrtimer interrupt pick up the latest offsets every time it runs, so timers can never be expired early on stale offsets. Gleixner sent the series to Linus Torvalds as the leap second fixes for Linux 3.5 on 13 July, tagged for backporting to stable kernels.

The stress test Stultz wrote while fixing it, leap-a-day, asks the kernel to insert a leap second every day at midnight UTC. It is now part of the kernel’s timer selftests.

The sequel: Cloudflare, 1 January 2017

Leap seconds kept arriving, and the next lesson came from user space. At midnight UTC on New Year’s Day 2017, as the leap second at the end of 2016 was applied, a number went negative inside RRDNS, Cloudflare’s DNS server, written in Go.

When a Cloudflare customer points a name at their origin server with a CNAME record, RRDNS sometimes has to look up the origin’s address through Cloudflare’s own recursive resolvers. It keeps track of how fast each resolver answers, smooths the measurements, and picks a resolver with a weighted random choice. It measured the time with Go’s time.Now(), which at the time read the wall clock and could go backwards; Go had no monotonic time source yet.

Cloudflare’s resolvers normally answer in a few milliseconds. When the wall clock went back a second in the middle of a lookup, the round trip came out at roughly minus one second. The smoothing kept a single bad sample from doing harm, but after a few of them the smoothed value itself went negative. The selection code passed it to rand.Int63n(), which panics if its argument is negative. Go’s recover caught the panics, and the lookups that hit them failed.

A few milliseconds minus the repeated second came out negative, and the random pick panicked on it.Open in topo ↗

The damage was small because it needed a CNAME lookup on an affected machine: at peak about 0.2% of DNS queries to Cloudflare failed, and under 1% of HTTP requests saw an error. The timeline was quick too. Impact started at 00:00, engineers were engaged at 00:10, the cause was confirmed at 00:34, and a fix went to one canary node at 00:55 and a canary data center at 01:03. The most affected data center had it at 01:23, it was rolling out everywhere from 01:48, most affected locations were fixed by 02:50, and the impact ended at 06:45.

The fix was one character. Where the selection code replaced a round-trip time of zero with a default timeout, it now replaced anything zero or below: rttMax == 0 became rttMax <= 0. Cloudflare restarted RRDNS everywhere and went looking for other code that assumed time only moves forward. Go 1.9 later added monotonic readings to time.Now(), so the difference between two times read by the same process no longer goes backwards when the wall clock does.

What I'd take from it

Measure durations on a monotonic clock. Wall-clock time can jump either way. Timeouts, deadlines and elapsed times belong on CLOCK_MONOTONIC (or a monotonic reading, as Go's time.Now has carried since Go 1.9). Keep wall-clock time for timestamps people read.
Clamp every difference between two timestamps. Cloudflare's fix was one character, treating a zero or negative round-trip time as unknown. Any code that turns a time difference into a sleep, a weight or a random range should check it first.
Code that runs once every few years needs a test that runs every day. The leap second path had last run for real at the end of 2008. John Stultz's leap-a-day test, which asks the kernel to insert a leap second every night, now lives in the kernel's selftests; that is the kind of test that catches this.
Smear the leap instead of stepping. Google spreads the extra second over 24 hours, noon to noon UTC, by running its clocks very slightly slow, so no clock ever repeats a second. If every machine you run follows the same smeared time, most software never sees a leap at all.
When a no-op fixes a system, find out what it changed. Setting the clock to the time it already showed stopped the load, because it made the kernel call clock_was_set(). The workaround pointed straight at the cause, and Stultz's first patch reasoned from it.