📖

Goエンジニアがk8sクラスタでノイジーネイバー問題に遭遇し、解決するまでの記録

2022/10/04に公開

1件

これは、とある僕のチームが運用しているWebアプリケーション　(Go製) の、ヘルスチェック用エンドポイントの (リクエストハンドラーの) コードです。リクエストがきたら200 OKを返すだけの、シンプルな実装です。

func health(w http.ResponseWriter, _ *http.Request) {
    w.WriteHeader(http.StatusOK)
}

ところが、たったこれだけの処理しかしていないエンドポイントのレイテンシが、ある時からピーク時に著しく劣化するようになり、ひどい時には最大3.4秒もかかるようになってしまったのです。

なぜこのようなことになってしまっていたのか、またそれをどのように調査し、解決したのかについて解説します。

システム概要

今回問題となったWebアプリケーションはGoで書かれています。実行環境は Kubernetes (GKE) で、クラスタ上に10個ほどのPodが常時展開されています。
平時、Pod全体でおよそ1000〜2000rps程度のリクエストが来ており、夜間帯になると3000rps程度にまで負荷が上昇する傾向があります。

調査

原因を調査したところ、わかったことがいくつかありました。

1. 全てのエンドポイントにおいて、低確率で著しくレイテンシが悪化することがある

冒頭に取り上げたのはヘルスチェックエンドポイントでしたが、アプリケーションが公開するその他すべてのエンドポイントで同じ現象がみられることがわかりました。
それら一つ一つが異なる処理をしており、外部APIをコールするものもあれば、Redisに依存するもの、あるいは外部依存が一切ないものまで様々ですが、すべて等しく性能劣化していることがわかりました。ただし、その確率自体は 0.1〜0.2%程度で、発生割合自体は少ないことも確認できました。

また、その確率には波があり、AP へのリクエスト数のトレンドとほぼ一致しており、アプリケーションへの負荷が高まるほど発生確率が高まる、ということも推定されました。
下記のグラフは全エンドポイントへの総rpsの時間推移です。

下記はリクエスト全体の中で、極端にレイテンシが高い (500ms以上の) リクエストが含まれる割合の時間推移を示しています。上のグラフと波がほぼ一致していることがわかります。

2. 特に、アクセスログの出力処理に時間がかかっている

1 で述べたように、すべてのエンドポイントが一律で性能劣化していることから、僕は「全エンドポイントの共通処理部分に問題があるのではないか？」という仮説を立てました。

このアプリケーションでは、全エンドポイント共通で必要になる処理 (たとえば「リクエストに含まれる特定ヘッダー値の抽出処理」や、「モニタリング系 SaaS へのデータ送信処理」など) をミドルウェアとして実装し、各種リクエストハンドラーに適用しています。

(このWebアプリケーションでは、Webフレームワークとしてchiを採用しており、それに準拠した実装になっています)

ミドルウェアの例


func ExtractUserID() func(http.Handler) http.Handler {
	return func(h http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			userID := r.Header.Get("X-User-Id")
			if userID == "" {
				userID = "N/A"
			}

            ctx := r.Context()
			ctx = context.WithValue(ctx, "userID", userID)

			h.ServeHTTP(w, r.WithContext(ctx))
		})
	}
}

このアプリケーションでは処理のトレーシングに Datadog (OpenTracing 準拠) を利用しており、これらの処理時間を計測すべく、全てのミドルウェアに対して Span を切ることにしました。

Spanを切るためのミドルウェア


func CreateSpan(name string) func(http.Handler) http.Handler {
	return func(h http.Handler) http.Handler {
		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			opts := []tracer.StartSpanOption{}
			ctx := r.Context()

			if s, ok := tracer.SpanFromContext(ctx); ok {
				sctx := s.Context()
				opts = append(opts, tracer.ChildOf(sctx))
			}

			span := tracer.StartSpan(name, opts...)
			defer span.Finish()

			ctx = tracer.ContextWithSpan(ctx, span)
			h.ServeHTTP(w, r.WithContext(ctx))
		})
	}
}

Spanミドルウェアを適用するイメージ


r := chi.NewRouter()

r.Use(middleware.StartSpan("middleware1"))
r.Use(middleware1)
r.Use(middleware.StartSpan("middleware2"))
r.Use(middleware2)
r.Use(middleware.StartSpan("middleware3"))
r.Use(middleware3)
...

すると、次のような結果が得られました。下記のグラフでは横軸が時間軸で、また最も上にある長方形の始端と終端が処理全体をカバーする関数の処理期間を示しており、そしてその下に積まれている長方形ひとつひとつが各種middlewareやリクエストハンドラーの処理期間になります (左下の細い線状のspanが、ハンドラーの期間を示しています) 。

これをみると、レイテンシが異常に長いリクエストについては、アクセスログの出力に大半の処理時間が使われていたことがわかります。
平時はせいぜい数十〜百 μs で終わっているアクセスログ出力処理が、一定確率で数百 ms、下手したら 1 秒以上かかってしまっている状況であることがわかりました。

3. 特定の (Kubernetes) Node 上に配置された Pod だけ性能劣化している

Datadog上で性能劣化しているリクエストについて確認していると、それらは特定のPodでのみ発生していることがわかりました。普段10個ほどのPodが展開されているうち、性能劣化がみられるのは1〜2個ほどでした。また、DeploymentのRolling updateが実施されてPodが再生成されても、常にいずれかのPodで性能劣化が発生している状況に陥っていました。

また、性能劣化しているPodは全て特定のNodeに配置されたものであることもわかりました。このことから、特定Nodeに配置されたPodでのみレイテンシ悪化が引き起こされていることが類推されます。

対応

