Herokuのworker dynoのパフォーマンスが数日前から突然悪くなった。
今まで30秒程度掛かっていたバックグラウンド処理が10分程度掛かるようになった。
直近で心当たりのあるリリースはなかったため、調査することにした。
丸一日調査して解決はしたのだが、思っていたよりも根が深く、自身の学びにもなったのでまとめておく。
前提情報
- Rails5.2
Jobフレームワーク: Sidekiq
Heroku
- web dyno * 2
- worker dyno * 2 (内1つはcron用)
DB
- posgresql
監視ツール
- Papertrail
- NewRelic
Papertrailでworker dynoのログを確認する
まずはログを確認する。Pepartrailを入れているので、問題が発生したJobIDをもとにログを特定する。 (各処理の実行時間などから問題の原因をある程度推測できるケースが多い)
ActiveRecordが発行しているログからDBへのアクセス時間が極端に遅くなっていることがわかった。 通常時はテーブルのUpdateに1ms程度掛かっていた処理が、100ms程度掛かっていることがわかった。
「DBアクセス周りになにか原因があるのではないか？」と推測する。
NewRelicでパフォーマンスを確認する
念の為NewRelic APMも確認する。 CPUやMemoryの状況に異常は見られなかった。 Transaction traceを確認するとDB Queryのパフォーマンスに異常はなく、アプリケーションコードの実行速度が極端に遅いことがわかった。
ActiveRecordの処理時間は生のDB Query以外の処理時間も含まれている。
「DBが原因ではない」と推測する。
DBが原因ではないことの確認
念の為web dynoからのアクセス時間を図ってみたところ、異常は見られなかった。
- webからのアクセスは遅くない
- workerからのアクセスのみ遅い
上記よりDBが原因ではないことがわかった。
「workerで動くアプリケーションに原因があるのではないか？」と推測する。
デバッグログを仕込む
workerで実行しているJobアプリケーションに対してデバックログを仕込んだ。
デバッグを仕込む際は、
- 大きめなメソッド単位でログを仕込んで、どこでメソッド時間がかかっているか特定する
- 時間が掛かっているメソッドが特定できたら、ドリルダウンで情報が把握できるようにあらに詳細なログを仕込む
というステップを踏む。
1の段階で全体的に遅いということがわかった。
「特定のコードが遅いというわけではなくプロセス自体が遅いのではないか？」と推測する。
Herokuのmetricsを確認
原因がわからず小一時間息詰まっていたが、初心に戻ってHerokuのMetricsタブを確認することにした。
するとDyno Loadが常に1以上稼働していることがわかった。
試しにworker dynoをもう一つ起動してjobを実行してみると もう一つのworkerに割り振られたJobは通常通りのパフォーマンスで処理を終えたことが確認できた。
「デーモンプロセスが動いていて、dynoを専有しているのではないか？」と推測する。
Sidekiqの管理画面を確認
Sidekiqの管理画面を確認すると実行中のジョブプロセスが常に1あることが判明。 worker dynoで再起動してみる。するとSidekiqの性質上、自動でリランが走った。 リランされたジョブがなぜか終了されることなく、デーモン化していることがわかった。
「アプリケーションコードで無限ループしているのではないか？」と推測する。
コードを確認
対象クラス内で無限ループが発生しそうなコードがないか調査したところ、whileを使用している処理が一箇所見つかる。 ある特定の条件の場合、whileを抜けられずに無限ループしてしまうことが判明。
原因は、
「アプリケーション内の無限ループによりworker dynoを専有していたこと」
