Netzwerkereignisse in .NET

Artikel
12/07/2023

Ereignisse ermöglichen Ihnen Zugriff auf:

genaue Zeitstempel während der gesamten Lebensdauer eines Vorgangs, Zum Beispiel wie lange die Verbindungsherstellung mit dem Server dauerte und wie lange eine HTTP-Anforderung brauchte, um die Antwortheader zu empfangen.
Debug-/Ablaufverfolgungsinformationen, die möglicherweise nicht auf anderen Wegen abgerufen werden können, zum Beispiel welche Art von Entscheidungen der Verbindungspool getroffen hat und warum

Die Instrumentierung basiert auf EventSource, sodass Sie diese Informationen sowohl innerhalb als auch außerhalb des Prozesses sammeln können.

Ereignisanbieter

Netzwerkinformationen werden auf die folgenden Ereignisanbieter aufgeteilt:

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

Die Telemetrie erzeugt einen gewissen Leistungsmehraufwand, wenn sie aktiviert ist. Achten Sie daher darauf, nur Ereignisanbieter zu abonnieren, die Sie tatsächlich interessieren.

Prozessinternes Nutzen von Ereignissen

Geben Sie nach Möglichkeit der prozessinternen Sammlung Vorzug, um die Ereigniskorrelation und -analyse zu vereinfachen.

EventListener

EventListener ist eine API, mit der Sie innerhalb des Prozesses an EventSource-Ereignissen lauschen können, der diese erzeugt hat.

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}")));
    }
}

Der obige Code erzeugt eine Ausgabe, die der folgenden ähnelt:

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

Der oben beschriebene EventListener-Ansatz eignet sich zwar für schnelle Experimente und das Debuggen, die APIs sind jedoch nicht stark typisiert und erzeugen eine Abhängigkeit von Implementierungsdetails der instrumentierten Bibliothek.

Um dies zu beheben, hat .NET eine Bibliothek für die prozessinterne Nutzung von Netzwerkereignissen erstellt: Yarp.Telemetry.Consumption. Das Paket wird derzeit zwar im Rahmen des YARP-Projekts gewartet, kann aber in jeder .NET-Anwendung verwendet werden.

Um sie zu verwenden, implementieren Sie die für Sie interessanten Schnittstellen und Methoden (Ereignisse):

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}");
    }
}

Registrieren Sie dann die Implementierungen bei Ihrem DI-Container:

services.AddTelemetryConsumer<MyTelemetryConsumer>();

Die Bibliothek stellt die folgenden stark typisierten Schnittstellen bereit:

Diese Rückrufe werden als Teil des instrumentierten Vorgangs aufgerufen. Daher gilt die allgemeine Protokollierungsanleitung. Sie sollten verhindern, dass im Rahmen des Rückrufs teure Berechnungen blockiert oder ausgeführt werden. Verlagern Sie alle nach der Verarbeitung anfallenden Vorgänge in verschiedene Threads, um zu vermeiden, dass die Latenz des zugrunde liegenden Vorgangs erhöht wird.

Nutzen von Ereignissen von außerhalb des Prozesses

dotnet-trace

dotnet-trace ist ein plattformübergreifendes Tool, mit dem .NET Core-Ablaufverfolgungen eines laufenden Prozesses ohne nativen Profiler gesammelt werden können.

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

Alle verfügbaren Befehle und Parameter finden Sie in der Dokumentation zu dotnet-trace.

Sie können die erfasste .nettrace-Datei in Visual Studio oder PerfView analysieren. Weitere Informationen finden Sie in der Analysedokumentation zu dotnet-trace.

PerfView

PerfView ist ein kostenloses, erweitertes Tool für die Leistungsanalyse. Es wird unter Windows ausgeführt, kann aber auch unter Linux erfasste Ablaufverfolgungen analysieren.

Um die Liste der zu erfassenden Ereignisse zu konfigurieren, geben Sie die Ereignisse unter Advanced Options / Additional Providers an:

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

TraceEvent

TraceEvent ist eine Bibliothek, mit der Sie in Echtzeit Ereignisse aus verschiedenen Prozessen nutzen können. dotnet-trace und PerfView basieren beide darauf.

Wenn Sie Ereignisse programmgesteuert und in Echtzeit verarbeiten möchten, lesen Sie die Dokumentation zu TraceEvent.

Start- und Stoppereignisse

