起動しているのにおかしい — まず何を見るか

一言でいうと

障害対応で高くつくのは、直すことではなくどこが原因かを切り分けることです。データベースはたいてい落ちません。起動したまま異常になり、そのとき症状が見える場所と原因がある場所は、ほとんどいつも違います。

なぜ必要なのか

注文APIが2つ、応答しません。エラーでもタイムアウトでもなく、ただ戻ってきません。

最初にすることは決まっています。遅いクエリを見ます。ところが、一覧が空です。CPUも空いていて、ディスクも遊んでいて、コネクション数も平常どおりです。メトリクスがすべて緑です。ここで「DBは正常なのでは」と結論づけてアプリケーション側を調べ始めると、その日1日が潰れます。

メトリクスが緑なのには理由があります。誰も仕事をしていないからです。みんな待っています。待っているセッションはCPUを使わず、ディスクにも触れず、遅いクエリの一覧にも載りません。そして、そのセッションたちを引き留めているセッションは、クエリを実行してさえいません。

どう動くのか

pg_stat_activityというビュー1つに、必要なものがほとんどそろっています。読む順序があります。

カラム	何を表すか
`state`	`active`は今クエリを実行中、`idle`はトランザクションの外で待機中、`idle in transaction`はトランザクションを開いたまま待機中です
`wait_event_type`・`wait_event`	何を待っているかを表します。`Lock`ならロック待ち、`Client`・`ClientRead`ならクライアントが次のコマンドを送ってこない状態です
`xact_start`	トランザクションが開始された時刻です。これが古いという事実1つで、ほとんどの事故を説明できます
`pg_blocking_pids(pid)`	このセッションをブロックしているpidの一覧です

stateの3つ目の値が核心です。idle in transactionとClientReadが同時にあれば、そのセッションは仕事を任せて姿を消したクライアントを待っているということです。サーバーの立場では何も悪くないため、どんな警告も鳴りません。

チェーンを1段たどると見える被害者

このコースのラボ環境で、そのまま取った画面です。

 pid  | application_name |        state        | wait_event_type |  wait_event   | blocked_by
------+------------------+---------------------+-----------------+---------------+-----------
  784 | nightly-batch    | idle in transaction | Client          | ClientRead    | {}
  796 | api-cart         | active              | Lock            | transactionid | {784}
  795 | api-order        | active              | Lock            | tuple         | {796}

api-orderがブロックされています。誰がブロックしたのかと聞かれれば、答えは796です。ところが796もブロックされています。796を切断しても、795はすぐ次の順番を待つだけで、本当の原因である784はそのまま残ります。

そこで問うべきなのは、「誰が私をブロックしたか」ではなく「ブロックされている人が誰もいない地点はどこか」です。

select distinct b as root_pid
  from pg_stat_activity a, unnest(pg_blocking_pids(a.pid)) b
 where cardinality(pg_blocking_pids(b)) = 0;

他人をブロックしていて、自分は誰にもブロックされていないpid、それがチェーンの根元です。上の画面では784が1つだけ出てきます。

wait_eventも見過ごしてはいけません。transactionidは「前のトランザクションが終わるのを待っている」、tupleは「同じ行を狙う待ち行列で、自分の前の人を待っている」という意味です。2つの値が混在していれば、待ち行列がすでに2重になっているということです。

コネクションはどこへ消えるのか

待っているセッションはコネクションを1つずつ握っています。これがこの障害が広がる仕組みです。

lock_timeoutのデフォルト値は0、つまり無制限です。上限を設けると、次のように終わります。

ERROR:  55P03: canceling statement due to lock timeout

1秒後にエラーで戻り、コネクションはすぐにプールへ返却されます。上限がなければそのコネクションは永遠に塞がれ、同じ行にリクエストが集中するほど、塞がれたコネクションが増えます。プールが尽きた瞬間から、その行とまったく関係ないリクエストまでコネクションを受け取れず失敗します。

症状が「DBが遅い」ではなく「サーバーが応答しない」として現れるのはこのためで、だからこの事故は、データベースではなくアプリケーションの問題と誤診されやすいのです。

max_connectionsを上げるのは最初の一手ではありません。コネクションが足りないのではなく、返却されていないので、上限を上げても塞がれるコネクションの上限が上がるだけです。バックエンド1つごとにプロセスが1つ起動するため、メモリとコンテキストスイッチのコストは正直に増えます。最初にすべきことは、なぜ返却されないのかを探すことです。

現場での姿

1つ目は、監視メトリクスに「最も古いトランザクションの経過時間」を入れることです。遅いクエリだけを見る監視では、idle in transactionを永遠に捕まえられません。クエリを実行していないので、捕まる場所がありません。1行で済みます。

select max(now() - xact_start) as oldest
  from pg_stat_activity where state <> 'idle';

この値1つが、このコースで扱う事故の半分を前もって教えてくれます。

2つ目は、上限をコードではなくコネクションに設定することです。クエリごとにset lock_timeoutを入れる方式は、いつか入れ忘れます。プールがコネクションを貸し出すときにセッションのデフォルト値として設定しておけば、入れ忘れる場所がなくなります。lock_timeoutは「待つ」ことの上限、idle_in_transaction_session_timeoutは「トランザクションを開いたまま遊んでいる」ことの上限で、それぞれ別の事故を防ぎます。ラボ環境で後者を3秒に設定して確認したところ、遊んでいたセッションはそのまま切断されて消えました。

3つ目は、マイグレーションには必ずlock_timeoutを設定することです。alter tableはACCESS EXCLUSIVEを要求します。同じ環境でそのロックを握らせておいてselect count(*)を実行してみたところ、読み取りまでそのままブロックされました。

ERROR:  canceling statement due to lock timeout
LINE 1: select count(*) from products

前に長いクエリが1つあるだけで、マイグレーションが待ち行列に入り、その後ろに来るすべてのクエリがマイグレーションの後ろに並びます。読み取りも含めてです。上限を設定しておけば、デプロイが失敗するだけで済みますが、設定しなければサービスが止まります。失敗するデプロイは、止まるサービスよりも安上がりです。

次のラボですること

実際の形のpg_stat_activityスナップショットを読み、ブロックされているものとブロックしているものを切り分けます。チェーンの根元を探す基準、idle in transactionが監視に捕まらない理由、そしてmax_connectionsを上げることがなぜ最初の一手ではないのかを、数字で確認します。