DBが落ちたという通知が来た。DBは一度も落ちていなかった

朝にSlackを開いたら、CRITICALの通知が4つたまっていた。

504 AppHttpException: The request timed out.
  POST /customer/practice/attempts

PrismaClientKnownRequestError
  Transaction already closed

500 DriverAdapterError: canceling statement due to statement timeout
  GET /admin/dashboard/stats

DATABASE 서비스 다운
  "error": "Database health check (retry) timeout after 2000ms"

最後の行がいちばん怖い。DBが落ちたという意味だからだ。4つを1画面で見ると、ひとつの物語が描ける。DBが苦しくなり、だからクエリが詰まり、だからリクエストがタイムアウトし、ついにはヘルスチェックまで失敗した。もっともらしい物語だ。

だから私はDBの指標から開いた。その物語は最初の画面で崩れた。

DBは21時間ずっと暇だった

障害の時刻を含む21時間の区間のRDS指標を5分単位で取り出した。252個のデータポイント。

指標	最小	最大
CPU	4.6%	19.7%
コネクション	53	73
CPUクレジット残高	576	576
読み取り遅延	0s	0.01s
書き込み遅延	0.01s	0.08s

CPUは20%を超えたことがなく、クレジット残高は最小値と最大値が同じだ。1つも使っていないという意味である。書き込み遅延は最大80ミリ秒。RDS Proxyも確認した。コネクション貸与の遅延は最大26ミリ秒、バックエンドのコネクションは最大36個。どこにも、8秒や10秒のクエリを説明してくれる数字がない。

DBは落ちていない。それどころか、忙しくすらなかった。

リクエスト1つが大西洋を25回渡る

では8秒のクエリはどこから出たのか。構造を見れば答えが出る。

我々のサービスは2つのリージョンで動く。us-eastとeu-west。primary DBはus-eastに1つだけで、eu-westのアプリの読み取りはローカルのレプリカが受けるが、書き込みはすべて大西洋を渡り、RDS Proxyを経由してus-eastのprimaryへ行く。

問題は書き込みの回数だった。練習記録の保存リクエスト(POST /customer/practice/attempts)1つを、コードを追いながら数えてみた。アセットのupsertが1回、事前集計の読み取りが3回、学習試行のトランザクションが4回、ランナーの再照会が1回、進捗更新が23回、ストリークのトランザクションが約6回、統計のトランザクションが2回、復習状態の更新が23回。独立したインタラクティブトランザクション3つの塊にまたがって、おおよそ25回。

ログにその数字がそのまま記録されていた。

06:03:17  request_done  POST /customer/practice/attempts
          status=201  duration_ms=11695  query_count=25

クエリ25個、11.7秒。このリクエストは失敗すらしていない。11.7秒を耐え抜いた末に201で成功した。

ここで1つ正直に断っておくことがある。私はこの往復1回に何ミリ秒かかるのかを測っていない。コードのあるコメントはリージョン間のRTTを220ミリ秒と書いており、別のコメントは文あたり80~100ミリ秒と書いていた。どちらが正しいのかを確認しないまま、私は「25 x 220ms = 5.5秒」という計算をイシューの本文に書いた。いま見返すと、それは測定ではなく引用だ。正確な記述はこうなる。往復回数は数えた(25)。往復あたりのコストは測っていない。それでも結論は揺らがない。大西洋を25回往復すれば、コストは秒単位で積み上がる。

EUの朝のピーク(06:00~06:10 UTC)に、3秒を超えたprimaryへの書き込みが57件集中した。LearningAttempt.create 8,989ms、UserActiveDate.upsert 9,070ms、LearningAttempt.findUnique 10,561ms。リクエストが互いに押し合いながら、往復の遅延が積み上がっていった。

通知2つは、その隙間から出てきた。

通知1と2: 5秒のトランザクションが9.3秒に耐えられなかった

ストリーク更新のコードはこうなっていた。

// streak.service.ts:254
const changed = await this.prisma.primary.$transaction(async (tx) => {
  // ... リージョンをまたぐクエリが6本 ...
});

オプションのオブジェクトがない。だからPrismaのデフォルトのインタラクティブトランザクションのタイムアウトである5,000ミリ秒が適用される。普段は問題ない。リージョンを渡らないのであれば。

Transaction API error: A query cannot be executed on an expired transaction.
The timeout for this transaction was 5000 ms,
however 9326 ms passed since the start of the transaction.

9,326ミリ秒。そしてこれがP2028になり、リクエストはゲートウェイで504になる。

