I/O-Lastprobleme durch Logging

Ein Kundenserver machte Ärger. Dass bei einem iowait-Wert von konstant über 90% nicht mehr viel zu wollen ist, dürfte klar sein. Die Maschine ist aber nicht grundsätzlich überlastet: Die Tage davor schnurrte sie noch wie ein Kätzchen.

Mittels iostat war schnell herausgefunden, dass die I/O-Last nicht auf einen Plattendefekt o.ä. zurückzuführen war, sondern wirklich tonnenweise Daten auf die Platten geschrieben wurden.

Leider sind solche Probleme oft schwierig zu analysieren, weil es für I/O-Last im Standard-Linux-Kernel kein Accounting gibt – sprich, man kann nur sehen, auf welchem Blockdevice die Last stattfindet, aber nicht, wer sie verursacht.

Einigermaßen zügig konnten wir „irgendwas mit dem Webserver“ ausmachen, denn wenn der gestoppt war, lief die Maschine wieder ruhig. Also haben wir kurzerhand den server-status-Handler im Apache aktiviert und dazu ExtendedStatus eingeschaltet. Auf diese Weise bekommt man eine schöne Prozessliste der laufenden Requests zu sehen. Und wir hatten Glück: Ziemlich schnell ließ sich eine Site ausmachen, bei der Andreas ein error_log vorfand, das inzwischen rund 42 GB groß war – angesichts der bereits rotierten error_logs, die nur weniger MB groß waren, lag auf der Hand, dass es hier Probleme gibt. Über das error_log fanden wir folgende Zeilen PHP-Code:

...
$handle=fopen($filename,"r");
while(!feof($handle))
...

Das geübte Auge erkennt sofort: Es wird nicht geprüft, ob $filename überhaupt zum Lesen geöffnet werden konnte. Konnte es nämlich nicht, weil die fragliche Datei gar nicht existierte. Wenn es nun aber kein $handle gibt, kann feof() ergo auch niemals am Ende von $handle ankommen – die Schleife läuft somit endlos. Lustigerweise entspricht dieser vorgefundene Code-Abschnitt ziemlich genau dem Negativbeispiel aus der PHP-Doku, und die Kommentare der Seite sind voller Lösungen, wie man sowas richtig programmiert.

Zurück zum Lastproblem. Das entsteht natürlich aus dem Logging, denn für jeden Schleifendurchlauf meckert PHP an, dass man feof() auf etwas ausführt, das kein geöffnetes Filehandle ist. grep sagt uns, dass das etwa 40.000 Mal im error_log steht. Pro Sekunde, wohlgemerkt – kein Wunder, dass das error_log nicht mal den Vormittag über brauchte, um langsam aber sicher die Platte zu füllen und gleichzeitig den kompletten Server auszubremsen. Man kann ja vieles accounten: CPU-Zeit, RAM, Prozessanzahl … aber dummerweise nicht ohne weiteres, wieviel Log-Output ein Script so generieren darf.