以下の内容はhttps://tech.guitarrapc.com/entry/2025/01/19/235900より取得しました。

最終更新日

.NET CLR監視のススメとClrProfilerの公開

C#

.NET CLR1情報を取得するライブラリを数年前に作ったのですが、改めて便利なので公開しました。今回は.NET CLR監視のススメです。

guitarrapc/ClrProfiler

.NET CLR情報とは

.NETにはCLR event tracingといわれる仕組みがあります。これは簡単にいうとパフォーマンスカウンターで取得していた.NETアプリケーションのメトリクスをWindowsとLinux両方でインプロセス取得できるようになる仕組みです。 .NET Core 2.2からCLRイベントを受信するためにEventListenerクラス導入されました。さらに.NET 3.0以降はEventPipeべースのインフラ基盤が整備され、別プロセスからもこのイベントを取得できるようになりました。2

CLR情報には、GCやスレッド情報が含まれるため、アプリケーションのパフォーマンスチューニングやデバッグに役立ちます。どんな情報がとれるかのドキュメントがわかりにくいのですが、.NET Framework時代のCLR ETW Events - Microsoft Learnが役に立ちます。

image

EventListenerとEventPipeの使い分け

EventListenerとEventPipeは似たようなことができますが「取り扱いしやすさ」で選べばいいでしょう。私はインプロセスならEventListener、外部ツールで取得するならEventPipeと使い分けています。このあたりはEventCounters in .NET - Microsoft Learnが詳しいです。

ざくっと比較すると次のようになります。

image

特徴 EventListener EventPipe
利用場面 インプロセス監視 プロファイリング・詳細解析
実装の簡単さ 非常に簡単 設定やデータ処理が少し複雑
カスタマイズ性 高い 中程度
データ収集規模 リアルタイム・特定イベント向け 大規模トレースや複数プロセス向け
依存性 アプリケーション内のみで完結 外部ツールやファイル書き出しが必要

EventListenerはアプリケーションの中で、どのイベントを受け取るかフィルタリングしつつ、どう処理するかを決めることができます。EventListnerは複数プロセス間で統合的な監視はできませんが、コンテナで利用するにも同一プロセスなケースが99％でしょう。CLRメトリクスを取得してDatadogやGrafanaで可視化したい、というときにEventListenerを使うといい、ぐらいの認識でいいでしょう。

EventListener API

EventListenerを使うと、アプリケーション内のEventSourceイベントを受信して独自処理を登録できます。CLRイベントに対してリスナーを登録することで、GCが起こったよ、スレッドプールが増減したよ、といった情報を取得できます。便利!例えば、System.Runtimeを1秒ごとに公開するなら次のようなコードでかけます。OnEventSourceCreatedでEventSourceを登録&有効化し、OnEventWrittenでイベントを受信します。

using System;
using System.Collections.Generic;
using System.Diagnostics.Tracing;

public class SimpleEventListener : EventListener
{
    public SimpleEventListener()
    {
    }

    protected override void OnEventSourceCreated(EventSource source)
    {
        if (!source.Name.Equals("System.Runtime"))
        {
            return;
        }

        EnableEvents(source, EventLevel.Verbose, EventKeywords.All, new Dictionary<string, string>()
        {
            ["EventCounterIntervalSec"] = "1"
        });
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        if (!eventData.EventName.Equals("EventCounters"))
        {
            return;
        }

        for (int i = 0; i < eventData.Payload.Count; ++ i)
        {
            if (eventData.Payload[i] is IDictionary<string, object> eventPayload)
            {
                var (counterName, counterValue) = GetRelevantMetric(eventPayload);
                Console.WriteLine($"{counterName} : {counterValue}");
            }
        }
    }

    private static (string counterName, string counterValue) GetRelevantMetric(
        IDictionary<string, object> eventPayload)
    {
        var counterName = "";
        var counterValue = "";

        if (eventPayload.TryGetValue("DisplayName", out object displayValue))
        {
            counterName = displayValue.ToString();
        }
        if (eventPayload.TryGetValue("Mean", out object value) ||
            eventPayload.TryGetValue("Increment", out value))
        {
            counterValue = value.ToString();
        }

        return (counterName, counterValue);
    }
}

詳しい使い方はEventListenerクラスを見ていただければ。参考になるサイトをおいておきます。

ClrProfiler

ClrProfilerはEventListenerを使ってCLR情報を取得、Datadogと連携するためのライブラリです。数年前に書いて、実環境で使っていたのですが、Private Repositoryのまま放置していたので改めて公開しました。長い間本番で叩かれているのでパフォーマンス的な問題はないはずですが、もしあればPRお待ちしています。3

