Nätverkshändelser i .NET

Artikel
12/06/2023

Händelser ger dig åtkomst till:

Korrekta tidsstämplar under en åtgärds livslängd. Till exempel hur lång tid det tog att ansluta till servern och hur lång tid det tog för en HTTP-begäran att ta emot svarshuvuden.
Felsöknings-/spårningsinformation som kanske inte kan hämtas på annat sätt. Till exempel vilken typ av beslut anslutningspoolen har fattat och varför.

Instrumentationen baseras på EventSource, så att du kan samla in den här informationen både inom och utanför processen.

Händelseleverantörer

Nätverksinformation delas upp mellan följande händelseprovidrar:

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

Telemetrin har vissa prestandakostnader när den är aktiverad, så se till att endast prenumerera på händelseleverantörer som du faktiskt är intresserad av.

Använda pågående händelser

Föredrar in-process-insamling när det är möjligt för enklare händelsekorrelation och analys.

EventListener

EventListener är ett API som gör att du kan lyssna på EventSource-händelser från samma process som skapade dem.

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

Föregående kod skriver ut utdata som liknar följande:

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 Den metod som beskrivs ovan är användbar för snabb experimentering och felsökning, men API:erna är inte starkt inskrivna och tvingar dig att vara beroende av implementeringsinformation för det instrumenterade biblioteket.

För att åtgärda detta skapade .NET ett bibliotek som gör det enkelt att använda nätverkshändelser i processen: Yarp.Telemetry.Consumption. Även om paketet för närvarande underhålls som en del av YARP-projektet kan det användas i alla .NET-program.

Om du vill använda den implementerar du de gränssnitt och metoder (händelser) som du är intresserad av:

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

Och registrera implementeringarna med din DI-container:

services.AddTelemetryConsumer<MyTelemetryConsumer>();

Biblioteket innehåller följande starkt inskrivna gränssnitt:

Dessa återanrop anropas som en del av den instrumenterade åtgärden, så den allmänna loggningsvägledningen gäller. Du bör undvika att blockera eller utföra dyra beräkningar som en del av återanropet. Avlasta allt arbete efter bearbetningen till olika trådar för att undvika att lägga till svarstid till den underliggande åtgärden.

Använda händelser utanför processen

dotnet-trace

dotnet-trace är ett plattformsoberoende verktyg som möjliggör insamling av .NET Core-spårningar av en process som körs utan en inbyggd profilerare.

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

Alla tillgängliga kommandon och parametrar finns i dotnet-trace-dokumenten.

Du kan analysera den insamlade .nettrace filen i Visual Studio eller PerfView. Mer information finns i dokumentationen för dotnet-trace-analys.

PerfView

PerfView är ett kostnadsfritt, avancerat prestandaanalysverktyg. Den körs i Windows men kan också analysera spårningar som registrerats i Linux.

Om du vill konfigurera listan över händelser som ska avbildas anger du dem under Advanced Options / Additional Providers:

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

TraceEvent

TraceEvent är ett bibliotek som gör att du kan använda händelser från olika processer i realtid. dotnet-trace och PerfView båda förlitar sig på det.

Om du vill bearbeta händelser programmatiskt och i realtid kan du läsa TraceEvent dokumenten.

Starta och stoppa händelser

Större åtgärder börjar ofta med en Start händelse och slutar med en Stop händelse. Du ser RequestStart/RequestStop till exempel händelser från System.Net.Http eller/ConnectStartConnectStop händelser från .System.Net.Sockets

Även om stora åtgärder som dessa ofta garanterar att en Stop händelse alltid kommer att finnas, är detta inte alltid fallet. Att se händelsen RequestHeadersStart från System.Net.Http garanterar till exempel inte att RequestHeadersStop den också loggas.

Händelsekorrelation

Nu när du vet hur du observerar dessa händelser måste du ofta korrelera dem tillsammans, vanligtvis med den ursprungliga HTTP-begäran.

Föredrar in-process-insamling när det är möjligt för enklare händelsekorrelation och analys.

Processkorrelation

Eftersom nätverk använder asynkron I/O kan du inte anta att tråden som slutförde en viss begäran också är den tråd som startade den. Det innebär att du inte kan använda [ThreadLocal] statiska objekt för att korrelera händelser, men du kan använda en AsyncLocal. Bekanta dig med AsyncLocal eftersom den här typen är nyckeln till att korrelera arbete mellan olika trådar.

AsyncLocal gör att du kan komma åt samma tillstånd djupare i asynkront flöde för en åtgärd. AsyncLocal värden flödar bara ned (djupare in i asynkron anropsstacken) och sprider inte ändringar upp till anroparen.

Ta följande som exempel:

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

Den här koden genererar följande utdata:

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

Värdet 1 flödade ned från anroparen till WorkAsync, men ändringen i WorkAsync (2) flödade inte tillbaka upp till anroparen.