このコードは我々のコードベースでここだけが無防備だった。他のトランザクション経路はwithTxRetryユーティリティを通るのだが、そのユーティリティはタイムアウトを8秒に引き上げ、P2028を再試行の対象として拾う。ストリーク更新だけがその傘の外に残って、デフォルトの5秒を使っていた。

通知4: ヘルスチェックが、自分が監視していたボトルネックを通った

いちばん怖かった「DATABASEサービスダウン」が、実はいちばん間抜けだった。

ヘルスチェックのコードはよく書けていた。SELECT 1を2秒のタイムアウトで投げ、失敗したら500ミリ秒休んでもう一度試し、それも失敗したらCRITICALの通知を撃つ。アプリのPrismaのプールと混ざらないよう、専用のコネクションプール(最大2個)まで別に持たせてある。アプリのプールが枯渇してもヘルスチェックは生きているようにする設計だ。

ところが、このプローブがDBに届く経路は隔離されていなかった。

// health.service.ts:139
// DIRECT_DATABASE_URLがあればそれを使い、なければDATABASE_URLにフォールバックする

DIRECT_DATABASE_URLが設定されていなかった。フォールバックがかかり、DATABASE_URLはアプリの書き込みが集中しているまさにそのRDS Proxyを指している。つまりeu-westのヘルスプローブが投げたSELECT 1は、大西洋を渡り、いままさに詰まっているそのプロキシを通って、us-eastのprimaryまで行って帰ってこなければならなかった。2秒以内に。

コードはこの事実を知っていた。フォールバックがかかるとき、こんな警告を残すようになっている。

DIRECT_DATABASE_URL is not set; DB health checks will use DATABASE_URL
and may still share proxy bottlenecks.

ログにこの行がそのまま記録されていた。誰も読まなかっただけだ。

決定的な証拠は、2つのリージョンが同じ時刻に揃って失敗したことだ。12:02:17、us-eastのタスクのヘルスチェックがタイムアウト。12:02:18、eu-westのタスクもタイムアウト。地域の問題だったなら片方だけが死ぬはずだ。2つが一緒に死んだということは、2つが共有しているもの、つまりプロキシの経路が原因だという意味である。

その先は予定された筋書きだ。ヘルスチェックが2回とも失敗したので/public/healthが503を返し、オーケストレータはこのタスクを問題ありとみなして置き換える。4分後に新しいタスクが立ち上がった。新しいタスクは起動するなり、まったく同じヘルスチェックのタイムアウトを再び食らった。タスクを取り替えたところで大西洋が狭くなるわけではないからだ。

「DATABASEサービスダウン」は障害の症状ではなかった。監視する側が監視対象の混雑した道を歩いてみて、自分がつらいと報告したものだった。

管理画面の500は別件だった

ここで4つの通知を1つに束ねたい誘惑が来る。私も最初はそう整理しようとした。しかし管理画面の500は根が違った。

GET /admin/dashboard/statsが人気の単語を抽出するとき、直近7日でフィルタをかける。ところがそのフィルタがかかるテーブル(category_attempt)には自分の日付カラムがない。日付は結合されるlearning_attemptの側にしかない。だからPostgresはcategory_attemptを日付で先に切り落とす方法がなく、全履歴をなめるしかない。インデックスをどれだけうまく張っても、このフィルタを選択的にはできない。

slow_query path=/admin/dashboard/stats
           label=CategoryAttempt.groupBy dur=8009ms

statement_timeoutは8,000ミリ秒だ。8,009ミリ秒。9ミリ秒の差で死んだ。リージョンとは関係のない、テーブルが大きくなればいつか必ず弾けるフルスキャンだった。

通知4つのうち3つが同じ根で、1つは違った。4つが1画面に出たからといって、原因が1つとは限らない。

棄却した仮説が1つ

もっともらしい容疑者が1つあった。06:00のバースト直前に回るdevice-cleanupのcronがロック競合を起こした、という仮説だ。時間帯が噛み合っていて、なかなか説得力があった。

2つのリージョンのログを05:30~06:15の区間でなめた。cron関連のログが1件もなかった。遅かったDevice.updateManyの経路を確認すると、cronのバルク更新ではなく/v2/public/auth/refresh、つまり普通のユーザーのトークン更新リクエストだった。仮説は実測で棄却された。時間帯が重なるのは相関であり、ログにないというのは事実である。

往復を畳んだ

処方は2通りある。症状に耐える道がある。タイムアウトを8秒に延ばし、プールを大きくし、再試行を付ける。コストそのものを消す道もある。往復の回数を減らす。

我々は両方やった。ストリークのトランザクションにwithTxRetryをかぶせるのは絆創膏だが、必要な絆創膏だった。しかし本当の処方は往復を畳むことだった。

