Pumaのスロット枯渇とは？CPU 21%で502が6万件出た理由

CPUもメモリも余っているのに、Railsアプリが502・504を吐き続けるときにどこを見ればいいかをまとめた。読み終わると、自分のアプリがいま同時に何リクエストさばけるかを計算でき、オートスケールの条件が実際に枯れる資源とかみ合っているかを確かめられる。

結論から。ボトルネックはPumaのスレッドスロットだった。スロットはCPUでもメモリでもないので、どのダッシュボードにも出てこなかった。

計器は平気な顔をしていた

メールを一斉送信した直後だった。ALB（AWSのロードバランサー）が50分間で502/504を62,684件返した。なのにグラフを開いても、枯れているものがない。

CPU          平常 1.6%  → ピーク 21.3%   (2 vCPU)
メモリ       66.5%      → 36.7%
DB接続       10.7       → 13.7          (pool 25)
RDS CPU      4.3%       → 9.7%
応答時間     0.009s     → 2.7s

メモリはむしろ下がった。オートスケールは一度も動かなかった。最初はDBを疑ったが、RDSは10%も使っていなかった。

5xxを二つに分けたら見えた

ALBの5xx指標は二つある。アプリが返したもの（HTTPCode_Target_5XX_Count）と、ALBが自分で作ったもの（HTTPCode_ELB_5XX_Count）だ。

Target 5XX                       0
ELB 5XX                     62,684
TargetConnectionErrorCount  19,292

アプリはエラーを一つも出していない。リクエストがアプリまで届いていなかったのだ。TargetConnectionErrorCount は、ALBがバックエンドと接続すら張れなかった回数。ここまで見ると「アプリが忙しくて扉を開けられなかった」に絞られる。

同時20で毎秒296をさばいていた

Railsアプリが一度にさばけるリクエスト数は、掛け算一つで決まる。

ECSタスク数 × Puma workers × threads

その案件の puma.rb は WEB_CONCURRENCY・RAILS_MAX_THREADS で変えられるようになっていたが、ECSのタスク定義にはどちらもなかった。デフォルトの2と5がそのまま入っていた。

2 tasks × 2 workers × 5 threads = 20

ピークは毎秒296リクエスト。必要な同時実行数はLittle's Law（同時に処理中のリクエスト数 = 毎秒リクエスト数 × 平均応答時間）ですぐ出る。296 × 2.5秒 ≈ 740。席20個に740人が並んでいたわけだ。

遅いだけで終わらなかった理由 — ヘルスチェック

スロットが全部埋まると、新しいリクエストは待ち行列で待つ。ここまではただ遅いだけだ。

問題は、ALBのヘルスチェックも同じPumaのスロットを使うことだ。ヘルスチェックが列の後ろでタイムアウトすると、ALBはそのタスクが死んだと判断してトラフィックを切る。healthy host数（平均）が1.0から0.1まで落ちた。送り先がなくなったALBは自分で5xxを返す。過負荷が障害に変わるのはここだ。

オートスケールが捕まえられない構造

スケール条件はCPU 80%・メモリ80%・Sidekiqキュー300だった。死んだ原因のスレッドスロットは条件にない。ポリシーは三つも付いていて、配線も正しかった。監視している資源と枯れた資源が違っただけだ。「設定してある」と「動く」は別の話だった。

CPUが21%で止まったのにも理由がある。Rubyはプロセスごとに GVL（一度に一つのスレッドしかRubyコードを動かせないロック）が一つ。スレッドはI/Oを待つ間だけ順番を譲る。メール送信・外部API・遅いクエリのように待ちが多いと、スロットは満席なのにCPUは遊ぶ。「スロット満席 + CPU 21%」はI/O待ち型の負荷でよく見る形だ。

だからスケールの基準は TargetResponseTime が合う。待ち行列で待った時間が、ALBの測る応答時間に含まれるからだ。RequestCountPerTarget は代わりにならない。平常時は10分で70リクエスト（応答0.009秒）、障害時は10分で177,514リクエスト（応答2.5秒）だった。同じリクエスト数でも、処理時間しだいで必要なスロット数は数百倍変わる。

スロットを増やそうとして踏みかけたもの — RAILS_MAX_THREADSを読むのはPumaだけじゃない

「じゃあ RAILS_MAX_THREADS=8 を入れればいい」が最初の考えだった。入れる前にこの変数を読んでいる場所を探したら、Pumaだけではなかった。Railsが生成する database.yml も、コネクションプールの大きさを同じ変数で決めている。このブログが動いているリポジトリもそうだ。

# config/database.yml
pool: <%= ENV.fetch("RAILS_MAX_THREADS", 5) %>

その案件はPumaとSidekiqをsupervisordで一つのコンテナに載せていた。ECSの環境変数はコンテナ単位なので、Sidekiqのプロセスにも同じ値が渡る。

Puma threads          5 → 8    意図したもの
DB pool              25 → 8    意図しなかったもの
Sidekiq concurrency  10 → 10   sidekiq.yml に固定されていて変わらない
→ Sidekiqのスレッド10本が接続8本を奪い合う → ConnectionTimeoutError

Pumaだけ見れば pool ≥ threads で安全に見える。同じコンテナの別プロセスまで見て初めて気づく。そこでpoolを DB_POOL_SIZE のような専用の変数に切り出した。一つの変数が二役を兼ねている構造が原因なので、値をいじるだけではまた起きる。

デプロイ順も引っかかる。terraform apply はタスク定義の環境変数をすぐ変えるが、database.yml はイメージの中にある。pool分離のコードが出る前にapplyすると、その瞬間にpoolが8になる。インフラとコードは別の道を別の速さで本番に届く。対になる変更は、順番をPRに書いておく。

自分のアプリでまず見るところ

本番の環境変数に WEB_CONCURRENCY・RAILS_MAX_THREADS が本当に入っているかから見る。デフォルトのまま動いているなら、スロット数は思っているより少ない。Puma.stats（または pumactl stats）を見ると、働いているスレッド数 busy_threads と待ち行列の長さ backlog が出る。平常時はどちらもほぼ0で、余裕たっぷりに見える。負荷が来たときにどれが先に枯れるかは、前もって計算しておかないとわからない。

診断の順番と workers・threads の比較は下の詳細にある。「資源は余っているのに5xx」のような障害を抱えている、あるいはRailsをECSに載せる構成を一緒に見てほしいなら、negabaro に気軽に聞いてほしい。