GKEのNoisy Neighbor問題はMetrics Explorerからは見えないことがある
Google CloudのMetrics Explorerには豊富なメトリクスが揃っており、一般的な監視であればこれらを見るだけで十分なことも多い。
しかし、メトリクスのサンプリング間隔によって、実際に起きている問題が覆い隠されてしまうことがある。
私はかつて、Google Kubernetes Engine (GKE) 上で動かしているAPIサーバーのレスポンスタイムが時折大きく悪化するのにMetrics Explorer上では異常がないように見えていたという問題に遭遇したことがある。
蓋を開けてみれば同じGKE Node上で動く短命なバッチがCPUを食い潰してAPIに影響を与えていたというものであった。いわゆるNoisy Neighbor問題である。
実際にこのサンプリング間隔の罠にどのようにハマったのかを紹介する。
なぜか時折遅くなるAPIサーバー
Google Kubernetes Engine (GKE) 上で動かしている開発環境用APIサーバーのレスポンスタイムが、時々悪化するという問題があった。
あるAPIリクエストは通常200ms程度で返るのに、遅いときには同じ条件でも4秒ほどかかることがあった。しかも再現性がなく、悪化するタイミングに明確なパターンが見えなかった。
その症状が起きていたときの2台のGKE NodeのCPU利用率(instance毎のMax値)はMetrics Explorerで次の通りになっていた。
CPU利用率は35%台に留まっており、CPUを使い切っているようには見えない。
次に当該VMのLoad Average (1m)は次の通りである。
多少のスパイクがあるとはいえ2コアCPUのNodeに対して平均1.5～2ぐらいで常時大きく跳ね上がっているわけではない。CPU利用率のグラフと合わせて見てしまうと「CPUが詰まってしまっている」とまでは判断しづらかった。
（後からグラフを見直してみると、スパイクがあるので短時間の負荷集中があったと気づけたかもしれないが…）
APIサーバーで実際に起きていたこと
Metrics Explorerを見ても決め手がなく、データベースも詰まっていない、APIサーバーに顕著なエラーログも出ていない。何が原因なのか分からないという手詰まりの状態だったが、開発環境用のAPIサーバーでもあったため、しばらくは深追いしていなかった。
しかしある日思い立って、GKEの当該NodeにSSHログインし、htopを実行し、CPUやメモリーの利用状況をリアルタイムで見ることにした[1]。
すると、以下のようにCPU 0、CPU 1ともに100%に張り付いている時間が20～30秒間ほどあり、そのときのLoad Averageは7.44に達していた。
htopのプロセスリストを見ると、Railsバッチタスクが複数同時に実行されているのがわかる。これらの同時に走っていた複数のバッチがCPUを食い尽くし、同じNode上で動いているAPI Podが割を食っていた。冒頭で述べたNoisy Neighbor問題である。
バッチが動いていないタイミングでは、CPU利用率は6～11%程度まで下がっていた。
ではなぜCPU食い潰し問題がMetrics Explorerではうまく可視化されていなかったのか。
これらのCPUを食い潰すバッチは1回あたり20～30秒程度で完了するものであった。Metrics ExplorerでのVMのCPU利用率のメトリクスは60秒間隔のサンプリングであるため[2]、60秒のうち20～30秒間だけCPU 100%だったとしても、単純に1分間の平均として均すと約33～50%にしか見えない。これがMetrics Explorerを見ているだけでは異常がないように見えてしまっていた理由である。
(余談)なぜバッチがCPUを食い潰していたのか
バッチを動かしているPodにはCPU Limitsが設定されておらず、Podが利用するCPU使用量に上限がなかった。そのため、複数のバッチが同時に走るとNode上の空いているCPUを一気に使い果たし、結果同じNode上の他Podに悪影響を与えてしまっていた。
Limitsを設定しておけば使用するCPU量の上限を設定できるので、バッチPodにCPU Limitsを設定することで無事APIのレスポンスタイムを安定化することができた。
まとめ
Metrics Explorerは強力なツールだが、サンプリング間隔に注意を払った上でデータを見る必要がある。ごく短時間だけ発生するような高負荷状態は、サンプリング間隔の狭間に埋もれてしまいグラフ上には上手く現れないことがある。
今回のケースでは、『開発環境のAPIがたまに遅いなぁ』とAPIのレスポンスタイムの悪化には気づいていたものの、Metrics Explorerのインフラ側メトリクスからは原因を特定できなかった。最終的にhtopで生のデータを直接確認してはじめてNoisy Neighborが原因だと判明した。
この経験から得られた教訓は2つある。
1つは、APIのレスポンスタイムのp99/p95値を監視してアラートを出す仕組みを持っておくことで、インフラ側メトリクスからは見えない問題の存在に気づくことができるということ。
もう1つは、見ているメトリクスのサンプリング粒度を把握しておき、必要であれば実際にマシンにログインして（サンプリングされてない）生のデータを確認する選択肢を持っておくことである。Linux Performance Analysis in 60,000 Milliseconds - Netflix TechBlogには、そうした場面で役立つコマンドが書かれている。
Discussion