その道具はすでに作られていた。6月27日付のマイグレーションにcreate_practice_attempt_v1というサーバーサイド関数があった。セッションのロック、照会、挿入、セッションメタの更新、事前集計の読み取りをSQLの関数1つに畳んで、往復1回で終わらせる関数だ。冪等性まで備わっている(同じclient attempt idで2回呼ぶと、2回目は既存の行を返してinserted=falseを返す)。

ところが、この関数を有効にする機能フラグPRACTICE_ATTEMPT_SINGLE_RT_ENABLEDがデフォルトfalseで、本番ではオフになっていた。

リージョンをなくすとかactive-activeへ行くとかの代わりに、我々がやったのは、すでに作ってあったスイッチを入れることだった。

カナリア: 何を見て判定するのか

フラグをeu-westにだけ入れた。us-eastは対照群としてオフのまま。task definitionを786から787へ上げてローリングデプロイ。

ここで判定の指標を何にするかが、この話の核心だ。遅延は罠である。トラフィックが空いている時間にデプロイすれば、何も直さなくてもp95はよくなる。実際、遅延はよくなった。p50が2,784msから2千msを下回った。しかしそれは証拠として弱い。

代わりに私はリクエストあたりのクエリ数を見た。

デプロイ前  n=85   avg query_count = 22.0
デプロイ後  n=49   avg query_count = 15.3

クエリ数は負荷と無関係なper-request指標だ。トラフィックが多かろうと少なかろうと、リクエスト1つがクエリを何個投げるかはコード経路が決める。22から15.3へ、約7個が減った。そしてその7個は、我々が関数1つに畳んだクエリのリスト(セッションのロック + 照会 + 挿入 + セッションメタ + 事前集計の読み取り)の個数と正確に一致する。コード経路が実際に変わったという証拠はこの数字だ。遅延ではなく。

デプロイ後の標本は15分間で49件だ。その窓では5xxもP2028も0件だったが、同じ日の同じ長さの「デプロイ前」のエラー数を並べて測ってはいない。このフラグはattemptの保存だけを畳む。ストリークのトランザクションは依然としてリージョンを渡っていく。その日の窓でP2028が0件だったのは運がよかったという意味であって、証明ではない。

デプロイは成功したが、フラグは消えるところだった

カナリアを入れたやり方には代償があった。787はコンソールから直接登録したtask definitionだ。次の正式なデプロイが回ると、CDパイプラインがフラグのないtask definitionで上書きする。致命的ではない(上書きされれば安全なOFFに戻る)。ただ、改善が静かに消える。

そこでterraformへ昇格させる必要があったのだが、ここで2つ目の罠が出てきた。terraformのワークフローはdevelopへのpushではstagingだけをapplyし、productionはmainへのpushでのみapplyする。ところがstagingにはそもそもeu-westリージョンがない。つまり本番のeu-westの変更を含むPRをdevelopにマージしても、何も起きない。baseをmainに変えなければならなかった。

3つ目の罠があった。mainに直接マージするとdevelopが遅れ、戻してマージしなければ次のリリースがこの変更をrevertしてしまう。back-mergeのPRを別に作る必要があった。

「terraform applyが成功した」と「本番に反映された」は別の文だ。

残ったもの

「DBダウン」の通知が来たら、DBの指標から開くべきだ。通知の名前は通知を撃ったコードが付けたものであって、原因が付けたものではない。我々のヘルスチェックはアプリのプールと隔離された専用プールまで用意してあったのに、肝心のDBへ行く道が同じだったせいで、アプリと一緒に詰まった。隔離はリソースだけを分ければよいのではなく、経路も分けなければならない。

タイムアウトを5秒から8秒に延ばせば、その日の通知は止まる。しかしリクエストは相変わらず大西洋を25回渡る。トラフィックが少し増えれば8秒でも足りなくなる。症状に耐えるのかコストを消すのかは、あらかじめ決めておくほうがよい。コストの正体が「回数 x 距離」なら、減らすべきは回数だ。

遅延は負荷に揺さぶられ、per-request指標は揺さぶられない。性能修正をデプロイしてp95がよくなったからと安心する前に、リクエスト1つがする仕事の個数が実際に減ったかどうかを見るべきだ。その数字は、明け方にデプロイしようと昼にデプロイしようと同じである。

私は往復回数を数え、往復あたりの遅延はコードのコメントから持ってきて使った。そのコメント2つは互いに違う値を言っていた。結論が変わらなかったのは幸いだが、次は結論が変わるかもしれない。測っていない数字は、測っていないと書こう。