PHP 8.3 の FPM で slowlog を有効にしたら 504 の原因が読めた

PHP 8.3.4、Amazon Linux 2023、nginx + PHP-FPM の構成。API の一部だけが数十秒で 504 になる事象を追っていた。アクセスは平常時 200req/s 程度、重いリクエストが混ざると pm.max_children を食い潰して全体が詰まる。nginx の error_log には upstream timed out しか出ず、アプリ側のログには何も残らない。PHP 側で「どこまで進んだか」が見えていなかった。

まず FPM の slowlog を有効にした。プール設定に以下を足す。

request_slowlog_timeout = 5s
slowlog = /var/log/php-fpm/www-slow.log
request_terminate_timeout = 30s

加えて nginx 側の fastcgi_read_timeout を 35s に揃え、FPM が先に切るようにした。反映は systemctl reload php-fpm で足りる。slowlog にはスタックトレースが出るので、504 になっていたリクエストがどの関数で止まっているかが読める。今回の原因は外部 API への同期呼び出しで、タイムアウト未指定のまま待っていた箇所だった。ここに connect_timeout と timeout を入れ、結果を短時間キャッシュするようにして解消した。

slowlog はリクエストのスタックを一定間隔でサンプリングするだけで、処理を止めない。だから本番でも入れられる。ただし request_slowlog_timeout を短くしすぎると、正常に遅いだけのバッチ系まで記録されてログが膨らむ。自分の環境では 5s にして、まず 1 日観察してから 3s に詰めた。あと slowlog はあくまで「その瞬間の PHP 側の居場所」しか示さない。DB のロック待ちや DNS の解決待ちは、スタックに出ないことがある。今回も最初は DB を疑って外した。

効かない条件もある。OPcache の preload で動くコードや、pcntl で fork するワーカーの中の処理は追いにくい。あと FPM を static で固定していると、詰まったワーカーが残り続けて slowlog が同じ箇所を吐き続けるだけになる。一時的に pm = dynamic に戻して切り分けた。

同じように 504 のときアプリログが空のまま、という状況の人に聞きたい。slowlog で原因が読めたケースと、結局 nginx や LB 側のタイムアウトを疑うことになったケースは、何が違ったか。