.NET のネットワーク イベント

イベントにより、次へのアクセスができます。

• 操作の有効期間を通して正確なタイムスタンプ。 たとえば、サーバーへの接続にかかった時間と HTTP 要求で応答ヘッダーの受信にかかった時間などです。
• 他の手段では取得できない可能性があるデバッグ/トレース情報。 たとえば、接続プールによって行われた決定の種類とその理由などです。

インストルメンテーションは EventSource に基づいており、プロセスの内部と外部の両方からこの情報を収集できます。

イベント プロバイダー

ネットワーク情報は、次のイベント プロバイダーに分割されます。

• System.Net.Http (HttpClient と SocketsHttpHandler)
• System.Net.NameResolution (Dns)
• System.Net.Security (SslStream)
• System.Net.Sockets
• Microsoft.AspNetCore.Hosting
• Microsoft-AspNetCore-Server-Kestrel

テレメトリは、有効にするといくらかのパフォーマンス オーバーヘッドが発生するため、実際に関心のあるイベント プロバイダーのみにサブスクライブするようにしてください。

インプロセスでイベントを使用する

イベントの関連付けと分析を容易にするために、可能であればインプロセス収集を優先します。

EventListener

EventListener は、イベントを生成した同じプロセス内から EventSource イベントをリッスンできる API です。

using System.Diagnostics.Tracing;

using var listener = new MyListener();

using var client = new HttpClient();
await client.GetStringAsync("https://httpbin.org/get");

public sealed class MyListener : EventListener
{
    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        if (eventSource.Name == "System.Net.Http")
        {
            EnableEvents(eventSource, EventLevel.Informational);
        }
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        Console.WriteLine($"{DateTime.UtcNow:ss:fff} {eventData.EventName}: " +
            string.Join(' ', eventData.PayloadNames!.Zip(eventData.Payload!).Select(pair => $"{pair.First}={pair.Second}")));
    }
}

上記のコードでは、次のような出力が生成されます。

00:598 RequestStart: scheme=https host=httpbin.org port=443 pathAndQuery=/get versionMajor=1 versionMinor=1 versionPolicy=0
01:470 ConnectionEstablished: versionMajor=1 versionMinor=1
01:474 RequestLeftQueue: timeOnQueueMilliseconds=470,6214 versionMajor=1 versionMinor=1
01:476 RequestHeadersStart:
01:477 RequestHeadersStop:
01:592 ResponseHeadersStart:
01:593 ResponseHeadersStop:
01:633 ResponseContentStart:
01:635 ResponseContentStop:
01:635 RequestStop:
01:637 ConnectionClosed: versionMajor=1 versionMinor=1

Yarp.Telemetry.Consumption

上記の EventListener アプローチは、簡単な実験とデバッグに役立ちますが、API は厳密に型指定されておらず、インストルメント化されたライブラリの実装の詳細に強制的に依存することになります。

これに対処するために、.NET では、インプロセスでネットワーク イベントを簡単に使用できるようにするライブラリが作成されました (Yarp.Telemetry.Consumption)。 パッケージは現在 YARP プロジェクトの一部として保持されていますが、任意の .NET アプリケーションで使用できます。

これを使用するには、関心のあるインターフェイスとメソッド (イベント) を実装します。

public sealed class MyTelemetryConsumer : IHttpTelemetryConsumer, INetSecurityTelemetryConsumer
{
    public void OnRequestStart(DateTime timestamp, string scheme, string host, int port, string pathAndQuery, int versionMajor, int versionMinor, HttpVersionPolicy versionPolicy)
    {
        Console.WriteLine($"Request to {host} started at {timestamp}");
    }

    public void OnHandshakeStart(DateTime timestamp, bool isServer, string targetHost)
    {
        Console.WriteLine($"Starting TLS handshake with {targetHost}");
    }
}

さらに実装を DI コンテナーに登録します。

services.AddTelemetryConsumer<MyTelemetryConsumer>();

ライブラリには、次の厳密に型指定されたインターフェイスが用意されています。

• IHttpTelemetryConsumer
• INameResolutionTelemetryConsumer
• INetSecurityTelemetryConsumer
• ISocketsTelemetryConsumer
• IKestrelTelemetryConsumer

これらのコールバックはインストルメント化された操作の一部として呼び出されるため、一般的なログ ガイダンスが適用されます。 コールバックの一部として、負荷の高い計算をブロックまたは実行しないようにする必要があります。 基になる操作に待機時間を追加しないように、処理後の作業を別のスレッドにオフロードします。

プロセスの外部からイベントを使用する

