DatadogのContinuous Profilerを有効にしたら問題が一気に解決した

はじめに

DatadogのContinuous Profilerを有効にしたら、数か月悩んでいたパフォーマンスの問題が10分で解決したので、そのパワフルさを紹介していきます。

＃「Datadogすげー」な記事ではあるのですが、パフォーマンスに影響を与えていた原因自体は.NETの基本的なプログラミングの問題なので、個人的には自爆案件で毎年恒例のやらかしアドベントカレンダーに投稿しようかとも思った内容です。

Continuous Profilerを設定する前の状況

Duende IdentityServerを利用してOIDCのIdPを構築しているのですが、ピーク時はTokenエンドポイントの呼び出しに10秒近くかかりアラートがバシバシ飛んでくる状況で、コンテナのCPU利用率が100%に張り付き、ヘルスチェックに応答できず、次々とOOM killerに殺されるみたいな状況が発生していました（念のための補足ですがDuende IdentityServerには性能劣化の問題はなく、自前のコードが原因です）。

もともとDatadog自体は導入していたので、APMのトレースを確認しては見たものの目立ったSPANは表示されず、特定のエンドポイントの原因というよりは何らかの原因によりCPU使用率が高騰し全体的に処理が遅くなっているということ以外はわからない状況でした。

また、調査のため１からDuende IdentityServerで構築したサンプルでは同様の問題が発生しないので、自前で実装したコードのどこかに問題はあるということだけはわかっていたのですが、とりあえず動いているという状況もあったのでコンテナ台数を増やして運用していました。

DatadogのContinuous Profilerとは？

DatadogのContinuous Profilerはメソッドの呼び出しレベルでパフォーマンスを追跡して継続的に監視するツールです。CPU、メモリ、I/Oのボトルネックを視覚的に表示してくれるので外形的な監視だけではわからない問題を特定することができます。

下のグラフはDuende IdentityServerのサンプルに、意図的に性能を劣化させるようなコードを仕込んだリクエストをContinuous Profilerで表示した例です。小さくて見づらいと思いますが、全体で930msかかる処理は大きく3つのブロック、2つのメソッド（HasDuplicate、FindClientByIdAsync）で遅くなっていることがわかります。

Continuous Profilerを有効にする

.NETの場合Datadogをすでに導入しているのであれば、環境変数を追加するだけでContinuous Profilerが有効になります。詳細は.NET プロファイラーの有効化を参照してください。

前述の通りContinuous Profilerを有効にすると外形的な監視からはわからないようなメソッドごとの処理速度などを観測できるようになりますが、若干パフォーマンスのペナルティーがあるので気を付けてください。筆者の環境ではContinuous Profilerを有効にすることで2%程度のCPU増加が観測されました（点線が前週のCPU利用率、全体的にCPU利用率が上昇していることがわかる）。

原因を探る

Continuous Profilerで問題のメソッドを見ると、HasDuplicatesやFindClientByIdAsyncが内部で持っているClientの列挙に問題がありそうだなというのがすぐにわかります。

クライアント定義の数なんてせいぜい数十の配列を列挙するだけで？と思いながらプロファイルの表示対象をOnly My CodeからAll Codeにすると...

あっ、単なる配列じゃなくてIConfigurationの検索から毎回評価されているようです。これは遅そうだ😢（ここまでプロファイラーを見始めてから5分）

修正する

IdentityServerの初期化コードで設定を引き渡している部分です。これまでIEnumerableで引き渡している部分をToArrayで具体化してから引き渡してあげます。

Program.cs

services.AddIdentityServer()
-    .AddInMemoryApiScopes(configuration.GetApiResourcesSection())
-    .AddInMemoryApiResources(configuration.GetApiResourcesSection())
-    .AddInMemoryIdentityResources(GetIdentityResources())
-    .AddInMemoryClients(configuration.GetIdentityClientsSection())
+    .AddInMemoryApiScopes(configuration.GetApiResourcesSection().ToArray())
+    .AddInMemoryApiResources(configuration.GetApiResourcesSection().ToArray())
+    .AddInMemoryIdentityResources(GetIdentityResources().ToArray())
+    .AddInMemoryClients(configuration.GetIdentityClientsSection().ToArray())
    ...略...

同一メソッド内であれば、IEnumerableを複数列挙するようなコードはVisual Studioが指摘してくれるのですが、今回のようにミドルウェア内部で列挙されるようなものは見つけ出すのがかなり困難です。Continuous Profilerを導入していなかったら原因解明までにあと何か月かかったことか、、、

確認する

上記の修正を適用したタイミングから、サイト全体のレイテンシ（aspnet_core_request）は3秒から50ミリ秒に、CPU利用率は30%から0.3%まで改善しました。

おわりに

IEnumerableのまま渡していたのは過去の自分なので完全に自爆案件なのですが、改めて可観測性の重要さを知る機会でした。