php-fpmのreloadがやたら遅かった話
これはなに
php-fpmのreloadが遅く、reload完了前にアクセスが発生してサービス側でタイムアウトが発生しました。
同じ轍を踏まないために整理しておくものです。
起きたこと
ある日、他サービスからのAPIリクエストが突然エラーになりました。
toC向けサービスのため、非常に焦ったのを覚えています。
ただ、発生頻度は少なく、1日に数回起きる程度でした。
推測〜検証サイクル
1回目
推測
発生頻度とタイミングから推測するに、リリースのタイミングで起きているようです。
リリースの時に何をやっているかと言えば、当然デプロイ関連のCI/CDですね。
CodeDeployでphp-fpmのreloadを行っていたため、まず最初に疑いました。
確認
リリースのタイミングでphp-fpmがreloadしているログを確認したため、原因の可能性が高いです。
また、リリース以外では高速でAPIがレスポンスされていたため、リリースが直接原因でした。
まず公式を確認しました。
以下記載があったため、当初はgraceful reloadが行えるかと思いました。
緩やかな (graceful) 停止/起動 機能を含む高度なプロセス管理
しかし、こちらの記事によると、バグにより即座にプロセスが終了してしまう可能性があるようでした。
そこで上記記事にもある通り、process_control_timeoutの値を調整してみます。
検証・リリース
process_control_timeoutを設定し、重いリクエストを送ってもプロセスが正常に処理でき、一時的に問題が解消されたように見えました。
以下項目も検討はしましたが、早期に影響を減らすため検証終了、本番適用を行いました。
- process_control_timeout をリクエスト元システムのタイムアウトより短くする
- php-fpmのreload自体、タイムアウト時間を超えていたため効果薄
- デプロイを段階的に実施する
- ただでさえ長いデプロイ時間がより長くなる
- 複数チームが1つのシステムを触っており、日に複数回リリースがあるため選択したくない
- toCシステム側のタイムアウトを伸ばす
- 顧客体験の毀損になるため極力選択したくない
- Blue/Greenデプロイの実装
- EC2運用のため、コストや運用を鑑みると厳しい
- 実装コストが大きく暫定対応できない
結果
発生頻度は減りましたが、残念ながら再発してしまいます。
想定していた結果ではありますが、ここから本格的に調査していきます。
2回目
推測
そもそもなぜphp-fpmをreloadしているのかに着目しました。
OPcacheをクリアするためでしたが、reloadでなくとも実現できるのでは?と考えました。
また、本当にphp-fpmが原因なのかも怪しくなってきたため、メトリクスも確認していきます。
確認
メトリクスに関しては、リリース時にCPUが必ずスパイクしていました。
CPUスパイクの原因も、reloadによるものと仮定すれば、reload時間が長いことも納得です。
また、reload以外でOPcacheをクリアする方法について、Geminiから以下回答がありました。
方法1:タイムスタンプのチェックを有効にする(opcache.revalidate_freq) これは最も手軽で一般的な解決策です。php.iniで以下の設定を行います。
- php.ini
- ファイルのタイムスタンプをチェックして、変更があればキャッシュを更新する
- opcache.validate_timestamps=1
- タイムスタンプをチェックする頻度(秒)。0にするとリクエスト毎にチェックする
- opcache.revalidate_freq=2
- この設定を有効にすると、PHPはファイルの最終更新日時(タイムスタンプ)を見るようになります。 設定変更のみで対応でき、非常に簡単です。 デプロイ時に何もする必要がありません。ファイルを上書きすれば、最大2秒後(設定値による)には自動で反映されます。
方法2:デプロイ時にスクリプトでキャッシュをクリアする(opcache_reset) キャッシュクリア用のPHPスクリプトを作成してdeploy.shから呼び出し
方法1を採用しようと思いましたが、以下懸念がありました。
- reloadをしないことによるキャッシュメモリの逼迫
- リリースの度にシンボリックリンクを作成しており、その分キャッシュが蓄積する
- 1度のリリースで数十MBのキャッシュをしているためそのまま採用できない
検証・リリース
方法2で回避しようと考えていましたが、リクエスト元のシステムと相談し、タイムアウト値を一時的に伸ばしてもらう結論でとりあえずは着地しました。
解消はしましたが、本質的な解決ではないので引き続き調査しました。
3回目(延長戦)
以下疑問を次々に検証していきました。
process_control_timeoutは処理終了を本当に待っているのか?
次の設定値でプロセスがどう生まれているのかを検証しました。
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 5
php-fpmを再起動したところ、マスター1個、ワーカー1個の計2個になりました。
100秒sleepさせて、プロセスが処理中であることを確認したのち、マスタープロセスをreload。
しばらく待った後に画面表示され、旧ワーカーが無くなり、新ワーカーが生まれていました。
プロセスの終了は待っておらず、新プロセスを立ち上げて処理を捌いていることがわかりました。
起動するワーカーの数が多すぎるのでは?
設定値を元に調べていたところ、ワーカーの起動数が多すぎるのでは?と気になりました。
pm.start_servers=20
以下手順で検証したところ、最大40個のワーカー起動を確認しました。
- 20個の並列リクエストを行い、全ワーカーを使用中にする
- php-fpmをreload
- php-fpmが動的に20個の追加ワーカーを起動
4. pm.start_servers=20を起動(pm.max_children=240まで起動する模様) - 合計40個のワーカーが同時起動していた
試しに、以下設定値へ変更したところ、CPUのスパイクが軽減されました。
pm = dynamic
pm.max_children = 40
pm.start_servers = 6
pm.min_spare_servers = 6
pm.max_spare_servers = 16
pm.max_requests = 1500
OPcacheを使わなかったらreload時間が早くなるのか?
OPcacheの読み込みは原因になり得ると知り、以下設定に変更してみました。
opcache.enable = 0
opcache.preload_user = xxxxx ➡︎ コメントアウト
opcache.preload= xxxxxxx ➡︎ コメントアウト
php-fpmのreloadを行ったところ、一瞬で起動できました!
ただし、OPcacheを無効にすると性能悪化が懸念されます。
[09-Sep-2025 10:06:17] NOTICE: Reloading in progress ...
・・・
[09-Sep-2025 10:06:17] NOTICE: ready to handle connections
OPcacheは使いたいのでpreloadだけを無効にしたらどうか?
preloadをコメントアウトし、reloadしてみました。
[09-Sep-2025 11:38:29] NOTICE: Reloading in progress ...
・・・
[09-Sep-2025 11:38:29] NOTICE: ready to handle connections
問題はこれですね。reload処理で負荷が高かったようです。
さいごに
preloadに辿り着くまで非常に長かったのですが、原因が分かって良かったです。
preload自体は、シンボリック切り替え+リリース頻度の関係上、無くせないため、
読み込むディレクトリを絞るなど、引き続き対応を検討中です。
また、ECSであれば回避策がもっと考えられたため、この機にECS化の検討に入っています。
以上、試行錯誤の記録として、試行錯誤の過程をありのままに記述させていただきました!
Discussion