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):
|
|
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:
|
|
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.