Viele (meiner) Debian-Systeme mit 100% Last durch ksoftirqd hängen geblieben. Exakt um 02:00:00.

Wort des Tages:

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 RHEL 6 - dummerweise wurde der folgende Absatz aus dem Advisory entfernt:

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:

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.