EKSでEBSのReadIOが高騰した話

f:id:cloudfish:20200116173700p:plain:w200

はじめに

あるシステムのステージング環境を運用している中で、EKSクラスタのワーカーノードが頻繁にダウンするというか事象が発生しました。
色々な調査の末、なんとか解決できましたので発生の経緯と対応内容を書いておきたいと思います。

環境

EKS（1.14）
ワーカーノード（インスタンスタイプ：t3.medium）

発生経緯

あるサービスのステージング環境を作成し開発側に引き渡し、アプリのデプロイが行われシステムテストが進められていました。

突然のNot Ready

開発担当からシステムからレスポンスがなくなったと連絡があったので、確認したところノードのステータスがNot Readyとなっていました。
開発作業に支障が出ていたため、とりあえず該当のEC2を再起動して復旧させました。
その後メトリクスをざっと確認したとところCPUが100% でしばらく張り付いていたので、該当時間帯にCPU使用率の高かったコンテナを調べて開発側に連絡して対応しました。開発中なのでよくあることだと思い、この時はそれ以上深追いもしませんでした。

以降1日1回程度Not Readyが発生

数回は再起動で対処していたのですが、流石に頻度が多くなってきていたのでインスタンスタイプをt3.mediumからc4.largeに変更ししました。別件で手を取られていたこともあるのですが、安易にタイプ変更をおこない一旦様子を見ることにしました。
が、それでも相変わらずNot Readyとなるため、本格的に原因調査することにしました。
その時点でやっと気が付いたのですが、当初見ていたメトリクスがCloudWatchから取得していたものではなくホスト上のメトリクスだったため実際は張り付くまでCPUが高くもなくCPUクレジットを使い切っている状況でもなかったことが分かりました。ここは始めにしっかり見るべきところだったと思います。

EBSの読み取り高負荷

CPU使用率をよく見たところのIOwaitの占める割合が異常に高いことに気がつきました。
そこでEBSへの読み込みもしくは書き込みが高くなっているのではと考えメトリクスを確認したところ、読み取りが最大秒間150MiBでしばらく張り付き、バーストバランスを使い切って0%となっていることが分かりました。バーストバランスがなくなるタイミングでNot Readyとなっていたため、原因はEBSのRead高負荷ということが分かりました。

ReadIOが高いプロセスの調査

Not Readyになるトリガーは分かりましたが、EBSのReadIOが高い原因を引き続き調査しました。
バッチ処理を行うPodがそのノードで常に起動していたため開発側でも調査してもらいましたが、特段不審な処理はないようでした。
インフラ面からは、IOの高いプロセスを特定するため、ノードにログインしてiostatコマンドで高負荷プロセスを確認することにしました。
ログ出力のfluentdのIOが高い可能性があることは分かっていましたが、さすがに秒間150MiBは高すぎですが、再発したタイミングでプロセスを確認したところ、ログ出力用のfluentdが秒間100MiBを超えるIOとなっていました。ログの読み込み設定を変更するなど試しましたが、いずれもIOは高騰するため最終的にfluentdのPodを落とすことにしました。
しかしながら、fluentdを落として以降も別のプロセスでIOが高騰し、しかも特定プロセスではなく様々なプロセスのIOが高いという状況となりいまいち原因がつかめませんでした。

ReadIOとメモリ

しばらくプロセスを眺めるもよく分からない状況が続きました。
そして改めて事象発生時のメトリクスを確認して見たとことろ、メモリと相関関係にあることに気がつきました。当初メモリも確認していたものの数百MBの空きがあったことや、OOM killerも発生していなかったので関連をあまり見ていなかったのですが、下のグラフを見るとメモリ使用量がある一定の閾値を超えた時点でReadIOが高騰し始めるように見えました。他の発生時点のメトリクスも同様の傾向を示していましたのでおそらくReadIOが高騰するトリガーとしてはメモリ使用量だということが分かりました。同時にCPUも上がっていますが、これはReadIOが高騰した結果、IO待ちが発生してCPU使用率が上がったものと考えられます。そのため、今回の発生順としては、メモリが使用率が上がった結果、ReadIOが高騰し、それによりCPU使用率も上がったものと推測できます。
f:id:cloudfish:20200130191737p:plain