Seit ein paar Monaten nervt mich der Server mit Fehlermeldungen, und ich habe lange nicht heraus bekommen, was los war. Viel zu lange…

Anfangs äußerte sich das so:

• das Überwachungssystem meldete zwischen 05:25 und 05:30 einen Ausfall und ein paar Minuten später die Entwarnung. Das kam nicht täglich, aber oft.
• diffus über den Tag verteilt kamen weitere Ausfallmeldungen.
• und teilweise antwortete der Server extrem langsam (gefühlt jedenfalls - ich bin nicht besonders geduldig).

Erst passierte das nur selten, dann immer öfter - bis zu dem Punkt, dass die Sache um halb sechs täglich kam, und das Überwachungssystem manchmal fünf Mal am Tag Ausfälle meldete.

Wenn das Überwachungssystem "Ausfall" meldet, bedeutet das nicht zwangsweise, dass irgendetwas gar nicht mehr funktioniert, sondern dass irgendetwas entweder gar nicht funktioniert oder extrem langsam antwortet. Nun sind beide Varianten unerwünscht, aber ich vermute, die Benutzer würden lieber eine Zeit lang einen langsamer antwortenden Server haben, während ich komplette Ausfälle vorziehe (die Ursachen dafür sind typischerweise leichter zu finden).

Jedenfalls störte das, und ich hab' auch danach gesucht, und viel gefunden, aber leider nichts, was wirklich Sinn ergeben hätte. Aber Anfang August hatte ich dann ein Problem isoliert.

Aber was heißt isoliert? Es konnte ein Problem in memcached (einem Cache Daemon, den ich nutze, um die Zahl der Datenbankanfragen zu reduzieren) sein - oder eines in der php-library php-memcache, die die Anbindung an memcached liefert. Genauer konnte ich es nicht festmachen, weil das Problem nur selten und wohl auch unter Umständen auftrat, die auf der Testmaschine nicht reproduzieren konnte.

Daher habe ich im Zuge der Wartungsarbeiten am 16.8. memcached aktualisiert, und am 17.8. festgestellt, dass das nicht geholfen hatte. Daraufhin habe ich den in sauren Apfel gebissen, und php-memcache gegen php-memcached ausgetauscht, eine alternative Anbindung an memcached (den Daemon - die Benamungen sind irgendwie ungut) ausgetauscht, und den Code angepasst, weil php-memcache und php-memcached ganz andere Funktionsnamen verwenden (die übrigens beide nicht durchgängig an die Namen der Funktion im memcache-Protokol angelehnt sind).

Das hat geholfen, die Zahl der Ausfallmeldungen ging zurück, nur war sie immer noch nicht 0, wie ich nach meinem Urlaub mit gewissem Missmut feststellen konnte. Insbesondere war diese Sache um halb sechs noch da.

Daraufhin war ich erst mal ratlos, und bin noch ein paar Mal durch alle möglichen Logfiles gegangen, um irgendein klares Bild zu finden. Was fand ich nicht? Genau.

Aber immerhin brachte die Zeit, in der ich nichts gefunden habe, noch mehr Fehlermeldungen, und damit mehr Daten.

Das Problem um halb sechs hatte bis Mittag August noch anders ausgesehen, da waren gerne mal zwei oder drei Ausfallmeldungen innerhalb von 15 Minuten. Jetzt war es nur noch Eine über 3 oder 6 Minuten.

Die anderen Ausfälle wurden gar nicht mehr gemeldet - was aber nicht heißt, dass es kein Problem gab, sondern dass nur keines gemeldet wurde, denn eindeutig verhielt sich das Forum zwischenzeitlich so, als wäre es ausgelastet, aber laut den Logfiles des Webservers war das nicht der Fall. Aber leider hatte ich das Pech, nie im richtigen Moment auf der Maschine zu sein um nachsehen zu können, was genau passierte.

Nie? Nein, gestern war ich drauf, rein zufällig, da ich gerade etwas in der Firma testen wollte, aber weil der Test von einer externen Maschine angestoßen werden sollte, bin ich kurz auf den Forumsserver gegangen und habe da mein Testscript angeworfen. Und während es lief, habe ich dann nachgesehen, wie viele Netzwerkverbindungen es offen hatte (es ist immer schön, wenn einem das eigene Script sagte, es habe 10 Verbindungen gleichzeitig offen, aber noch besser ist, wenn das Betriebssystem das auch bestätigt).

Und dabei habe ich dann knapp 1000 offene Verbindungen von den 8 oder 10 laufenden PHP-Prozessen zum memcached gesehen.

Das war dann einer dieser "Bitte was?"-Momente. "Was zum Teufel ist hier los? Sag' mir bitte jemand, dass das nicht wahr ist." Das darf nicht sein, und das *kann* nicht sein.

