Ein Drama in 7 Akten. Unser zentraler Datenspeicher hält uns auf Trab.

Ende November 2017 erreichten wir einen Meilenstein: Wir haben unseren zentralen Datenspeicher und damit alle Websites unserer Kunden auf superschnelle SSD umgestellt. Die Benchmarks waren fantastisch. Die Kunden überglücklich. Wir auch.

Kurz nach dem Jahreswechsel standen dann ein paar Updates unseres Datenspeichers auf dem Programm. Guter Dinge haben wir also losgelegt. Doch da tauchte wie aus dem Nichts ein Problem auf: Die Performance unseres Datenspeichers war plötzlich im Keller.

Erste Kunden haben sich bei uns gemeldet. Wir waren ahnungslos. Und ziemlich frustriert.

Vor wenigen Tagen (bzw. Nächten) dann die grosse Erlösung: Wir haben das Problem gefunden. Die volle Performance ist zurück. Entsprechend gross die Erleichterung. Doch was war das Problem?

In diesem Blogpost nehmen wir Sie mit auf eine Reise hinter die Kulissen und in die Tiefen eines zentralen Datenspeichers. Und möglicherweise hilft dieser Beitrag irgendwann und irgendwo einem anderen verzweifelten Ceph-Administrator.

Die Ausgangslage: Ein Update steht an

Ein zentraler Datenspeicher besteht aus zwei Komponenten:

1. Der Hardware: Also aus den eigentlichen Festplatten. Diese Festplatten sind in Server eingebaut, was bei uns dann ungefähr so aussieht:
   

2. Der Software, welche die Hardware steuert. In unserem Fall ist das Ceph.

Für Ceph werden regelmässig neue Versionen veröffentlicht, welche Fehler beheben und neue Funktionen bringen. So gehört es also zu den Routineaufgaben eines Ceph-Administators, alle paar Monate ein solches Update einzuspielen.

Am 2. Januar 2018 haben wir mit den vorbereitenden Arbeiten begonnen:

• Wir haben das Betriebssystem aller Ceph-Nodes von RHEL 7.3 auf RHEL 7.4 aktualisiert – damit einher gehen viele Treiber-Updates, ein neuer Kernel etc.

• Selbiges haben wir auf den sogenannten Hypervisors gemacht, also unseren Servern, die wiederum die (virtuellen) Kundenserver beherbergen.

• Zeitgleich wurden die Sicherheitslücken Meltdown und Spectre bekannt und wir haben flottenweit Patches eingespielt.

• Während den Updates wurde uns ein Bug bekannt: Sind HDDs und SSDs in einem Server (in diesem Kontext auch Node genannt) gemischt, können Daten, die aus Gründen der Redundanz zwingend auf verschiedener Hardware abgelegt werden müssten, auf dem gleichen Node gespeichert werden. Fällt ein Node aus (z.B. bei einem Neustart nach einem Kernel-Update), schaltet Ceph die davon betroffenen Daten in den Nur-Lesen-Modus, weil die Konsistenz der Daten nicht mehr gewährleistet werden kann.
  Unseren Kundenservern gefällt das natürlich gar nicht, wenn sie plötzlich nicht mehr Daten schreiben können. Die vorläufige Lösung für das Problem: Von drei Kopien auf vier Kopien erhöhen. So konnten wir sicherstellen, dass immer ausreichend Kopien aller Daten auf unterschiedlicher Hardware gespeichert ist.

• Am 8. Januar dann haben wir mit dem eigentlichen Update der Ceph-Software begonnen. Das Update wird Stück für Stück ausgerollt und tangiert mehrere Stellen: Sowohl die Nodes wie auch die Kundenserver.

Und während all diesen Updates merken wir: Die Performance ist nicht mehr, wie sie sein soll.

Die Performance bricht ein. Was ist nun schuld?

Das Problem: Wir haben in der Vorbereitung mindestens fünf umfangreiche Änderungen in relativ kurzer Zeit vollzogen, was die Fehlersuche entsprechend schwierig gestaltete.

Mit vereinten Kräften, Beihilfe des Herstellers Red Hat und in unzähligen, zusätzlichen Nachtschichten haben wir uns akribisch vorgearbeitet. Dabei galt es nach dem Ausschlussverfahren herauszufinden, an welcher Stelle es genau klemmt. War es das Update des Betriebssystems? Die vierte Kopie? Das eigentliche Update von Ceph? Eine Konfigurationseinstellung in Ceph, die nicht (mehr) ideal ist?

Um jeweils einen Vergleich zu haben, führten wir vor und nach jeder gemachten Änderung Benchmarks durch. So auch am 30. Januar, als ein paar Änderungen an den Kerneleinstellungen vorgenommen wurden.

Zwei anschliessend ausgeführte Benchmarks im Abstand von ungefähr 30 Sekunden zeigten etwas Auffälliges: Die Ergebnisse lagen um Faktor 10 massiv weit auseinander.

Was schwankt hier so?

Das liess aufhorchen: Eine solche Diskrepanz innert so kurzer Zeit und bei etwa gleichzeitiger Auslastung war mehr als auffällig.

Ebenfalls interessant: Auf einigen Festplatten traten sogenannte Slow Requests auf – also Anfragen an die Festplatten, die über 30 Sekunden benötigen, um beantwortet zu werden. Das war jenseits von gut und böse und im Normalbetrieb absolut nicht erklärbar.

Ein Blick auf die Auslastung einer einzelnen Festplatte zeigte während des Auftreten der Slow Requests auch einen plötzlichen Sprung:

