長く悩んだサーバー障害を、実は Datadog Bits AI が6分で原因特定していた話

何がすごいのか

Datadog Bits AI が、原因をとっくに特定していたこと

背景：

学習用のUbuntuサーバーを生徒6人で共有して、Node.jsとMySQLを使ってCRUDアプリを開発するプログラミング教室でのこと。生徒はVS CodeでサーバーにSSH接続してプログラミングを学んでいる。

何が問題だったか：

複数の生徒が同時にサーバーへSSH接続し、順調に学習している。ほとんど問題ないのだが、数ヶ月に一度程度、SSHが繋がり難かったり、SSH再接続ができなかったりする問題に悩まされていた。ネットワークの調子がわるいのかとしばらく待つとSSH再接続が復旧する。

なぜ解決できなかったのか：

SSHが繋がり難いときは、サーバーOS にログインできないので調べようもなく、仕方なくDatadogのダッシュボードでCPU使用率やプロセスのモニタリングを眺めながら「なんとなく遅いかな」で諦めていた。

これを何度か繰り返している。VS Codeではなく、Windows のコマンドプロンプト[CMD]であればSSH接続できたので、ターミナルのコマンドで $ free -h や $ ps aux を実行したり、/var/log/auth.log を眺めたりしていた。

事象が再発

ある土曜日の午前、また同じことが起きた。
教室には講師と生徒の二人がいつものようにVS Codeで学習していた。30分くらい経過したら、生徒が「ターミナルが応答しない」と言い出し、数分後に講師のターミナルも応答しなくなった。しばらくすると二人のターミナルが応答し学習を継続した。と思いきや、またまたターミナルが応答しない。今度は長い。

Datadog ダッシュボードを開き、ログモニタリングを調べていると、たぶん自宅からリモートでセルフ学習（宿題）しているのだろう別の生徒がサーバーにログインしている。プロセスモニタリングでは、生徒の誰かの PM2 プロセスがCPU高負荷になっている様子が把握できる。しかし、これらが VS Code のターミナルが応答しない原因とは思えないので、諦めてターミナルが応答するのを待っていた。

Bits AI SRE が原因を特定していた

Datadog ダッシュボードでの調査を諦めてターミナルの応答を待っている間に Bits AI はとっくのとうに原因分析を完了していた。Bitsが複数の仮説・被疑箇所とそれらの検証を終えて、調査レポートを作成していたので、下記にその日の履歴と、Bits AI SRE に教えてもらった技術的な根本原因を記録する。

Bits AI は下記一連の調査を自動実行していた：

• 監視アラートを起点に自動調査を開始
• 複数の仮説を生成
• 仮説を検証し、原因を特定
• さらに…

🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾🐾

サーバー構成

生徒は VS Code でSSH接続してJavaScript, HTML, SQL, Linux を学んでいる。

コンピュートリソース状況

午前09:30頃からCPU負荷が上昇し、10:20頃から10:45頃までCPU利用率が100%を継続している。4GBメモリは常時3GB使っているがCPUの傾向にあわせて増えている。

プロセスモニタリング

Datadog でプロセス単位のCPUとメモリリソースを調べることができる。プロセス単位では10~20%のCPU利用率、メモリは117MBが最大のようなので、見ているだけで原因を特定できなかった。

Bits AI - SREインシデント調査

いつもは使っていなかった Bits AI をたまたま開いてみた。

英語で表示されるが、ブラウザの翻訳で日本語表示ができる。
メッセージは「4GBメモリのサーバーで メモリ不足が発生し、スワップメモリの退避I/Oが大量発生している 。システム負荷が19~43倍に跳ね上がった結果、全てのサービスが応答不能になった」とのこと。

仮説を検証していた

Bits AI によると生成された仮設（GENERATED HYPOTHESES）が５つあり、２つの検証済み［VALIDATED］ が実際に起きていた減少と一致しており、３つの仮説が無効［INVALIDATED］ は原因ではないと判断されていた。

調査結果の全文を見る

下図は「ホストメモリ枯渇」の報告レポート画面全体である。

仮説の検証

どうやら「アプリのURL監視アラート」をトリガーにして仮説調査がスタートしている。
まず３つの仮説 (1)モニタリングの設定ミス (2)アプリコードの回帰 (3)バックエンドサービス停止 からポート3011の停止を検知しており、次に (1)ホストリソースの枯渇 (2)プロセスOOM Kill の仮説から深刻なリソース不足を検知している、といった順番に検証を進めて、調査結果としてスワップメモリのI/Oにかかるシステム負荷が最大43倍増加していることと結論付けていた。

仮説検証の詳細トレース

そのうえ、検証フロー図だけでなくそれぞれの検証の詳細も報告されていた！

Bits AI との会話

Bits AI にチャットで質問ができるし、正確な値を教えてくれる。

Bits AI の有効化

Datadog メニューの [Bits AI] > [Monitors]
モニタリング設定に対して［AUTO-INVESTIGATE］を有効化した

特定した原因について

ここまで Bits AI による SRE インシデント調査でできる機能を見てきた。
ここから VS Code によるリモートSSH接続がなぜ不安定だったのか原因を特定するまでの流れを振り返る。

VS Code リモートSSH接続が繋がらない理由