Ich meine das so: *Kann* nicht sein.

Kleiner Ausflug:

Deshalb, und weil es 0,2 Millisekunden beim Verbindungsaufbau spart, und weil ich es nicht sonderlich mag, wenn netstat mir hunderte Verbindungen im "time wait"-Zustand zeigt (das nervt und ist fürchterlich unübersichtlich - aber rausfiltern will ich sie auch nicht, weil die auch auf Probleme hinweisen), habe ich php-memcached (und vorher php-memcache) dahin konfiguriert, sogenannte persistente Verbindungen zu machen: Da wird also nicht für jede Seitenerzeugung, die 0,1 Sekunde dauert eine neue Verbindung aufgemacht und hinterher geschlossen (und gammelt dann vier Minuten oder so im "time wait"-Zustand herum), sondern jeder laufende PHP-Prozess benutzt dieselbe offene Verbindung über die 2000 Anfragen, die er bearbeitet, bevor er durch den Nächsten ersetzt wird.

Nun, was soll ich sagen? Es waren kaum Verbindungen nach memcached im "time wait"-Zustand. So weit, so gut. Es waren aber 993 Verbindungen "established". So weit, so… ein, schlecht. Ganz schlecht.

Neugierig geworden habe ich mir dann angesehen, was eigentlich passierte (ich liebe strace): Ein PHP-Prozess bekam eine Anfrage, machte eine neue Verbindung zu memcached auf, und memcached nahm die nicht an. Nach 5 Sekunden oder so hat der PHP-Prozess das dann festgestellt, und nach ein paar weiteren Versuchen den Rest der Anfrage eben ohne memcache absolvert (das ist langsamer, geht aber).

Irgendwann beendete sich dann einer der PHP-Prozesse, worauf dann ein paar hundert Verbindungen zu memcached wieder frei wurden, und für die nächste Zeit alles wieder so lief wie es sollte. Ich vermute, dass die PHP-Prozesse nicht für *jede* Anfrage eine neue Verbindung aufgemacht haben, oder dass sie zwischendurch doch mal Verbindungen schlossen, aber ich hatte gestern weder Zeit noch Lust, mir das noch näher an zu sehen (Hinweis: ich hatte noch zu arbeiten). Daher hab' ich nur kurz die persistenten Verbindungen abgeschaltet, und lebe jetzt mit mehr als 200 Verbindungen der Marke "time wait" statt mit 1000 "established".

Nun ist es zu früh zu sagen, ob nicht noch andere Probleme da sind, die das Forum langsam machen, aber ich denke, das war es.

Randnotizen über Dinge, die die Sache so richtig lustig gemacht haben (lustig für Leute, die Schmerzen lieben):

• der memcache-Daemon schreibt zwar Meldungen in sein Logfile, wenn die Maximalzahl der Verbindungen erreicht ist, tut das aber definitiv nicht immer. Mal abgesehen davon, dass jede Uhrzeitangabe fehlt, was das Logfile für die Lösung der Frage, was denn um 18:15 passiert ist, eher unbrauchbar macht.
• PHP/FPM schreibt zwar dann und wann mal darüber etwas das ein Logfile, was helfen könnte, aber die entscheidende Information steht in einem anderen Logfile.
• und in das schreibt es dann hinein, dass irgendwelche Anfragen zu lange gedauert haben. Leider steht in ungefähr 93% der Fälle am Ende "dump failed", was de facto bedeutet, dass der Eintrag im Logfile noch wertloser ist als sonst, und in den anderen 7% der Fälle steht leider nicht drin, was für eine Art von Anfrage das Ding gerade beantwortet hat (das kann man manchmal aber aus dem dump entnehmen. "Manchmal". Logfiles, die *manchmal* helfen, sind meistens wertlos).
• php-memcached bietet übrigens überhaupt keine Hilfe bei der Suche.
• Wie dieses "dump failed" zustande kommt, möchte ich mal wissen. Oder vieleicht doch nicht? Aus der Anwendung heraus habe ich überhaupt keine Probleme, einen solchen Dump zu erzeugen - warum kann PHP das dann selbst nicht?

Seufz. Ich hasse Computer.

Aber damit nicht genug, das "halb sechs"-Problem war ja noch übrig. Ich hätte es nicht beweisen können, aber für mich sah es die ganze Zeit so aus, als wäre das etwas Anderes. Und es war.

Heute morgen gab die übliche Meldung über einen Ausfall (05:29 bis 05:35), und außerdem Panikmeldungen des Forums, dass die Tophit-Berechnung um 05:23 und 05:28 fehlgeschlagen war (die sind eigentlich verzichtbar, aber interessant war die genaue Fehlermeldung: In beiden Fällen lief gleichzeitig noch eine zweite Tophit-Berechnung, was nur passieren kann, wenn die Kiste völlig überlastet ist). Nun passiert so etwas etwa alle zwei Monate mal, nicht öfter - und schon gar nicht binnen 5 Minuten wieder.