När telemetrihändelser (och deras motsvarande återanrop) inträffar som en del av den underliggande åtgärden sker de inom samma asynkrona omfång som anroparen som initierade begäran. Det innebär att du kan observera asyncLocal.Value inifrån återanropet, men om du anger värdet i återanropet kommer ingenting att kunna observera det längre upp i stacken.

Följande steg visar det allmänna mönstret.

Skapa en föränderlig klass som kan uppdateras inifrån händelseåteranrop.

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

AsyncLocal.Value Ange före huvudåtgärden så att tillståndet flödar in i åtgärden.

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

Kontrollera om det delade tillståndet är tillgängligt i händelseåteranropet och uppdatera det. AsyncLocal.Value kommer att vara null om begäran skickades av en komponent som inte angav AsyncLocal.Value i första hand.
```
public void OnRequestHeadersStop(DateTime timestamp)
{
    if (_requestInfo.Value is { } info) info.HeadersSent = timestamp;
}
```

Bearbeta den insamlade informationen efter att åtgärden har slutförts.

await _client.GetStringAsync(url);

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

Fler sätt att göra detta finns i avsnittet exempel.

Korrelation utanför processen

Varje händelse har en bit data som är kopplad till den med namnet ActivityID. Det här ID:t kodar asynkron hierarkin när händelsen skapades.

Om du tittar på en spårningsfil i PerfView visas händelser som:

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

Du vet att dessa händelser tillhör samma begäran eftersom de delar prefixet /#14396/1/1/ .

När du gör manuella undersökningar är ett användbart trick att leta efter händelsen av System.Net.Http/Request/Start en begäran som du är intresserad av och sedan klistra in den ActivityID Text Filter i textrutan. Om du nu väljer alla tillgängliga leverantörer visas listan över alla händelser som har skapats som en del av den begäran.

PerfView samlar automatiskt in ActivityID, men om du använder verktyg som dotnet-tracemåste du uttryckligen aktivera providern System.Threading.Tasks.TplEventSource:0x80:4 (se dotnet-trace exemplet ovan).

HttpClient-begäran jämfört med anslutningens livslängd

Eftersom .NET 6 är en HTTP-begäran inte längre kopplad till en specifik anslutning. I stället kommer begäran att betjänas så snart en anslutning är tillgänglig.

Det innebär att du kan se följande händelseordning:

Starta begäran
Dns-start
Begäran stoppas
Dns-stopp

Detta indikerar att begäran utlöste en DNS-matchning, men bearbetades av en annan anslutning innan DNS-anropet slutfördes. Detsamma gäller för socketanslutningar eller TLS-handskakningar – den ursprungliga begäran kan slutföras innan de gör det.

Du bör tänka på sådana händelser separat. Övervaka DNS-matchningar eller TLS-handskakningar på egen hand utan att koppla dem till tidslinjen för en specifik begäran.

Intern diagnostik

Vissa komponenter i .NET instrumenteras med ytterligare händelser på felsökningsnivå som ger mer insikt i exakt vad som händer internt. Dessa händelser har höga prestanda och deras form förändras ständigt. Som namnet antyder är de inte en del av det offentliga API:et och du bör därför inte förlita dig på deras beteende eller existens.

Oavsett kan dessa händelser ge många insikter när allt annat misslyckas. Stacken System.Net genererar sådana händelser från Private.InternalDiagnostics.System.Net.* namnområden.

Om du ändrar villkoret EventListener i exemplet ovan till eventSource.Name.Contains("System.Net")visas över 100 händelser från olika lager i stacken. Mer information finns i det fullständiga exemplet.

Exempel

Mäta DNS-matchningar för en viss slutpunkt
Mäta tid-till-huvuden när du använder HttpClient
Dags att bearbeta en begäran i ASP.NET Core som kör Kestrel
Mäta svarstiden för en omvänd .NET-proxy

Mäta DNS-matchningar för en viss slutpunkt

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

Mäta tid-till-huvuden när du använder 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;
}

Dags att bearbeta en begäran i ASP.NET Core som kör Kestrel

Detta är för närvarande det mest exakta sättet att mäta varaktigheten för en viss begäran.

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

Mäta svarstiden för en omvänd .NET-proxy

Det här exemplet gäller om du har en omvänd proxy som tar emot inkommande begäranden via Kestrel och gör utgående begäranden via HttpClient (till exempel YARP).

Det här exemplet mäter tiden från att ta emot begärandehuvudena tills de skickas ut till serverdelsservern.

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

Behöver du mer telemetri?

Om du har förslag på annan användbar information som kan exponeras via händelser eller mått skapar du ett problem med dotnet/runtime.

Om du använder Yarp.Telemetry.Consumption biblioteket och har några förslag skapar du ett microsoft-/reverse-proxy-problem.

Dela via