dotnet-トレース

dotnet-trace は、ネイティブ プロファイラーなしで実行中のプロセスの .NET Core トレースを収集できるクロスプラットフォーム ツールです。

dotnet tool install --global dotnet-trace

dotnet-trace collect --providers System.Net.Http,System.Net.Security,System.Threading.Tasks.TplEventSource:0x80:4 --process-id 1234

使用可能なすべてのコマンドとパラメーターについては、dotnet-trace のドキュメントを参照してください。

キャプチャした .nettrace ファイルは、Visual Studio または PerfView で分析できます。 詳細については、dotnet-trace 分析のドキュメントを参照してください。

PerfView

PerfView は、無料の高度なパフォーマンス分析ツールです。 Windows で実行されますが、Linux でキャプチャされたトレースを分析することもできます。

キャプチャするイベントのリストを構成するには、それらを Advanced Options / Additional Providers の下に指定します。

*System.Net.Sockets,*System.Net.NameResolution,*System.Net.Http,*System.Net.Security

TraceEvent

TraceEvent は、さまざまなプロセスからのイベントをリアルタイムで使用できるライブラリです。 dotnet-trace と PerfView のどちらもそれに依存しています。

プログラムとリアルタイムでイベントを処理する場合は、TraceEvent のドキュメントを参照してください。

イベントの開始と停止

大規模な操作は、多くの場合に、Start イベントで始まり、Stop イベントで終了します。 たとえば、System.Net.Http からの RequestStart/RequestStop イベントや System.Net.Sockets からの ConnectStart/ConnectStop イベントが発生します。

これらのような大規模な操作では、多くの場合、Stop イベントが常に存在することが保証されますが、必ずしもそうとは限りません。 たとえば、System.Net.Http から RequestHeadersStart イベントが発生しても、RequestHeadersStop もログに記録される保証はありません。

イベントの相関関係

これらのイベントを観察する方法がわかったところで、多くの場合、それらをまとめて、通常は元の HTTP 要求に関連付ける必要があります。

イベントの関連付けと分析を容易にするために、可能であればインプロセス収集を優先します。

インプロセスの関連付け

ネットワークでは非同期 I/O が使用されるため、特定の要求を完了したスレッドが、その要求を開始したスレッドであると想定することはできません。 つまり、[ThreadLocal] スタティックを使用 してイベントを関連付けることはできませんが、AsyncLocal を使用できます。 この種類は、異なるスレッド間で作業を関連付ける鍵であるため、AsyncLocal について理解してください。

AsyncLocal を使用すると、操作の非同期フローの深くで、同じ状態にアクセスできます。 AsyncLocal 値は下方にのみ流れ (非同期呼び出し履歴の深く)、変更が呼び出し元まで上方に伝達されません。

次の例を確認してください。

AsyncLocal<int> asyncLocal = new();
asyncLocal.Value = 1;

await WorkAsync();
Console.WriteLine($"Value after WorkAsync: {asyncLocal.Value}");

async Task WorkAsync()
{
    Console.WriteLine($"Value in WorkAsync: {asyncLocal.Value}");
    asyncLocal.Value = 2;
    Console.WriteLine($"Value in WorkAsync: {asyncLocal.Value}");
}

このコードを実行すると、次の出力が生成されます。

Value in WorkAsync: 1
Value in WorkAsync: 2
Value after WorkAsync: 1

値 1 は呼び出し元から WorkAsync に流れましたが、WorkAsync の変更 (2) は呼び出し元に戻されませんでした。

テレメトリ イベント (およびその対応するコールバック) は基になる操作の一部として発生するため、要求を開始した呼び出し元と同じ非同期スコープ内で発生します。 これは、コールバック内から asyncLocal.Value を観察できますが、コールバックに値を設定した場合、スタックのさらに上方でそれを観察できなくなることを意味します。

次の手順は、一般的なパターンを示しています。

1. イベント コールバックの内部から更新できる変更可能なクラスを作成します。

   public sealed class RequestInfo
   {
       public DateTime StartTime, HeadersSent;
   }
   