Und weil ich gerade nichts besseres zu tun hatte (außer Bilder bearbeiten, die Beta der Homepage fertig machen, den Reisebericht vom Urlaub fertig machen, den nächsten Urlaub planen, mir Gedanken um den Ersatz des nicht mehr vorhandenen Handys zu machen, lrzsz 0.2 weiter machen, herausfinden warum das Onlinebanking meistens keine Umsätze liefert (aber manchmal schon), oder auch darüber nachdenken, wann ich die nächsten Urlaubstage nehme. Oder die Zeitrafferaufnahmen von Helgoland zu Videos machen, oder, apropos Video, herausfinden unter welchen Umständen welcher Konverter warum crasht. (halt, nein, *warum* nicht. Die Chance, dass mir die Mittagessen der vergangenen sechs Monate hoch kommen, wenn ich die Interna von avconv betrachte, ist einfach zu groß)), hab' ich noch mal in die Logfiles geguckt.

Und da fand ich zum ersten Mal ein klares Bild in den Logfiles, und konnte erkennen, dass da gegen 04:30 (Pi mal Daumen - das sa-System protokolliert nur alle 10 Minuten) ein langer Job begann, der viel, viel Plattenbandbreite und CPU brauchte (vermutlich das Backup), und offenbar bis ungefähr um 6 lief.
Komisch, hätte ich das nicht gestern oder auch früher bereits erkennen sollen? Ich meine, zumindest die Sache mit der Plattenbandbreite? Hätte ich, keine Frage. Aber ich war wohl zu sehr auf die memcache-Sache fixiert, und hab' mich in die Irre führen lassen.

So gegen 05:35 hatte es mal so rund 30000 "dirty pages" (Sache, die noch auf die Platte geschrieben werden müssen), 10 mal mehr als zu jedem anderen Zeitpunkt.
Ab 05:15 idlenten die CPUs nicht mehr bei 800 Megahertz herum, sondern waren größtenteils auf 3500 - und um 05:35 waren sie alle bei 3500.
Die CPU-Temperatur stiegt auch massiv an (sieht man sonst im Tagesverlauf nie).

Jetzt gibt es zwei Möglichkeiten: Irgendein anderer Job läuft so gegen 05:15 oder 05:25 an (oder erreicht eine kritische Phase, wo er viel, viel Kapazität braucht), oder der Backupjob kommt um die Zeit in eine kritische Phase. Seufz. Wie bekommt man denn das raus?
Na gut, das war einfach - ich schaute in mein eigenes Backup-Logfile (warum habe ich das? Keine Ahnung, aber jetzt war es nützlich) und mal kurz auf den Backup-Server zwecks Gegencheck der Zeitstempel.
Und sah, dass heute um 05:28 das Backup der Postgres-Datenbank angelaufen ist, und bis etwa 05:47 lief.

Jetzt wüßte ich schon noch gerne, warum die Störung nicht bis 05:47 ging… Ich meine, es ist gut dass nicht, aber trotzdem verstehe ich nicht ganz. Und langsam würde ich schon ganz gerne verstehen, was vor sich geht.

Aber dringender ist eine andere Frage: Was mache ich dagegen?

1. "nice" auf das Datenbankbackup anwenden? Das wird am Resourcenhunger wohl nicht viel ändern, aber der Versuch kostet immerhin nichts (außer das Backup u.U. langsamer zu machen).

2. Den Backup-Job auf 03:10 statt 04:20 legen, und postgres nach weit vorne, damit der zu einer möglichst unkritischen Zeit läuft? Das ist nett für die Benutzer, die um die Zeit eher weniger aktiv sind, aber ich bekomme vermutlich trotzdem Fehlermeldungen…
   
   Oh, und für einen Admin wäre es eventuell eher schädlich… Seufz.

3. Oder soll ich in den sauren Apfel beißen, und die Datenbank auf eine andere Kiste replizieren (die Testkiste reicht dafür), und von da aus das externe Datenbankbackup machen?
   
   Aber das setzt voraus, dass ich auf beiden Kisten dieselbe "major version" von Postgres habe, und zwingt mich dann dazu, beim nächsten größeren Systemupdate *beide* Maschinen anzufassen, was ich eigentlich so gar nicht will. Ich würde größere Systemupdates gerne an einem Morgen erledigen können, statt einen ganzen Tga reservieren zu dürfen.
   
   Und natürlich wäre es auch ganz nett, wenn die Testkiste, die im Moment sowieso ziemlich dicht ist, benutzbar bliebe…

4. Noch einen Server für diesen Mist bereit stellen? Wo war noch die Gelddruckmaschine?
   

Seufz. Ich hasse Computer.