MongoDB シャードクラスタの書き込み経路シリーズの第5/6回である。
この記事が答える問い: primary が書き込みを1つも終えられないのに、なぜ自動 failover が起きないのか？ Flow Control と Storage Node Watchdog はなぜこの状態を捉えられないのか？ では何を監視すべきか？
基準バージョン: MongoDB 4.2（公式ドキュメント
v4.2ブランチ、サーバーソースr4.2.12タグ）。7.0 で変わった点は該当する節に別途記した。
MongoDB 4.2 で primary の異常に自動で反応する仕組みは3つある。3つの仕組みは、primary が生きているか、secondary が遅れているかを見る。primary が応答はするのに書き込みを終えられない状態は、どの判定基準にも引っかからない。
| 仕組み | 見るもの | 書き込みが止まった primary を見ると |
|---|---|---|
| 自動 failover（選挙） | heartbeat に応答するか | heartbeat が応答するので選挙は起きない |
| Flow Control | majority commit の遅延（lag） | lag が0に近いので正常と判定する |
| Storage Node Watchdog | ファイルシステムの無応答 | ファイルシステムは正常なので発動しない |
そのため、運用者が進行（progress）を直接監視する必要がある。監視すべき問いは「応答するか」ではなく「書き込みを終えるか」である。
この状態を生む原因は、ストレージエンジン WiredTiger（以下、エンジン）の中にある。具体的には、WiredTiger スナップショットの pause ループによる livelock である。livelock とは、スレッドが CPU を使って回り続けるのに、操作が終わらない状態である。この原因は第3/6回で扱う。この記事では、3つの仕組みがこの状態に反応しない理由と、監視の設計を扱う。
レプリカセットのメンバーは互いに heartbeat を送る。4.2 のドキュメントはこう記している。
Replica set members send heartbeats (pings) to each other every two seconds. If a heartbeat does not return within 10 seconds, the other members mark the delinquent member as inaccessible.
| 項目 | 値 |
|---|---|
| heartbeat の周期 | 2秒 |
| 応答がなければアクセス不能とみなすまでの時間 | 10秒 |
| 選挙を起こす接続断の時間 | electionTimeoutMillis、デフォルト10秒 |
選挙は、secondary が primary との接続を electionTimeoutMillis より長く失ったときに始まる。選挙規則の入力は「heartbeat が返ってくるか」の1つだけである。primary が書き込みを処理しているかは入力にない。
heartbeat コマンドを処理するコードは、グローバルロックも ticket も取らない。ticket は、エンジンに同時に入れる操作数を制限する入場券である。処理関数は src/mongo/db/repl/repl_set_commands.cpp（r4.2.12）の CmdReplSetHeartbeat::run である。この関数は引数をパースした後、processHeartbeatV1 だけを呼ぶ。
通常の書き込みは違う。insert・update・delete・findAndModify は、グローバルロックを IX（書き込みの意図）モードで取りながら write ticket を1つ受け取る（src/mongo/db/concurrency/lock_state.cpp:262-266 (r4.2.12)）。4.2 の write ticket のデフォルト値は128個である（src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp:474-475 (r4.2.12)）。
write ticket 128個を受け取った操作がすべてエンジン内で止まっていても、heartbeat は ticket を待たない。そのため、エンジンが止まっても heartbeat は正常に応答しうる。この結論はソースを読んで導いた推論である。実際に再現はしていない。
たとえば、store_inventory コレクションに書き込む writer サービスの書き込みが1つも終わらない間も、secondary は2秒ごとに heartbeat の応答を受け取る。選挙規則の入力には変化がない。
Flow Control は 4.2 で入った機能である。majority commit の遅延とは、primary が適用した書き込みを過半数のメンバーが確認するまでに遅れている時間である。Flow Control は、この遅延を一定値以下に保つために primary の書き込み速度を落とす。
With flow control enabled, as the lag grows close to the flowControlTargetLagSeconds, writes on the primary must obtain tickets before taking locks to apply writes.
デフォルト値は enableFlowControl: true、flowControlTargetLagSeconds: 10 である。FCV（featureCompatibilityVersion）が 4.2 で、majority read concern が有効でなければ動作しない。
lag の計算式はソースにある（src/mongo/db/storage/flow_control.cpp:77-82 (r4.2.12)）。
return static_cast<std::uint64_t>(durationCount<Milliseconds>(myLastApplied - lastCommitted));
myLastApplied は、primary が最後に適用した書き込みの時刻である。lastCommitted は、過半数のメンバーが確認した最後の書き込みの時刻である。この差がしきい値（flowControlTargetLagSeconds）より小さければ、Flow Control は正常と判定し、ticket を増やす（同じファイルの328-350行）。2つの時刻の間に操作がほとんどないときも、正常と判定する。
primary が書き込みできないと、次のように流れる。
myLastApplied が止まる。lastCommitted が myLastApplied と同じになる。上の流れは計算式から導いた推論である。例示値で考えてみる。primary が 10:00:00 に最後の書き込みを適用した。secondary がこれを複製し、lastCommitted も 10:00:00 になった。その後 primary が何も適用できなければ、lag は 10:00:00 − 10:00:00 = 0秒 に固定される。しきい値の10秒にはるかに届かない。
lag が大きくなって Flow Control が書き込みを遅らせる状況でも、この状態は解けない。Flow Control はエンジンの入口で入ってくる書き込みの量を減らす。すでに ticket を受け取ってエンジンの中に入った操作には手を出せない。
Storage Node Watchdog（以下、Watchdog）は、4.2 から Community 版にもある。監視対象は、次のディレクトリのファイルシステムの無応答である。
--dbpath ディレクトリ--dbpath 内の journal ディレクトリ（journaling を有効にしている場合）--logpath のファイルがあるディレクトリ--auditPath のファイルがあるディレクトリファイルシステムが応答しなければ、Watchdog は mongod を終了させる（終了コード61）。その mongod が primary だったなら failover が起きる。
Watchdog はデフォルトで無効である。watchdogPeriodSeconds のデフォルト値は -1（無効）で、有効にするには mongod の起動時に60以上の整数を渡す必要がある。
CPU がエンジン内のループに縛られた状態でも、ディスクとファイルシステムは正常に応答する。そのため Watchdog を有効にしていても、この状況では発動しない。この結論は、ドキュメントの監視対象から導いた推論である。
そのほかに、エンジンが進行できないときに primary を降格させる機能は、4.2 のドキュメントでは見つけられなかった。ドキュメントとパラメーターをすべて確認したわけではない。
応答はするのに仕事を終えられない構造は、Kubernetes の liveness probe でもよく生じる。probe が /health だけを確認しているとしよう。HTTP スレッドが応答すれば、作業キューが止まっていても probe は正常と判定する。MongoDB の heartbeat は、この /health probe と同じ役割を果たしている。
進行を見るには、3つのシグナルを合わせて見る。
1つだけを見ると誤検知が起きる。スループットだけを見ると、書き込みがもともと少ない明け方に鳴る。待ち行列だけを見ると、正常な瞬間的なバーストでも鳴る。
下のパスは db.serverStatus() の結果のパスである。各 shard の primary で読む。
| serverStatus のパス | 意味 | 止まった primary で予想される形 |
|---|---|---|
wiredTiger.concurrentTransactions.write.available |
残りの write ticket 数 | 0付近にとどまる |
opcounters.insert・.update・.delete |
累積処理件数 | 増加が止まるか急減する |
opLatencies.writes.latency・.ops |
累積の書き込み遅延・件数 | 区間平均の遅延が急増する |
globalLock.currentQueue.writers |
待機中の書き込み数 | 増え続ける |
ホストで予想される形は3つある。
iowait が0に近ければ、CPU はディスクを待たずに命令の実行に使われている。コンテキストスイッチが減るのは、pause ループがシステムコールをしないので、スレッドが自分から CPU を手放さないからである。この2つの解釈は、第3/6回のエンジンソースの分析から導いた推論である。
globalLock.currentQueue.writers は、ロック待ちと ticket 待ちを合わせて数える。r4.2.12 のソースでは、この値は状態が kQueuedWriter のクライアント数である（src/mongo/db/stats/lock_server_status_section.cpp:76-83）。lock_state.cpp でこの状態になるのは、次の3つの場合である。
この値が増えたからといって、ロック競合と断定してはいけない。ticket が尽きても同じ値が上がる。
下は疑似コードである。指標名は serverStatus のパスで書いた。収集器（exporter）が出す実際の指標名は確認していないので、環境に合わせて変える。しきい値はすべて例示値である。
# 의사 코드. 각 shard primary마다 평가한다. 임계치는 예시값.
ALERT MongoPrimaryWriteStalled
WHEN
# 1) 엔진 입구가 막혔다
wiredTiger.concurrentTransactions.write.available <= 2
# 2) 들어오려는 쓰기가 있다
AND globalLock.currentQueue.writers > 10
# 3) 처리량이 늘지 않는다 (1분 증가율이 지난주 같은 시각의 10% 미만)
AND rate(opcounters.insert + opcounters.update + opcounters.delete, 1m)
< 0.1 * baseline_same_hour_last_week
# 4) CPU는 명령 실행에 묶여 있다
AND host.cpu.user >= 90%
AND host.cpu.iowait < 5%
FOR 2m
SEVERITY page
NOTE "heartbeat가 정상이어도 자동 failover는 일어나지 않는다. 대응 절차 문서를 연다."
区間平均の書き込み遅延は、累積値の差から求める。
avg_write_latency_us(1m) =
delta(opLatencies.writes.latency, 1m) / delta(opLatencies.writes.ops, 1m)
書き込みが1つも終わらなければ、分母が0になる。このときは、完了件数が0であるという事実をそのままシグナルとして使う。
7.0 からは、条件1をそのまま使えない。7.0 は ticket 数を動的に調整する。そのため 7.0 のドキュメントは、残りの ticket 数（ticket availability）が長く0のままでも過負荷のシグナルとはみなさないと記している。6.0 以下では、同じ状況が過負荷のシグナルである。7.0 以上では、条件2〜4を中心に見る。
serverStatus の指標は間接的なシグナルである。小さな書き込みを定期的に送って、終わるかを測るプローブ（probe）のほうが直接的である。下は実行で検証していない mongo shell の例である。
// 예시: 외부 감시 프로세스가 30초마다 실행한다.
// ops_probe 데이터베이스의 probe 컬렉션에 문서 한 건을 갱신한다.
const started = new Date();
db.getSiblingDB("ops_probe").probe.updateOne(
{ _id: "writer-probe" },
{ $set: { at: started } },
{ upsert: true }
);
const elapsedMs = new Date() - started;
// elapsedMs가 예시 임계치(2000ms)를 넘거나 클라이언트 타임아웃으로 실패하면 알린다.
maxTimeMS は協調型の中断である。操作が自分で中断要求を確認して初めて止まるので、エンジン内で止まった操作は止められない（第4/6回を参照）。primary の指標より先に、アプリケーションで異常が見えることが多い。一般論として予想される順序は次のとおりである。
アプリケーションの再試行がサーバーに待機中の操作をさらに積み上げる構造は、第2/6回で扱う。
- heartbeat と
rs.status()の青信号だけを見て、DB を原因から外してはいけない。 heartbeat はエンジンを経由しないので、primary の状態表示も正常のまま残る（ソースに基づく推論）。- Flow Control の設定を変えても、この状態は解けない。 Flow Control は、lag が大きいときに入口で書き込みを遅らせるだけである。
- Watchdog を有効にしても、この状態は検知されない。 Watchdog はファイルシステムの無応答だけを見る。
- スループット低下単独のアラートは誤検知が多い。 待ち行列の増加と組み合わせる。
- 4.2 にエンジンの進行状況で primary を降格させる機能が本当にないかは、ドキュメントとパラメーターをすべて確認していない。
- エンジンが止まっている間も heartbeat が応答するという結論は、r4.2.12 のソースを読んで導いた推論である。実際に再現していない。
opcounters・opLatencies.writesのフィールド定義を、4.2 のドキュメント原文と突き合わせていない。- mongos が shard への接続を得られないときに出すエラーの正確なコードと名前は確認していない。
- 収集器（exporter）が使う実際の指標名は確認していない。
- シャードクラスタで shard ごとに書き込みプローブを置く具体的な方法と副作用は検証していない。
- 7.0 以降のバージョンで、heartbeat の処理経路と Flow Control の計算式が変わったかは確認していない。