Das Problem
Ich verwende PHP-FPM 7.4.30 unter Apache 2.4 auf RHEL 8 und schaffe es nicht, PHPs Slowlog richtig zum Laufen zu bringen. Es gibt keine gültigen Informationen über Skripte mit langer Laufzeit zurück.
Wenn ich das Slowlog aktiviere – selbst mit einem hohen Wert von request_slowlog_timeoutetwa 10 Sekunden oder mehr – sehe ich viele Einträge im Protokoll, darunter auch Skripte, von denen ich weiß, dass sie nicht lange laufen. Die Liste erscheint zufällig und zeigt Backtraces für eine Vielzahl von Skripten und darin enthaltenen Funktionen. Es gibt kein offensichtliches Muster. Ich bin sicher, dass die zurückgegebenen Informationen nicht gültig sind. Diese Skripte brauchen zwischen der Anforderung und der Rückgabe eines Ergebnisses an Apache einfach nicht so lange.
Was soll passieren
Laut der PHP-Dokumentation sollte das Slowlog nur jene Skripte kennzeichnen, die seit demAnfragezum Server erfolgte. Mit anderen Worten, es sollte die Zeit zwischen der Anforderung und dem Abschluss der Ausführung des Skripts gemessen werden. Dies geschieht jedoch nicht, wenn ich das Slowlog aktiviere.
Was scheint zu passieren
Meine Theorie ist, dass das Slowlog nicht die Laufzeit misst vonindividuelle Anfragendie von Apache kommen, sondern von der Zeit, in der einDer untergeordnete Prozess läuft. Da untergeordnete Prozesse ziemlich lange laufen können, erscheinen sie für das Slowlog möglicherweise als lang laufende Skripte. Wenn das Slowlog erkennt, dass ein untergeordneter Prozess länger als gelaufen ist request_slowlog_timeout, gibt es einen Backtrace des aktuell laufenden Skripts aus (das kann alles sein, was zu diesem Zeitpunkt läuft).
Meine Fragen
- Warum zeigt PHP-FPM im Slowlog ungültige Einträge wie diesen an? Kann es den Beginn einer Anfrage nicht erkennen?
- Wie konfiguriere ich das Slowlog, um nur das aufzuzeichnen, was beabsichtigt ist: die Laufzeit einer einzelnen Anfrage?
Ich habe keine weiteren Berichte zu diesem Problem gefunden, kann es aber jedes Mal erstellen, wenn ich das Slowlog auf einem Produktionsserver sowie auf einem Testserver mit nur einem Benutzer aktiviere.
Vielen Dank für jegliche Einsicht oder Hilfe.
Antwort1
Haben Sie zufällig eine Antwort gefunden?
Ich habe das gleiche Problem und habe Stunden damit verbracht, es herauszufinden. Noch verwirrender ist, dass das php-fpm-Fehlerprotokoll Einträge wie
WARNUNG: [Pool www] Child 7559 wurde bei Signal 15 (SIGTERM) nach 166,818268 Sekunden ab Start beendet.
Oder
[19-Jun-2023 16:24:56] WARNUNG: [pool www] child 7646, script '' (request: " ") timed out (66.168368 sec), beendet
Allerdings ist dieselbe PID nirgends im langsamen Protokoll zu finden, bevor sie request_terminate_timeout erreicht. Die Logik scheint vorzuschreiben, dass eine Anfrage, die 66+ Sekunden lang ausgeführt wurde, bevor sie beendet wurde, auch nach 10 Sekunden im langsamen Protokoll protokolliert wird.
Ich bin ratlos