VS Code は、サーバー側で VS Code Server を起動し、拡張機能を立ち上げてファイル同期や設定読み込みなど思い処理を行う。今回の障害では、下記事象が発生してリモートSSH接続が途切れたり、繋がり難くなっていたりという状態になっていた。

- メモリ枯渇
　↓
- メモリ大量スワップ
　↓
- 27% のI/O待ち
　↓
- ロードアベレージ 100超過
　↓
- VS Code Server（extensionHost）が、OOM Killで強制停止
　↓
- VS Code Serverの再起動が、無限ループ 

Bits AI による2つの継続調査

この日のプログラミング教室では、VS Code による学習を諦めて、CMDターミナルでのSSH接続でプログラミング学習をした。その間も Bits AI による無人の調査は継続しており、新たな調査レポートが2個報告されていた。

「PM2メモリ容量の制限なし」及び「OOMによるアプリ終了」

「利用可能なメモリがすべて使い果たされた」とは、どういうことか。
複数の生徒が開発した Node.js アプリは PM2 でプロセスを実行している。6人の生徒ユーザーアカウントによる 7個の PM2 プロセスと 30個以上の Node.js ワーカーが実行されている。
PM2 で実行するアプリは、メモリ利用量の上限を設定していないので、それぞれのプロセスが13~16GBの仮想メモリを使い、8~10GBのメモリとディスク間のスワップが増加してシステムCPUが90%以上の負荷がかかり、連鎖的な OOM Kill によって次々とアプリが強制終了させられていたようだ。追加2つの調査報告は、先ほどよりも詳細な仮説検証が行われていた。

私が長い間、誤解していたこと

「物理メモリが足りなくても、仮想メモリ（スワップ）があるから動くはずだ」
これが間違いだった。Bits AI SREのレポートを読んで初めて理解したことは、各プロセスのRSSメモリは数十～数百MB程度だったが、仮想メモリは無制限に使われる設定であり、実際に62GBが予約されていたということ。
レポートによるとスワップされるメモリ量は最大28.5MB/秒であり、I/O待機時間が13～27% に高まり、システム負荷は平常時の19～43倍となった。次に、この報告を確かめることにした。

プロセス毎のメモリリソース

普段は物理メモリだけ見ていたが、仮想メモリも見ることができるのですね。
特に、VS Code Server の仮想メモリが約68GB(63GiB)とドデカイことがわかるが、実際に確保されているわけではないとのこと。物理メモリは580MB(552MiB)とそんなものかなと思ったけれど、4人が同時に VS Code を使うと、物理メモリを約2GB使ってしまう。他にも Node.js アプリがPM2で実行されている。

メモリのスワップを読む

利用可能なスワップメモリ約1.5GBは、午前のプログラミング教室が開始する9時から徐々に利用されて10時前には全て使い尽くしている。プログラミング教室は午後13:30に終了している。
この間ずっと、スワップメモリによるディスクI/Oが続きCPU高負荷な状態であったため、VS CodeによるリモートSSH接続が極端に遅延していたと理解することができる。

Dataog Agent も OOM Kill されていた

サーバーのCPU・メモリリソースを再確認すると、Datadog Agent も停止と再起動していることを確認できた。Datadog Agent が停止している時間帯 10:07 から 10:23 までは、メトリック送信が無かった時間帯となり下図のようなグラフとなって現れる。

なお、図のLoad Averages は「CPUを待っているプロセス数」と「ディスク読み書き(I/O待ち数)」がカウントされる。このサーバーは4vCPUなので、100個を超えるプロセス待ちは異常な状態が続いていたことを意味する。

OOM Killer が発動する条件

Linux が OOM Killer を発動するのは、下記２つの条件が同時に起きたとき。

1. 物理メモリが枯渇した
2. スワップ領域も限界に達した

つまり、どうにもこうにもメモリを確保できないときに、最終手段として oom_score の高いプロセスの順にkillされる。複数要素で決まる oom_score だが、大量のメモリを使っているプロセスはkill候補になる。
そのうえ、VS Code と PM2 の再起動回数の上限を設定していないので、無限に再起動を繰り返す最悪のループに突入してしまったらしい。

恒久対策を考える

原因が特定されたので、今回の障害が再現されないように対策をする。
Bits AI にチャットで質問して、恒久的な是正措置をアドバイスしてもらう。

優先度の高い順に、7つの対策が示唆されました。
そのうえ、モニタリングの改善も提案された！

監視アラートのメッセージに追加するようにチャットに英語で指示すると、アラートには日本語でメッセージを記述してくれた。

更にさらに、Bits AI に指示するための org単位の Bits.md までも用意されているし、自動で指示を書き込んでくれた。

まとめ

• VS Code リモートSSH接続が突然つながらない、遅くなる原因はサーバーのメモリだった
• 何か月も原因がわからず悩んでいたが、Datadog の AI は6分で原因特定していた
• 複数の仮説を検証し、エビデンス、分析レポート、チャット相談、対策示唆ができた
• これからの障害調査は、Bits AI に任せてみたい

AIによる運用（AIOps）はもはや「監視モニタリングのツールや自動化ツール」ではなく、Datadog社 がいうように「夜中でも無人で24時間働き続けるSREの同僚」が現実のものとなっていることを実感した。同じように原因不明の障害に悩んでいる情報システムには、Bits AI の自動調査を有効化してみたい。

🐕🐕🐕🐕🐕犬ぞりの如く、運用者をひっぱって、走って走って走っていきそう。