本ライブラリは、CLR情報を取得するClrProfiler、Datadogへメトリクスを送信するClrProfiler.DatadogTracingに分かれています。ClrProfilerはEventListenerを使ってCLR情報を取得し、ClrProfiler.DatadogTracingはDatadogへメトリクスを送信します。ClrProfilerは依存ゼロなのでアプリケーションに組み込みやすくなっています。究極には自分でEventListenerを書けばいいのですが、とりあえずCLR監視をしたいときには便利に使えます。

たとえば、コンソールアプリケーションで使う場合は次のようになります。LoggerFactoryさえ渡せばいいので、ASP.NET CoreのDIパイプラインに登録してあげてもいいでしょう。

// Run Client (datadog agent with udp)
var dogstatsdConfig = new StatsdConfig
{
    StatsdServerName = host,
    StatsdPort = port,
    ConstantTags = ["app:YourAppName"],
};
DogStatsd.Configure(dogstatsdConfig);

// enable clr tracker
var tracker = new ClrTracker(loggerFactory);
tracker.EnableTracker(); // required, enable clr tracker explicitly
tracker.StartTracker();

サンドボックス用のコンソールアプリ(SandboxConsoleApp)を開始すると、動作確認のためUDPサーバーを起動してDogstatsDからメトリクスを受信します。次のようなメトリクスが送られているのがわかります。

clr_diagnostics_event.gc.startend_count:11|c|#app:SandboxConsoleApp,gc_gen:2,gc_type:0,gc_reason:induced
clr_diagnostics_event.gc.suspend_object_count:45|c|#app:SandboxConsoleApp,gc_suspend_reason:gc
clr_diagnostics_event.gc.startend_duration_ms:0.5566|g|#app:SandboxConsoleApp,gc_gen:2,gc_type:0,gc_reason:induced
clr_diagnostics_event.gc.suspend_duration_ms:0.9653999999999999|g|#app:SandboxConsoleApp,gc_suspend_reason:gc
clr_diagnostics_event.threadpool.adjustment_avg_throughput:504.68830819370083|g|#app:SandboxConsoleApp,thread_adjust_reason:warmup
clr_diagnostics_event.threadpool.adjustment_new_workerthreads_count:32|g|#app:SandboxConsoleApp,thread_adjust_reason:warmup
clr_diagnostics_event.gc.suspend_object_count:145|c|#app:SandboxConsoleApp,gc_suspend_reason:gc
clr_diagnostics_event.gc.startend_count:10|c|#app:SandboxConsoleApp,gc_gen:2,gc_type:0,gc_reason:induced
clr_diagnostics_event.gc.suspend_duration_ms:0.7823|g|#app:SandboxConsoleApp,gc_suspend_reason:gc
clr_diagnostics_event.gc.startend_duration_ms:0.5456|g|#app:SandboxConsoleApp,gc_gen:2,gc_type:0,gc_reason:induced
clr_diagnostics_event.threadpool.adjustment_avg_throughput:509.89785405018245|g|#app:SandboxConsoleApp,thread_adjust_reason:warmup
clr_diagnostics_event.threadpool.adjustment_new_workerthreads_count:32|g|#app:SandboxConsoleApp,thread_adjust_reason:warmup

Datadogで可視化

CLRメトリクスは取得しても意味がなく、それを可視化してパフォーマンスチューニングとして利用できる形で使うことが重要です。ClrProfilerはDatadogで可視化を想定しています。

CLRメトリクスをDatadogダッシュボードで見られるようにすると、アプリケーションの動作を可視化できます。たとえばGCの回数を可視化すると、SOHによるGCが多いのか、Gen2が多いのかといったメモリ動作を理解しやすくなります。スレッドプールの調整回数を表示すると、タスクを無駄に使ってないか、スレッド競合していないかが見えてきます。Datadogはタグ設計次第で詳細度を変えられるのであとは使い方次第です。

これまで.NET CLR監視をしてきて、Datadogで可視化するときによく使うクエリをいくつか紹介します。

GCの回数やサイズを可視化

例えば次のようなクエリをDatadogで実行すると、GC世代ごとのサイズや回数を可視化できます。gc_gen,appのように複合してタグを設定すると、アプリケーションごとのGCの振る舞いを見ることができます。monotonic_diff関数を使うと前回値との差分をグラフ化できて便利です。

# GC Generation Size by gc_gen (Sum)
sum:clr_diagnostics_timer.gc.gc_size{*} by {gc_gen}
# GC Executed Count by gc_gen (Sum)
sum:clr_diagnostics_timer.gc.gc_count{*} by {gc_gen}
# 時間ごとのGC Generation Size by gc_gen (Sum)
monotonic_diff(sum:clr_diagnostics_timer.gc.gc_size{*} by {gc_gen})
# 時間ごとのGC Executed Count by gc_gen (Sum)
monotonic_diff(sum:clr_diagnostics_timer.gc.gc_count{*} by {gc_gen})