2. 状態が操作内に流れるように、メインの操作の "前" に AsyncLocal.Value を設定します。

   private static readonly AsyncLocal<RequestInfo> _requestInfo = new();
   
   public async Task SendRequestAsync(string url)
   {
       var info = new RequestInfo();
       _requestInfo.Value = info;
   
       info.StartTime = DateTime.UtcNow;
       await _client.GetStringAsync(url);
   

3. イベント コールバックの内部で、共有状態が使用可能かどうかを確認し、更新します。 最初に AsyncLocal.Value を設定していないコンポーネントによって要求が送信された場合、AsyncLocal.Value は、null になります。

   public void OnRequestHeadersStop(DateTime timestamp)
   {
       if (_requestInfo.Value is { } info) info.HeadersSent = timestamp;
   }
   

4. 操作の完了後、収集された情報を処理します。

   await _client.GetStringAsync(url);
   
   Log($"Time until headers were sent {url} was {info.HeadersSent - info.StartTime}");
   

これを行うその他の方法については、サンプルのセクションを参照してください。

プロセス外部の関連付け

すべてのイベントには、ActivityID というデータがアタッチされています。 この ID によって、イベントが生成された時点で非同期階層がエンコードされます。

PerfView でトレース ファイルを調べると、次のようにイベントが表示されます。

System.Net.Http/Request/Start           ActivityID="/#14396/1/1/"
System.Net.Http/RequestHeaders/Start    ActivityID="/#14396/1/1/2/"
System.Net.Http/RequestHeaders/Stop     ActivityID="/#14396/1/1/2/"
System.Net.Http/ResponseHeaders/Start   ActivityID="/#14396/1/1/3/"
System.Net.Http/ResponseHeaders/Stop    ActivityID="/#14396/1/1/3/"
System.Net.Http/Request/Stop            ActivityID="/#14396/1/1/"

これらのイベントは /#14396/1/1/ プレフィックスを共有しているため、同じ要求に属していることがわかります。

手動で調査を行う場合、関心のある要求の System.Net.Http/Request/Start イベントを探し、その ActivityID を Text Filter テキスト ボックスに張り付けると便利です。 使用可能なすべてのプロバイダーを選択したら、その要求の一部として生成されたすべてのイベントの一覧が表示されます。

PerfView によって ActivityID が自動的に収集されますが、dotnet-trace のようなツールを使用する場合は、System.Threading.Tasks.TplEventSource:0x80:4 プロバイダーを明示的に有効にする必要があります (上記の dotnet-trace の例を参照)。

HttpClient 要求と接続の有効期間

.NET 6 以降、HTTP 要求は特定の接続に関連付けられなくなりました。 代わりに、接続が使用可能になるとすぐに要求が処理されます。

これは、次の順序でイベントが表示される可能性があることを意味します。

1. 要求の開始
2. Dns の開始
3. 要求の停止
4. Dns の停止

これは、要求によって DNS 解決がトリガーされたが、DNS 呼び出しが完了する前に別の接続によって処理されたことを示します。 ソケット接続や TLS ハンドシェイクでも同じことが言えます。それらが実行する前に、元の要求が完了することがあります。

そのようなイベントは、個別に考える必要があります。 特定の要求のタイムラインに結びつけることなく、DNS 解決や TLS ハンドシェイクを独自に監視します。

内部診断

.NET の一部のコンポーネントは、内部で何が起こっているかの詳細な分析情報を提供する追加のデバッグ レベルのイベントでインストルメント化されています。 これらのイベントにはハイ パフォーマンスのオーバーヘッドが伴い、それらの形状は絶えず変化しています。 名前が示すように、これらはパブリック API の一部ではないため、それらの動作や存在に依存しないでください。

それでも、これらのイベントは、他のすべてが失敗したときに多くの分析情報を提供できます。 System.Net スタックは、そのようなイベントを Private.InternalDiagnostics.System.Net.* 名前空間から生成します。

上記の EventListener の例の条件を eventSource.Name.Contains("System.Net") に変更すると、スタック内のさまざまなレイヤーから 100 以上のイベントが表示されます。 詳細については、完全な例を参照してください。

サンプル

• 特定のエンドポイントの DNS 解決を測定する
• HttpClient を使用する場合のヘッダーまでの時間を測定する
• Kestrel を実行している ASP.NET Core で要求を処理する時間
• .NET リバース プロキシの待機時間を測定する

特定のエンドポイントの DNS 解決を測定する

services.AddTelemetryConsumer(new DnsMonitor("httpbin.org"));

public sealed class DnsMonitor : INameResolutionTelemetryConsumer
{
    private static readonly AsyncLocal<DateTime?> _startTimestamp = new();
    private readonly string _hostname;

    public DnsMonitor(string hostname) => _hostname = hostname;

    public void OnResolutionStart(DateTime timestamp, string hostNameOrAddress)
    {
        if (hostNameOrAddress.Equals(_hostname, StringComparison.OrdinalIgnoreCase))
        {
            _startTimestamp.Value = timestamp;
        }
    }

    public void OnResolutionStop(DateTime timestamp)
    {
        if (_startTimestamp.Value is { } start)
        {
            Console.WriteLine($"DNS resolution for {_hostname} took {(timestamp - start).TotalMilliseconds} ms");
        }
    }
}

HttpClient を使用する場合のヘッダーまでの時間を測定する

var info = RequestState.Current; // Initialize the AsyncLocal's value ahead of time

var response = await client.GetStringAsync("http://httpbin.org/get");

var requestTime = (info.RequestStop - info.RequestStart).TotalMilliseconds;
var serverLatency = (info.HeadersReceived - info.HeadersSent).TotalMilliseconds;
Console.WriteLine($"Request took {requestTime:N2} ms, server request latency was {serverLatency:N2} ms");

public sealed class RequestState
{
    private static readonly AsyncLocal<RequestState> _asyncLocal = new();
    public static RequestState Current => _asyncLocal.Value ??= new();

    public DateTime RequestStart;
    public DateTime HeadersSent;
    public DateTime HeadersReceived;
    public DateTime RequestStop;
}

public sealed class TelemetryConsumer : IHttpTelemetryConsumer
{
    public void OnRequestStart(DateTime timestamp, string scheme, string host, int port, string pathAndQuery, int versionMajor, int versionMinor, HttpVersionPolicy versionPolicy) =>
        RequestState.Current.RequestStart = timestamp;

    public void OnRequestStop(DateTime timestamp) =>
        RequestState.Current.RequestStop = timestamp;

    public void OnRequestHeadersStop(DateTime timestamp) =>
        RequestState.Current.HeadersSent = timestamp;

    public void OnResponseHeadersStop(DateTime timestamp) =>
        RequestState.Current.HeadersReceived = timestamp;
}

Kestrel を実行している ASP.NET Core で要求を処理する時間

これは現在、特定の要求の期間を測定する最も正確な方法です。

public sealed class KestrelTelemetryConsumer : IKestrelTelemetryConsumer
{
    private static readonly AsyncLocal<DateTime?> _startTimestamp = new();
    private readonly ILogger<KestrelTelemetryConsumer> _logger;

    public KestrelTelemetryConsumer(ILogger<KestrelTelemetryConsumer> logger) => _logger = logger;

    public void OnRequestStart(DateTime timestamp, string connectionId, string requestId, string httpVersion, string path, string method)
    {
        _startTimestamp.Value = timestamp;
    }

    public void OnRequestStop(DateTime timestamp, string connectionId, string requestId, string httpVersion, string path, string method)
    {
        if (_startTimestamp.Value is { } startTime)
        {
            var elapsed = timestamp - startTime;
            _logger.LogInformation("Request {requestId} to {path} took {elapsedMs} ms", requestId, path, elapsed.TotalMilliseconds);
        }
    }
}

.NET リバース プロキシの待機時間を測定する

このサンプルは、Kestrel 経由で受信要求を受信し、HttpClient 経由で送信要求を行うリバース プロキシ (YARP など) がある場合に適用されます。

このサンプルでは、要求ヘッダーの受信から、それらがバックエンド サーバーに送信されるまでの時間を測定しています。

public sealed class InternalLatencyMonitor : IKestrelTelemetryConsumer, IHttpTelemetryConsumer
{
    private record RequestInfo(DateTime StartTimestamp, string RequestId, string Path);

    private static readonly AsyncLocal<RequestInfo> _requestInfo = new();
    private readonly ILogger<InternalLatencyMonitor> _logger;

    public InternalLatencyMonitor(ILogger<InternalLatencyMonitor> logger) => _logger = logger;

    public void OnRequestStart(DateTime timestamp, string connectionId, string requestId, string httpVersion, string path, string method)
    {
        _requestInfo.Value = new RequestInfo(timestamp, requestId, path);
    }

    public void OnRequestHeadersStop(DateTime timestamp)
    {
        if (_requestInfo.Value is { } requestInfo)
        {
            var elapsed = (timestamp - requestInfo.StartTimestamp).TotalMilliseconds;
            _logger.LogInformation("Internal latency for {requestId} to {path} was {duration} ms", requestInfo.RequestId, requestInfo.Path, elapsed);
        }
    }
}

さらに多くのテレメトリが必要な場合

イベントまたはメトリックを介して公開される可能性のある他の有用な情報についての提案がある場合は、dotnet/runtime の問題を作成します。

Yarp.Telemetry.Consumption ライブラリを使用していて、提案がある場合は、microsoft/reverse-proxy の問題を作成します。