PHP-FPM-Slow-Logs gruppieren, um zu finden, worauf Ihre Website wartet

«Die Website ist langsam» ist nichts, was jemand beheben kann. «Vier von zehn langsamen Anfragen warten auf einen einzigen externen API-Aufruf» schon. PHP-FPM kann Ihnen den zweiten Satz kostenlos liefern, über ein Log, das auf den meisten Servern abgeschaltet ist. So schalten Sie es ein, lesen es und gruppieren es, damit die Antwort von selbst herausfällt.

Das Problem: langsam, aber wo?

Wenn PHP-Seiten langsam sind, beginnen die meisten Untersuchungen von außen (Werkzeuge zur Seitenzeitmessung) oder bei der Datenbank (Slow Query Log). Beides ist nützlich, und beides übersieht die häufigste Ursache auf modernen Websites: PHP wartet auf etwas, das weder CPU noch die lokale Datenbank ist. Ein Payment-Gateway. Eine Lager- oder ERP-API. Eine Lizenzprüfung. Ein Session-Lock, den eine andere Anfrage desselben Besuchers hält. Diese Wartezeiten erscheinen nicht als CPU, also wirkt der Server untätig, während Besucher auf einen Spinner starren.

Das Slow Log von PHP-FPM fängt sie alle, denn es ist ihm egal, warum eine Anfrage langsam ist. Es macht einfach einen Schnappschuss davon, was die Anfrage gerade tut.

Schalten Sie es ein

In der Pool-Konfiguration (zum Beispiel /etc/php-fpm.d/www.conf):

slowlog = /var/log/php-fpm/www-slow.log
request_slowlog_timeout = 3s
request_terminate_timeout = 60s

Läuft eine Anfrage länger als request_slowlog_timeout, nimmt der FPM-Master einen Backtrace des Workers und schreibt ihn ins Slow Log. Die Anfrage läuft weiter. Nichts wird beendet. request_terminate_timeout ist ein separates Sicherheitsnetz, das außer Kontrolle geratene Anfragen tatsächlich beendet, und es lohnt sich, es bei dieser Gelegenheit zu setzen.

Wählen Sie eine Schwelle knapp über dem, was für Ihre nicht gecachten Seiten «normal» aussieht. Zu niedrig, und Sie protokollieren gesunde Anfragen. Zu hoch, und Sie sehen nur die Katastrophen. Laden Sie FPM neu und lassen Sie es über eine Phase mit Verkehr sammeln.

Lesen Sie einen Eintrag

Ein Eintrag im Slow Log sieht so aus:

[22-Oct-2026 10:14:07]  [pool www] pid 41822
script_filename = /var/www/shop/index.php
[0x00007f1c2a614f20] curl_exec() /var/www/shop/modules/erpsync/Client.php:188
[0x00007f1c2a614e10] request() /var/www/shop/modules/erpsync/Client.php:97
[0x00007f1c2a614d00] getStock() /var/www/shop/modules/erpsync/Stock.php:42
[0x00007f1c2a614bf0] hookDisplayProduct() /var/www/shop/classes/Hook.php:1017
...
[0x00007f1c2a6140a0] dispatch() /var/www/shop/index.php:28

Der oberste Frame, der direkt unter script_filename, ist das, worauf die Anfrage im Moment des Schnappschusses blockiert war. Darunter steht, wie sie dorthin kam. In diesem Beispiel wartet eine Produktseite auf curl_exec(), aufgerufen von einem Modul zur Lagersynchronisation, während der Produktanzeige.

Ein Eintrag ist eine Anekdote. Ein Tag davon ist ein Profil.

Gruppieren Sie nach dem blockierenden Frame

Gruppieren Sie jeden Eintrag nach seinem obersten Frame und zählen Sie:

