Fatale Sekunde

Viele (meiner) Debian-Systeme mit 100% Last durch ksoftirqd hängen geblieben. Exakt um 02:00:00 Uhr (bzw. eigentlich um 01:59:60 Uhr):

[24855453.244162] Clock: inserting leap second 23:59:60 UTC

Wort des Tages:

02:57 < WinstonSmith> ceiling cat is watching your leapseconds crash your servers

Wenigstens ging in der Firma alles gut.

Update: Es ist mir auch jetzt, sechs Stunden nach der fatalen Sekunde, nicht zu 100% möglich nachzuvollziehen, was genau passiert ist. Zunächst einmal scheint es zwei verschiedene Kernel Bugs gegeben zu haben: Der eine wird aktiv, wenn die leap second von ntpd via ntp_adjtime() weitergegeben wird. Dieser Bug kann wohl zu einem Spinlock führen, auch unter RHEL6 - dummerweise wurde der folgende Absatz aus dem Advisory entfernt:

RHEL 6 customers may be affected by a known issue that causes NMI Watchdog to detect a hang when receiving the NTP leapsecond announcement. This issue is being addressed in a timely manner. If your systems received the leapsecond announcement and did not experience this issue, then they are no longer affected.

Dieser Fehler dürfte wohl für die sporadischen Berichte, daß in den 24 Stunden vor der Schaltsekunde besonders viele Server aus unerfindlichen Gründen abgestürzt sind, verantwortlich sein. Das macht Sinn, denn weder ist die Verbreitung des leap second pre-announcements durch die NTP-Hiearchie völlig uniform noch sind die Polling-Intervalle der einzelnen Clients alle gleich. So weit, so gut.

Was dann nach der Schaltsekunde passierte ist wohl einem weiteren Kernel-Bug geschuldet, aber ob es dieser hier ist, weiß ich nicht. Auf jeden Fall waren die ersten paar Minuten nach der Schaltsekunde sehr hektisch. Die häufigsten Probleme, die in diversen IRC-Channeln gemeldet wurden, waren:

  • Die ksoftirqd/X-Prozesse haben plötzlich alle 100% CPU gezogen.
  • Massive Performance-Einbrüche in der AWS-Cloud.
  • Diverse Prozesse, die 100% CPU brauchen. Betroffen waren Java (und damit auch Tomcat, ActiveMQ), Ruby (und damit z.B. auch Puppet, Passenger etc.), aber auch andere Stacks wie z.B. solche, die auf Erlang basieren (und damit dann z.B. auch RabbitMQ).
  • MySQL-Prozesse, die 100% CPU-Zeit verbrauchen<

Ferner gab es vereinzelte Berichte über andere Probleme: So berichteten zwei Chat-Teilnehmer, daß ihnen aus der globale BGP-Tabelle plötzlich ~35k Prefixes fehlen würden. Eine Person gab einen durchaus glaubwürdigen Bericht einer Node Evicition bei einem Oracle-Cluster ab - dies und ähnliche Berichte waren jedoch so selten, daß ich nicht weiß, was ich davon halten soll.

Da bei mir keine einzige Passenger-Instanz betroffen war, habe ich ein bißchen nachgebohrt, und es stelle sich raus, daß die betroffenen Stacks alle JRuby benutzt haben - also wahrscheinlich einfach das Java-Problem “geerbt” haben. Die Last-Probleme in der AWS-Cloud sollten sich auch mit den Amok laufenden Prozessen erklären lassen. Was genau jetzt das Problem war - ob z.B. dieser Bericht hier - vermag ich zum gegenwärtigen Zeitpunkt nicht zu sagen. Ich weiß nur, daß ich froh bin, daß ntpd bei uns mit -x lief und deswegen die Sekunde um 02:00:00 einfach bisserl länger war als normal.

Alle CPU-Last-Probleme konnte man in allen Fällen mit einem einfachen Reboot lösen, später kamen dann Leute auf die Idee, einfach mal die Zeit neu zu setzen (ntpd aus, ntpdate foo, ntpd an) - auch das hat gewirkt und geht natürlich deutlich schneller als ein Reboot. Wenn ich mir das hier so ansehe dann war heute wohl eine dieser Nächte wo die Windows-Admins mal ausnahmsweise mit dem Finger auf uns zeigen können.

Update 2: Lustigerweise scheinen ältere Debian-Kernel ohne Probleme überlebt zu haben, auch wenn ntpd ohne -x lief. Ich sammel ja zentral syslog ein, und da steht:

Jul  1 01:59:59 thrassa kernel: [24855453.244162] Clock: inserting leap second 23:59:60 UTC
Jul  1 01:59:59 www kernel: [17298700.141197] Clock: inserting leap second 23:59:60 UTC
Jul  1 01:59:59 db kernel: [17298542.762483] Clock: inserting leap second 23:59:60 UTC
Jul  1 01:59:59 mail kernel: [17298445.927835] Clock: inserting leap second 23:59:60 UTC

Auf keine der Systeme hatte ich auch nur das kleinste Problem.

Update 3: Mittlerweile geht ein Kernel-Entwickler davon aus, daß der Bug im Kernel auftrat, weil nach dem einfügen der Schaltsekunde die Funktion clock_was_set() nicht aufgerufen wurde. Eine komplette Analyse von Leuten, die wirklich verstehen, was in den letzten 24 Stunden passiert ist, steht immer noch aus.