Das muss soweit nicht aussergewöhnlich sein: Es ist durchaus denkbar, dass eine Festplatte plötzlich mehr zu tun hat und etwas abarbeiten muss.

Nur: Die Festplatte hatte während dieser Zeit gar nicht mehr Arbeit zu erledigen:

Die Anzahl Schreib- und Leseoperationen der Festplatte war in etwa konstant – ein plötzlicher Anstieg liess sich nirgends erkennen. Wie also konnte die Auslastung der Disk steigen, obwohl die anfallende Arbeit unverändert war?

In der Latenz, also der Reaktionszeit der Festplatte, war der Ausschlag dann wieder deutlich sichtbar:

Ein erstes Muster lässt sich erkennen

Das Spiel ging weiter. Betrachtete man die Auslastung der Festplatte über einen grösseren Zeitraum, zeigte sich dieses Bild:

Was auffiel: Die Sprünge in der Auslastung erfolgten mit verdächtiger Regelmässigkeit. Und das auf allen Festplatten in einem Node gleichzeitig. Dann wurde es ganz verrückt: Die Sprünge in der Auslastung waren nicht nur auf den Festplatten zu sehen, die in den zentralen Datenspeicher integriert sind, sondern auch auf den Festplatten, auf welchen das Betriebssystem der Nodes abgelegt ist und welche mit dem Rest überhaupt nichts am Hut haben.

Die heisse Spur: Ceph ist unschuldig

An dieser Stelle wurde klar: Das Problem hat gar nicht direkt mit Ceph zu tun.

Ein Blick zurück verriet dann auch, ab wann diese seltsamen Lastspitzen auftreten:

Am 15. Dezember. Da war doch unsere Weihnachtsfeier. Und ein Freitag. Auch ein Blick in unser internes Änderungsprotokoll zeigte nichts Verdächtiges:

Dann noch einen Blick in den internen Chat. Die brennende Frage: Was ist am 15. Dezember geschehen? Und da. In der Historie tauchte dieser Code-Schnipsel auf:

Die Puppen tanzen

Wir verwenden für das Management unserer Server das Tool Puppet. Alle 30 Minuten prüft Puppet die Konfiguration eines Servers und rollt ggf. Änderungen aus.

Für Puppet gibt es ein kleines Helferlein namens Facter, dass vor einem sogenannten Puppet-Run Informationen aufbereitet, die dann anschliessend von Puppet genutzt werden können. Solche Informationen können z.B. der verfügbare Arbeitsspeicher oder der verwendete Prozessor sein.

Und das Helferlein lässt sich auch erweitern. So ist es für uns z.B. wichtig, in einem Node die sogenannten Festplatten-IDs zu kennen. Damit können wir beispielsweise das Status-Lämpchen einer bestimmten Festplatte blinken lassen. Ist eine Festplatte defekt und muss ersetzt werden, lassen wir das Lämpchen blinken und der Mitarbeiter vor Ort hat eine zusätzliche Kontrolle, sicher die richtige Disk in den Fingern zu haben.

Jetzt taute es: Am 15. Dezember hatten wir das Tool «Facter» erweitert, damit es für uns fortan auch die Festplatten-IDs einsammelt. Eine winzige und unscheinbare Änderung, möchte man meinen.

Aber jetzt war der Fehler gefunden: Das Auslesen dieser Festplatten-Informationen führte dazu, dass alle Disks fehlerhafterweise für ungefähr 5 Sekunden nicht mehr reagieren. Das Auslesen geschieht über den RAID-Controller und, wie sich herausstellte, ist dieses Fehlverhalten ein Bug des RAID-Controllers. Ein Update der RAID-Controller-Firmware behebt das Problem.

Was also ist genau passiert? Aktuell haben wir 34 Nodes in Betrieb. Wenn alle 30 Minuten Puppet bzw. Facter durchläuft, gerät durchschnittlich etwa alle 53 Sekunden ein einzelner Node für etwa 5 Sekunden ins Stocken.

Das gibt dann über den ganzen Datenspeicher gesehen (und Daten werden immer über den ganzen Datenspeicher verteilt) ca. 48 Sekunden Normalbetrieb, dann wieder 5 Sekunden stockender Betrieb und so weiter. Womit auch die unterschiedlichen Benchmark-Ergebnisse erklärt wären.

Die grosse Erlösung

Flink wurde also das Einsammeln der Disk-Informationen vorläufig abgeschaltet und voilà: Ein Blick auf einen Server zeigte Folgendes:

Die Kurve ist wieder, wie sie sein soll: flach.
Man sieht hier den sogenannten I/O-Wait, also die Zeit, welche ein Prozess auf dem Server auf Antwort des zentralen Datenspeichers warten muss.

Die Erleichterung ist riesig!

Besonders gemein an der Sache war, dass die Performance-Einbussen schon seit dem 15. Dezember bestanden hatten, in diesen Tagen aber niemandem etwas aufgefallen ist. Schliesslich war ja auch Weihnachten und generell herrschte weniger Betrieb als sonst.

Somit haben wir die Quelle des Übels am völlig falschen Ort vermutet: In den Änderungen, die ab dem 2. Januar durchgeführt wurden.

Inzwischen sind wir enorm erleichtert und glücklich darüber, das Problem gefunden zu haben. Wir gehen mit einem grossen Zuwachs an Erfahrung aus dieser nervenaufreibenden Zeit hervor.

Und natürlich tut es uns leid, dass die Performance-Probleme gerade bei datenbankintensiven Operationen auch auf Kundenseite zu spüren waren. Dafür und für die entstandenen Unannehmlichkeiten möchten wir uns bei Ihnen in aller Form entschuldigen.