awk '/^script_filename/ { w = 1; next }
     w && /^\[0x/ {
       fn = $2
       match($0, /[^ ]+:[0-9]+$/)
       print fn " @ " substr($0, RSTART, RLENGTH)
       w = 0
     }' /var/log/php-fpm/www-slow.log \
  | sort | uniq -c | sort -rn | head -25

Die Ausgabe ist eine Rangliste dessen, was langsame Anfragen tatsächlich getan haben. In einem typischen langsamen Onlineshop könnte sie so aussehen:

 812 curl_exec() @ .../modules/erpsync/Client.php:188
 497 execute() @ .../classes/db/DbPDO.php:132
 251 session_start() @ .../config/bootstrap.php:61
  88 file_get_contents() @ .../themes/shop/fonts.php:12

Gruppieren Sie dann auf eine zweite Art, nach dem ersten Frame innerhalb eines Plugin-, Modul- oder Theme-Verzeichnisses. Das macht aus der Liste statt «welche Funktion» ein «wessen Code», und das ist die Frage, die die Entwickler stellen werden.

Was die häufigen Frames bedeuten

• curl_exec(), file_get_contents() auf eine URL, fsockopen(): ein externer Aufruf, der synchron während der Seitenerzeugung erfolgt. Sehen Sie sich das verwendete Timeout an. Ein langes Timeout bei einem langsamen Dritten blockiert einen Worker für genau so lange. Die Lösung ist ein kurzes Timeout, das Cachen der Antwort oder das Verlagern des Aufrufs aus der Seitenanfrage heraus.
• execute(), query(), mysqli_query(): eine Datenbankwartezeit. Nehmen Sie Datei und Zeile mit ins Slow Query Log und führen Sie EXPLAIN für die Abfrage aus, die dort läuft. Antwortet der Buffer Pool aus dem Speicher und die Abfrage braucht trotzdem Sekunden, sind die Abfrage oder ihre Indizes das Problem, nicht die Hardware.
• session_start(): fast immer Session-Locking. Dateibasierte und manche datenbankbasierte Session-Handler sperren die Session für die gesamte Anfrage, sodass bei einem Besucher, dessen Browser mehrere Anfragen gleichzeitig abschickt, diese hintereinander warten. Schließen Sie die Session früh mit session_write_close(), sobald der Code hat, was er braucht, oder verwenden Sie einen nicht blockierenden Handler.
• sleep(), usleep(), Wiederholungsschleifen: jemandes Code wartet absichtlich. Meist ein erneuter Versuch gegen einen externen Dienst, der einen schlechten Tag hat.
• Reine PHP-Funktionen tief in einem Template oder einer Schleife: echte CPU-Arbeit. Seltener, als die meisten erwarten, und die einzige Kategorie, in der schnellere Hardware direkt hilft.

Gewichten Sie es, dann bestätigen Sie den Pool

Das Slow Log zählt Anfragen über der Schwelle. Es sagt Ihnen nicht, wie viel Gesamtzeit jede Kategorie kostet. Kombinieren Sie es mit dem Access Log Ihres Webservers, indem Sie in nginx $request_time und $upstream_response_time protokollieren, um langsame Anfragen nach URL und nach Dauer zu gewichten. Eine Kategorie mit weniger Einträgen, aber weit längeren Anfragen kann mehr zählen.

Prüfen Sie dann, ob die langsamen Anfragen auch den Pool aushungern:

grep -c 'reached pm.max_children' /var/log/php-fpm/error.log
curl -s 'http://localhost/fpm-status?full' | head -20

Sind die Worker erschöpft, warten Besucher selbst auf Seiten, die für sich genommen schnell sind. pm.max_children zu erhöhen behandelt das Symptom. Den langsamen externen Aufruf zu verkürzen behandelt die Ursache.

Ein Wort zum Overhead

Einen Backtrace zu nehmen bedeutet, dass sich der FPM-Master kurz an den Worker hängt. Bei einer vernünftigen Schwelle ist der Overhead vernachlässigbar, weil es nur bei Anfragen passiert, die ohnehin schon langsam sind. Setzen Sie die Schwelle auf einer stark besuchten Website nicht auf einen Sekundenbruchteil und lassen Sie sie dort. Sammeln, analysieren, dann wieder auf ein Monitoring-Niveau anheben.

Ihre Checkliste

• slowlog, request_slowlog_timeout und request_terminate_timeout in jedem Pool gesetzt.
• Ein Tag Slow Log, gruppiert nach blockierendem Frame, dann nach Plugin oder Modul.
• Externe Aufrufe gefunden und ihre Timeouts gelesen.
• Datenbank-Frames zu den Abfragen jener Zeilen zurückverfolgt, mit EXPLAIN.
• session_start()-Einträge auf Session-Locking geprüft.
• Langsame Anfragen nach Dauer aus dem Access Log gewichtet, und Pool-Erschöpfung bestätigt oder ausgeschlossen.

Wenn ein Slow Log irgendwohin zeigt, wohin Sie nicht leicht folgen können, helfen wir gern beim Lesen.

Mit einem Ingenieur sprechen

Related

Verwandt: Performance-Audits für Webanwendungen · PHP-Upgrades und flottenweites Security-Patching · Hochverfügbare Web-Tiers, N+1 auf jeder Ebene