調査でわかったことをまとめると、以下のようになります。

全てのエンドポイントにおいて、低確率で著しくレイテンシが悪化することがある
特に、アクセスログの出力処理に時間がかかっている
特定の (Kubernetes) Node上に配置されたPodだけ性能劣化している

ここから、僕は2つのアプローチで改善を試みました。

アクセスログ出力処理の性能改善

このアプリケーションではログライブラリとしてzapを使っています。zap自体は同種の他のライブラリよりも速いと言われています。しかし、調査の中でアプリケーションの中での使い方に少々問題があることがわかりました。

zap はログの構造化をサポートしており、アプリケーションではログをJSON形式で出力していたのですが、ログ構造体をJSON化する処理のコストはそれなりに高くつきます。なかでも、zap.Anyという任意の構造体をログフィールド化するAPIでは、処理の中でリフレクションが用いられることがあり、処理が重くなる場合があります (公式による注意) 。ですが、件のアプリケーションではこれが多用されていたため、改善のためこれらをzapcore.ObjectMarshalerやzapcore.ArrayMarshalerに置き換えることで、改善ができないかと考えました。

修正前のログ出力コードは以下のようなものでした。

修正前


zap.Info("access_log", 
    zap.Int64("latency", latency),
    zap.String("env", env),
    zap.Any("http", map[string]interface{}{
        "method":      r.Method,
        "useragent":   r.UserAgent(),
        "version":     r.Proto,
        "path":        r.URL.Path,
    })
)

このとき、 (Datadogに収集された) CPU Profileの図をみると、以下のようになっています。ログ処理全体のCPU Timeが1.58sで、うちJSONシリアライズ処理 (*encodeState.marshal) で7〜8割の時間を使っていることがわかります。

これを、次のようなコードに書き換えました。

修正後


zap.Info("access_log", 
    zap.Int64("latency", latency),
    zap.String("env", env),
    zap.Object("http", func(enc zapcore.ObjectEncoder) error {
        enc.AddString("method", r.Method)
        enc.AddString("useragent", r.UserAgent())
        enc.AddString("version", r.Proto)
        enc.AddString("path", r.URL.Path)
        return nil
    })
)

この修正を適用した後のCPU Profileの図が以下になります。ログ処理全体のCPU Timeが440msまで短縮されており、修正前と比べて1/3ほどになったことが確認できました。JSONシリアライズ処理の長さがかなり改善されているのもわかります。

しかし、改修後も依然としてレイテンシ劣化は起こり続けてしまっていて、このアプローチは本件の解決策にはなり得ませんでした。先述の通りレイテンシ劣化の発生確率が低くて、CPU Profileが計測されているときにそれが起こっておらず、Datadogから見れるCPU Profileはそうした状況を反映できてなかったのではないかと僕は考えています。なんにせよ真のボトルネックは別にあるのではないか、ということが伺えました。

Nodeの性能改善

調査結果をみると、k8sクラスタを構成するNodeのうち、特定のNode上にあるPodでのみ性能劣化が起こっていることから、当該Nodeが他と比べそもそもスペックが低いとか、Node VMが乗っている実機サーバーに何らかの問題があるとか、そういったことが原因に関わっているのではないか？ということを考えました。

上記に記したアクセスログ処理自体の改善をはかるのと同時並行で、Nodeの性能問題について、部署内のSREチームに調査を依頼しました。すると、特定NodeにおけるDisk I/Oで過剰にスロットリングが発生していたという報告が得られました。

下記のグラフは、横軸を時間軸とし、縦軸にNodeごとのinstance/disk/throttled_write_ops_countメトリクスの値をプロットしたものです。これをみると、特定のNodeだけ非常に高い値を維持していることがわかります。

SREチームの見解では、おそらくそのNodeにだけ存在するPodによって大量のDisk Writeが発生しており、Disk I/Oが詰まった状態になっていて、結果Node上にある他Podのコンテナログ出力時に時間がかかる状態になっているのではないか、ということでした。要は、ノイジーネイバー問題が発生していたということです。アクセスログの出力処理に時間がかかっていたのも、これが原因であると考えられるとのことでした。

これを解決するためには、当該のPodをWebアプリケーションのPodと同居させないようにする必要がありました。今回は、そのPodに載っているアプリケーションのEOLが予定されていたため、SREチームに当該Podを削除してもらうこととなりました。

原因と思しきPodがNodeから削除されると同時に、Webアプリケーション性能が著しく改善しました。具体的には、アプリケーションにおいて処理に500ms以上かかっているリクエストの数が激減したのです (縦軸がレイテンシが劣化したリクエストの数で、横軸は時間軸です) 。アクセスログ出力にかかる時間が膨らむといった事象もみられなくなりました。

その後、今に至るまで性能劣化はみられておらず、問題は完全解決したとみられます。

振り返り

特にマルチテナントで運用されるKubernetesクラスタにおいては、ノイジーネイバー問題は避けて通れない課題になるかと思います。今後もKubernetes上のアプリケーションの性能劣化が発生した場合、そうした可能性も念頭において調査を進めるとスムーズになるように思いました。

しかし今回は、ノイジーネイバー問題の主因となっていたアプリケーションが幸いにもEOL予定だったため、それを削除するという判断ができましたが、クラスタの中で稼働しているPodを恒久的に削除する、ということができる場面は限られるかと思います。ですが、そうした場合でもNode / Pod Affinityを設定することで、問題のあるPodだけを特定Nodeに隔離し、それ以外のPodは別Nodeに退避させるなどの対応が可能です。状況に応じて、k8sクラスタ運用者と適切な対応策を検討しましょう。

Discussion

GCPであればログの出力をgRPCで非同期にすることもできます。
私の記事にあります。