問題
RHEL 8 上の Apache 2.4 で PHP-FPM 7.4.30 を実行していますが、PHP の slowlog が正しく動作しません。長時間実行されるスクリプトに関する有効な情報が返されません。
slowlog を有効にすると ( request_slowlog_timeout10 秒以上など高い値でも)、長時間実行されていないことがわかっているスクリプトを含む多くのエントリがログに表示されます。リストはランダムに表示され、さまざまなスクリプトとその内部の関数のバックトレースが表示されます。明らかなパターンはありません。返された情報は有効ではないと確信しています。これらのスクリプトは、リクエストから Apache への結果の返送までにそれほど時間がかかりません。
何が起こるべきか
PHPのドキュメントによると、スローログは、リクエストサーバーへのリクエストが行われた時点です。つまり、リクエストからスクリプトの実行が完了するまでの時間を測定する必要があります。ただし、スローログを有効にすると、この動作は行われません。
何が起こっているのか
私の理論では、スローログは実行時間を計測していない。個別のリクエストApacheから来たものではなく、子プロセスが実行中子プロセスは長時間実行される可能性があるため、スローログでは長時間実行されるスクリプトのように見える場合があります。スローログは、子プロセスが を超えて実行されていることを確認するとrequest_slowlog_timeout、現在実行中のスクリプト (その時点で実行中のものであれば何でもかまいません) のバックトレースを出力します。
私の質問
- PHP-FPM がスローログにこのような無効なエントリを表示するのはなぜですか? リクエストの開始を検出できないのでしょうか?
- 意図したもの、つまり単一のリクエストの実行時間のみを記録するようにスローログを構成するにはどうすればよいですか?
この問題に関する他の報告は見つかりませんでしたが、実稼働サーバーと、ユーザーが 1 人だけのテスト サーバーでスローログを有効にするたびに、この問題が発生します。
ご意見やご支援をいただければ幸いです。
答え1
偶然答えを見つけましたか?
私も同じ問題を抱えており、解決に何時間も費やしました。php-fpmのエラーログに次のようなエントリが記録されるのはさらに困惑します。
警告: [プール www] 子 7559 は開始から 166.818268 秒後にシグナル 15 (SIGTERM) で終了しました
または
[2023 年 6 月 19 日 16:24:56] 警告: [プール www] 子 7646、スクリプト '' (リクエスト: " ") の実行がタイムアウトしました (66.168368 秒)。終了します
ただし、同じ PID は、request_terminate_timeout に達するまでスロー ログのどこにも見つかりません。ロジックによれば、終了する前に 66 秒以上実行されたリクエストも、10 秒後にスロー ログに記録されるはずです。
私は困惑している