タグにappをつけておけば、アプリケーション事のGCイベントの時間や、サスペンドイベントの時間を見たりもできます。

# GC Event Duration(ms) by app (avg)
avg:clr_diagnostics_event.gc.startend_duration_ms{*} by {app}
# GC Event Suspend Duration(ms) by app (avg)
avg:clr_diagnostics_event.gc.suspend_duration_ms{*} by {app}

GCの理由もとれるので、GCの原因を特定するのにも使えます。.NETアプリケーションのGCはGen2でStop the worldがおこるので、Gen2の状況がわかるとアプリケーションのパフォーマンスチューニングに役立ちます。もちろんGen0やGen1は少ないほうがいいので、そういう指標を見るのにもいいですね。

# GC Event Count by generation (Sum)
sum:clr_diagnostics_event.gc.startend_count{*} by {gc_gen}.as_count()
# GC Event Gen0 by reason
sum:clr_diagnostics_event.gc.startend_count{gc_gen:0} by {gc_reason}.as_count()
# GC Event: Gen1 by reason
sum:clr_diagnostics_event.gc.startend_count{gc_gen:1} by {gc_reason}.as_count()
# GC Event: Gen 2 by reason
sum:clr_diagnostics_event.gc.startend_count{gc_gen:2} by {gc_reason}.as_count()

スレッドの情報を可視化

.NETアプリケーションはスレッドの情報も重要です。例えば次のようなクエリを実行すると、実行中のワーカースレッド数、スレッド数がわかります。

# Using WorkerThread Counts by app
sum:clr_diagnostics_timer.thread.using_worker_threads{*} by {app}
# Current ThreadCount by app
sum:clr_diagnostics_timer.thread.thread_count{*} by {app}

スレッドの数だけでなくキューの長さも確認できるので、スレッドプールの調整が必要かわかります。

# Thread QueueLength(num Locks) by app
sum:clr_diagnostics_timer.thread.queue_length{*} by {app}

スレッドプールの調整されたか理由ごとに判別できます。とくに重要なのがスレッド枯渇です。スレッド枯渇はアプリケーションのパフォーマンス低下に直結するのでアラートを出すといいでしょう。ただ、.NET Frameworkではアプリケーション起動時にスレッドプール調整をしていましたが、.NET 6以降はスレッドプールが枯渇することは見かけなくなりました。4

# TP Adjust: Thread Starvation by app
sum:clr_diagnostics_event.threadpool.adjustment_new_workerthreads_count{thread_adjust_reason:starvation} by {app}
# TP Adjust: Thread Warmup by app
sum:clr_diagnostics_event.threadpool.adjustment_new_workerthreads_count{thread_adjust_reason:warmup} by {app}
# TP Adjust: Cooperative Blocking by app
sum:clr_diagnostics_event.threadpool.adjustment_new_workerthreads_count{thread_adjust_reason:cooperative_blocking} by {app}
# TP Adjust: Timeout by app
sum:clr_diagnostics_event.threadpool.adjustment_new_workerthreads_count{thread_adjust_reason:timedout} by {app}

コンテンションがおこっているかもわかります。コンテンションは.NETランタイム実行中にスレッドがロック競合(contention)に直面している状態をさします。例えば、lock文やスレッドプールの過剰な使用、デッドロック、スレッド枯渇などをさします。コンテンションが0になることはまずないのですが、コンテンションがミリオンオーダーなど膨大な数値になっているときは注意が必要です。

# Contention: Lock Count by app
diff(sum:clr_diagnostics_timer.thread.lock_contention_count{*} by {app})

まとめ

アプリケーションサーバーの監視といえば、アプリケーションメトリクスやAPM、動作するVMなどホスト情報というのが多いです。しかし.NETはCLRから得られる情報も多く、パフォーマンスチューニングやどこで悪化したかを確認するのに有用でしょう。

今回.NETのCLR情報を取得するためのライブラリを公開しました。ぜひ、.NETアプリケーションの監視にお役立てください。

  1. CLRはCommon Language Runtimeの略です↩
  2. dotnet/diagnosticsリポジトリで公開されているdotnet-dumpやdotnet-traceなどのツールは、EventPipeを利用してCLRイベントを取得しています↩
  3. コンテナビルドしたうえで、VM、Kubernetes、ECS、ContainerApps、AppServiceなどいろいろなLinux環境で動作させています↩
  4. 過去のものと考えていきたい。今はデフォルトのままがベストだと考えています↩


以上の内容はhttps://tech.guitarrapc.com/entry/2025/01/19/235900より取得しました。
このページはhttp://font.textar.tv/のウェブフォントを使用してます
不具合報告/要望等はこちらへお願いします。
モバイルやる夫Viewer Ver0.14