Oft beginnen größere Vorgänge mit einem Start-Ereignis und enden mit einem Stop-Ereignis. So können Sie in System.Net.Http beispielsweise RequestStart/RequestStop-Ereignisse oder in System.Net.SocketsConnectStart/ConnectStop-Ereignisse beobachten.

Obwohl große Vorgänge wie diese häufig ein eindeutiges Zeichen sind, dass ein Stop-Ereignis vorhanden ist, ist dies nicht immer der Fall. Das Auftreten des RequestHeadersStart-Ereignisses von System.Net.Http garantiert beispielsweise nicht, dass RequestHeadersStop auch protokolliert wird.

Ereigniskorrelation

Nun wissen Sie, wie Sie diese Ereignisse überwachen. Häufig müssen diese Ereignisse miteinander korreliert werden (in der Regel mit der ursprünglichen HTTP-Anforderung).

Geben Sie nach Möglichkeit der prozessinternen Sammlung Vorzug, um die Ereigniskorrelation und -analyse zu vereinfachen.

Prozessinterne Korrelation

Da im Netzwerk asynchrone E/A-Vorgänge verwendet werden, können Sie nicht davon ausgehen, dass der Thread, der eine bestimmte Anforderung abgeschlossen hat, auch der Thread ist, der sie gestartet hat. Dies bedeutet, dass Sie Ereignisse nicht mit statischen [ThreadLocal]-Feldern korrelieren können. Sie können jedoch AsyncLocal verwenden. Machen Sie sich mit AsyncLocal vertraut, da dieser Typ unerlässlich ist, um Arbeit threadübergreifend zu korrelieren.

AsyncLocal ermöglicht Ihnen den Zugriff auf denselben Zustand tiefer im asynchronen Flow eines Vorgangs. AsyncLocal-Werte fließen nur nach unten (tiefer in den asynchronen Aufrufstapel), und geben keine Änderungen nach oben an den Aufrufer weiter.

Betrachten Sie das folgenden Beispiel:

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}");
}

Mit diesem Code wird die folgende Ausgabe generiert:

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

Der Wert 1 ist vom Aufrufer nach unten an WorkAsync weitergegeben worden. Die Änderung in WorkAsync (2) ist jedoch nicht nach oben zum Aufrufer zurückgegeben worden.

Da Telemetrieereignisse (und die entsprechenden Rückrufe) im Rahmen des zugrunde liegenden Vorgangs auftreten, erfolgen sie innerhalb desselben asynchronen Bereichs, in dem sich auch der Aufrufer befindet, der die Anforderung initiiert hat. Dies bedeutet, dass Sie asyncLocal.Value von innerhalb des Rückrufs überwachen können. Wenn Sie aber den Wert im Rückruf festlegen, kann „asyncLocal.Value“ nicht mehr von weiter oben im Stapel überwacht werden.

Die folgenden Schritte zeigen das allgemeine Muster.

Erstellen Sie eine veränderbare Klasse, die innerhalb von Ereignisrückrufen aktualisiert werden kann.
```
public sealed class RequestInfo
{
    public DateTime StartTime, HeadersSent;
}
```

Legen Sie AsyncLocal.Value vor dem Hauptvorgang fest, damit der Zustand in den Vorgang einfließen kann.

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);

Überprüfen Sie in den Ereignisrückrufen, ob der gemeinsame Zustand verfügbar ist, und aktualisieren Sie ihn. AsyncLocal.Value entspricht null, wenn die Anforderung von einer Komponente gesendet wurde, die AsyncLocal.Value überhaupt nicht festgelegt hat.
```
public void OnRequestHeadersStop(DateTime timestamp)
{
    if (_requestInfo.Value is { } info) info.HeadersSent = timestamp;
}
```

Verarbeiten Sie die gesammelten Informationen nach Abschluss des Vorgangs.

await _client.GetStringAsync(url);

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

Weitere Möglichkeiten hierzu finden Sie im Abschnitt „Beispiele“.

Prozessexterne Korrelation

Jedem Ereignis ist ein Datenelement namens ActivityID angefügt. Diese ID codiert die asynchrone Hierarchie zu dem Zeitpunkt, an dem das Ereignis generiert wurde.

Wenn Sie sich eine Ablaufverfolgungsdatei in PerfView ansehen, werden folgende Ereignisse angezeigt:

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/"

Am gemeinsamen Präfix /#14396/1/1/ können Sie erkennen, dass diese Ereignisse zur gleichen Anforderung gehören.

