PHP 8.3 の FPM で max_execution_time を超えたリクエストが 504 になるまでの挙動を実測した

PHP 8.3.4、nginx 1.24 + PHP-FPM（pm=dynamic、pm.max_children=24）、DB は MySQL 8.0。120 万行の注文テーブルに対して月次集計を走らせる管理画面があり、フロントの nginx は fastcgi_read_timeout 60s、PHP 側は max_execution_time=30。ところが実行すると 30 秒で PHP のエラーログに何も出ず、ブラウザには 60 秒で 504 が返る。リクエスト自体は 90 秒近く走り続けていました。

まず FPM の設定を確認します。

; www.conf
request_terminate_timeout = 0

ここが 0 だと FPM はワーカーを能動的に殺しません。max_execution_time は PHP の実行時間を測るだけで、sleep() や外部 I/O の待ち、PDO::query() のロングクエリ中はカウントされない。集計クエリがまさにこれで、PHP 側のタイマーは止まったまま nginx のタイムアウトだけが先に来ていました。

切り分けは slowlog と FPM の status で行いました。

; www.conf
slowlog = /var/log/php-fpm/slow.log
request_slowlog_timeout = 10s
pm.status_path = /status

slowlog には 10 秒時点のスタック（PDO->query() の中）が出て、クエリが犯人だと確定。次に request_terminate_timeout = 45s を設定し、nginx 側を fastcgi_read_timeout 50s に上げて再度実行。45 秒でワーカーが落ち、FPM のログに execution timed out (45.000000 sec) が残り、504 ではなく 502 が返るようになりました。ここまで来れば原因は読めます。

なぜ 45 秒にしたか。nginx より短くしないと、PHP がタイムアウトしたことをクライアントに伝えられず、ワーカーだけが残るためです。逆に短くしすぎると正常な重い処理まで殺すので、slowlog で実測した 10 秒と、実際に完走した最長 38 秒の間に置きました。

効かない条件もあります。request_terminate_timeout は FPM のマスタがワーカーに SIGTERM を送るだけで、MySQL 側のクエリは kill されません。実際、ワーカーを落とした後も DB のプロセスリストに集計クエリが 20 秒ほど残っていました。PDO::ATTR_TIMEOUT や MAX_EXECUTION_TIME ヒントを併用しないと、DB 側は止まりません。あと request_terminate_timeout は CLI では効かないので、cron で同じ処理を回す時は別途 set_time_limit() が要ります。以前、管理画面だけ直して cron 側を忘れ、夜間にワーカーが張り付いたまま朝を迎えたことがありました。

同じ構成で、集計クエリを分割するか非同期に逃がすか、どちらに寄せていますか。