Wenn Sie manuelle Untersuchungen durchführen, wird empfohlen, nach dem System.Net.Http/Request/Start-Ereignis der betreffenden Anforderung zu suchen und den zugehörigen ActivityID-Wert in das Text Filter-Textfeld einzufügen. Wenn Sie jetzt alle verfügbaren Anbieter auswählen, wird Ihnen die Liste aller Ereignisse angezeigt, die im Rahmen dieser Anforderung generiert wurden.

PerfView erfasst den ActivityID-Wert automatisch. Wenn Sie Tools wie dotnet-trace verwenden, müssen Sie den Anbieter System.Threading.Tasks.TplEventSource:0x80:4 jedoch explizit aktivieren (siehe dotnet-trace-Beispiel oben).

HttpClient-Anforderung im Vergleich zur Verbindungslebensdauer

Seit .NET 6 ist eine HTTP-Anforderung nicht mehr an eine bestimmte Verbindung gebunden. Stattdessen wird die Anforderung bedient, sobald eine Verbindung verfügbar ist.

Dies bedeutet, dass Sie möglicherweise die folgende Ereignisreihenfolge beobachten:

Anforderungsbeginn
DNS-Start
Anforderungsstopp
DNS-Stopp

Dies weist darauf hin, dass die Anforderung eine DNS-Auflösung ausgelöst hat, aber von einer anderen Verbindung verarbeitet wurde, bevor der DNS-Aufruf abgeschlossen wurde. Das Gleiche gilt für Socket-Verbindungen oder TLS-Handshakes: Die ursprüngliche Anforderung kann vor der Socket-Verbindung oder dem TLS-Handshake abgeschlossen werden.

Sie sollten gesondert über solche Ereignisse nachdenken. Überwachen Sie DNS-Auflösungen oder TLS-Handshakes separat, ohne sie an die Zeitachse einer bestimmten Anforderung zu binden.

Interne Diagnose

Bestimmte Komponenten in .NET werden mit zusätzlichen Ereignissen auf Debugebene instrumentiert, die mehr Einblick in die internen Vorgänge bieten. Diese Ereignisse sind mit hohem Leistungsaufwand verbunden, und ihre Form ändert sich ständig. Wie der Name bereits andeutet, gehören sie nicht zur öffentlichen API. Daher sollten Sie sich nicht auf ihr Verhalten oder ihre Existenz verlassen.

Als letzte Option können diese Ereignisse jedoch viele Erkenntnisse liefern. Der System.Net-Stapel gibt solche Ereignisse von Private.InternalDiagnostics.System.Net.*-Namespaces aus.

Wenn Sie die Bedingung im obigen EventListener-Beispiel in eventSource.Name.Contains("System.Net") ändern, werden mehr als 100 Ereignisse aus verschiedenen Ebenen im Stapel angezeigt. Weitere Informationen finden Sie im vollständigen Beispiel.

Beispiele

Messen von DNS-Auflösungen für einen bestimmten Endpunkt
Messen der Time-to-Header bei Verwendung von HttpClient
Zeit für die Verarbeitung einer Anforderung in einer ASP.NET Core-Instanz, in der Kestrel ausgeführt wird
Messen der Latenz eines .NET-Reverseproxy

Messen von DNS-Auflösungen für einen bestimmten Endpunkt

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");
        }
    }
}

Messen der Time-to-Header bei Verwendung von 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;
}

Zeit für die Verarbeitung einer Anforderung in einer ASP.NET Core-Instanz, in der Kestrel ausgeführt wird

Dies ist derzeit die genaueste Methode, um die Dauer einer bestimmten Anforderung zu messen.

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);
        }
    }
}

Messen der Latenz eines .NET-Reverseproxy

Dieses Beispiel ist relevant für Sie, wenn Sie über einen Reverseproxy verfügen, der eingehende Anforderungen über Kestrel empfängt und ausgehende Anforderungen über HttpClient ausgibt (z. B. YARP).

In diesem Beispiel wird die Zeit vom Empfang der Anforderungsheader bis zum Senden an den Back-End-Server gemessen.

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);
        }
    }
}

Benötigen Sie weitere Telemetriedaten?

Wenn Sie Vorschläge für andere nützliche Informationen haben, die über Ereignisse oder Metriken verfügbar gemacht werden könnten, erstellen Sie einen Issue in dotnet/runtime.

Wenn Sie die Yarp.Telemetry.Consumption-Bibliothek verwenden und Vorschläge haben, erstellen Sie einen Issue in microsoft/reverse-proxy.

Freigeben über