Netwerkevenementen in .NET

Artikel
12/06/2023

Gebeurtenissen geven u toegang tot:

Nauwkeurige tijdstempels gedurende de hele levensduur van een bewerking. Bijvoorbeeld hoe lang het duurde om verbinding te maken met de server en hoe lang het duurde om een HTTP-aanvraag te ontvangen om antwoordheaders te ontvangen.
Foutopsporing/traceringsinformatie die mogelijk niet op andere manieren kan worden verkregen. Bijvoorbeeld wat voor soort beslissingen de verbindingsgroep heeft genomen en waarom.

De instrumentatie is gebaseerd op EventSource, zodat u deze informatie zowel binnen als buiten het proces kunt verzamelen.

Gebeurtenisproviders

Netwerkgegevens worden verdeeld over de volgende gebeurtenisproviders:

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

De telemetrie heeft enige overhead voor de prestaties wanneer deze is ingeschakeld, dus zorg ervoor dat u zich alleen abonneert op gebeurtenisproviders waarin u daadwerkelijk geïnteresseerd bent.

Gebeurtenissen in proces gebruiken

Geef de voorkeur aan in-process verzameling indien mogelijk voor eenvoudigere correlatie en analyse van gebeurtenissen.

EventListener

EventListener is een API waarmee u kunt luisteren naar EventSource-gebeurtenissen vanuit hetzelfde proces dat ze heeft geproduceerd.

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

Met de voorgaande code wordt uitvoer afgedrukt die vergelijkbaar is met de volgende:

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

Hoewel de EventListener hierboven beschreven benadering handig is voor snelle experimenten en foutopsporing, worden de API's niet sterk getypt en moet u afhankelijk zijn van implementatiedetails van de geïnstrumenteerde bibliotheek.

Hiervoor heeft .NET een bibliotheek gemaakt waarmee u eenvoudig netwerkgebeurtenissen in het proces kunt gebruiken: Yarp.Telemetry.Consumption. Hoewel het pakket momenteel wordt onderhouden als onderdeel van het YARP-project , kan het worden gebruikt in elke .NET-toepassing.

Als u deze wilt gebruiken, implementeert u de interfaces en methoden (gebeurtenissen) waarin u geïnteresseerd bent:

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

En registreer de implementaties bij uw DI-container:

services.AddTelemetryConsumer<MyTelemetryConsumer>();

De bibliotheek biedt de volgende sterk getypte interfaces:

Deze callbacks worden aangeroepen als onderdeel van de geïnstrueerde bewerking, zodat de algemene richtlijnen voor logboekregistratie van toepassing zijn. U moet voorkomen dat u dure berekeningen blokkeert of uitvoert als onderdeel van de callback. Offload elk naverwerkingswerk naar verschillende threads om te voorkomen dat latentie wordt toegevoegd aan de onderliggende bewerking.

Gebeurtenissen van buiten het proces gebruiken

dotnet-trace

dotnet-trace is een platformoverschrijdend hulpprogramma waarmee .NET Core-traceringen van een actief proces zonder systeemeigen profiler kunnen worden verzameld.

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

Zie de dotnet-trace docs voor alle beschikbare opdrachten en parameters.

U kunt het vastgelegde .nettrace bestand analyseren in Visual Studio of PerfView. Zie de docs voor dotnet-trace-analyse voor meer informatie.

PerfView

PerfView is een gratis hulpprogramma voor geavanceerde prestatieanalyse. Het wordt uitgevoerd in Windows, maar kan ook traceringen analyseren die zijn vastgelegd in Linux.

Als u de lijst met gebeurtenissen wilt configureren die moeten worden vastgelegd, geeft u deze op onder Advanced Options / Additional Providers:

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

TraceEvent

TraceEvent is een bibliotheek waarmee u gebeurtenissen uit verschillende processen in realtime kunt gebruiken. dotnet-trace en PerfView beide vertrouwen erop.

Als u gebeurtenissen programmatisch en in realtime wilt verwerken, raadpleegt u de TraceEvent documenten.

Gebeurtenissen starten en stoppen

Grotere bewerkingen beginnen vaak met een Start gebeurtenis en eindigen met een Stop gebeurtenis. U ziet RequestStart/RequestStop bijvoorbeeld gebeurtenissen van System.Net.Http of/ConnectStartConnectStop gebeurtenissen van .System.Net.Sockets

Hoewel grote bewerkingen zoals deze vaak garanderen dat een Stop gebeurtenis altijd aanwezig is, is dit niet altijd het geval. Als u bijvoorbeeld de RequestHeadersStart gebeurtenis van System.Net.Http waaruit wordt weergegeven, niet garandeert dat RequestHeadersStop deze ook wordt geregistreerd.

Gebeurteniscorrelatie

Nu u weet hoe u deze gebeurtenissen moet observeren, moet u deze vaak samen correleren, meestal met de oorspronkelijke HTTP-aanvraag.

Geef de voorkeur aan in-process verzameling indien mogelijk voor eenvoudigere correlatie en analyse van gebeurtenissen.

Correlatie in proces

Omdat netwerken asynchrone I/O gebruiken, kunt u er niet van uitgaan dat de thread die een bepaalde aanvraag heeft voltooid, ook de thread is die deze heeft gestart. Dit betekent dat u geen statische elementen kunt gebruiken [ThreadLocal] om gebeurtenissen te correleren, maar u kunt een AsyncLocal. Vertrouwd raken met AsyncLocal dit type is belangrijk om werk in verschillende threads te correleren.

AsyncLocal biedt u toegang tot dezelfde status in de asynchrone stroom van een bewerking. AsyncLocal waarden stromen alleen omlaag (dieper in de asynchrone aanroepstack) en geven geen wijzigingen door aan de aanroeper.

Kijk een naar het volgende voorbeeld:

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

Deze code produceert de volgende uitvoer:

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

De waarde 1 stroomde van de aanroeper naar beneden WorkAsync, maar de wijziging in WorkAsync (2) stroomde niet terug naar de beller.

Wanneer telemetrie-gebeurtenissen (en de bijbehorende callbacks) plaatsvinden als onderdeel van de onderliggende bewerking, vinden ze plaats binnen hetzelfde asynchrone bereik als de beller die de aanvraag heeft gestart. Dit betekent dat u vanuit de callback kunt observeren asyncLocal.Value , maar als u de waarde in de callback instelt, kan niets de stack verder bekijken.

In de volgende stappen ziet u het algemene patroon.

Maak een onveranderbare klasse die kan worden bijgewerkt vanuit callbacks van gebeurtenissen.
```
public sealed class RequestInfo
{
    public DateTime StartTime, HeadersSent;
}
```

Stel de AsyncLocal.Value voor de hoofdbewerking in, zodat de status in de bewerking stroomt.

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

Controleer in de callbacks van gebeurtenissen of de gedeelde status beschikbaar is en werk deze bij. AsyncLocal.Value is null als de aanvraag is verzonden door een onderdeel dat de AsyncLocal.Value eerste plaats niet heeft ingesteld.
```
public void OnRequestHeadersStop(DateTime timestamp)
{
    if (_requestInfo.Value is { } info) info.HeadersSent = timestamp;
}
```

De verzamelde gegevens verwerken na het voltooien van de bewerking.

await _client.GetStringAsync(url);

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

Zie de sectie Voorbeelden voor meer manieren om dit te doen.

Correlatie buiten het proces

Elke gebeurtenis bevat een stukje gegevens dat eraan is ActivityIDgekoppeld. Deze id codeert de asynchrone hiërarchie op het moment dat de gebeurtenis is geproduceerd.

Als u een traceringsbestand bekijkt in PerfView, ziet u gebeurtenissen zoals:

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

U weet dat deze gebeurtenissen deel uitmaken van dezelfde aanvraag omdat ze het /#14396/1/1/ voorvoegsel delen.

Wanneer u handmatige onderzoeken uitvoert, is een handige truc om te zoeken naar de System.Net.Http/Request/Start gebeurtenis van een aanvraag waarin u geïnteresseerd bent en deze vervolgens in het Text Filter tekstvak te plakkenActivityID. Als u nu alle beschikbare providers selecteert, ziet u de lijst met alle gebeurtenissen die zijn geproduceerd als onderdeel van die aanvraag.

PerfView verzamelt automatisch de ActivityID, maar als u hulpprogramma's zoals dotnet-tracegebruikt, moet u de System.Threading.Tasks.TplEventSource:0x80:4 provider expliciet inschakelen (zie dotnet-trace het bovenstaande voorbeeld).

HttpClient-aanvraag versus levensduur van verbinding

Omdat .NET 6, is een HTTP-aanvraag niet meer gekoppeld aan een specifieke verbinding. In plaats daarvan wordt de aanvraag verwerkt zodra er verbinding beschikbaar is.

Dit betekent dat u mogelijk de volgende volgorde van gebeurtenissen ziet:

Aanvraag starten
Dns-start
Aanvraagstop
Dns-stop

Dit geeft aan dat de aanvraag een DNS-omzetting heeft geactiveerd, maar is verwerkt door een andere verbinding voordat de DNS-aanroep is voltooid. Hetzelfde geldt voor socket-verbindingen of TLS-handshakes: de oorspronkelijke aanvraag kan worden voltooid voordat ze dit doen.

U moet afzonderlijk nadenken over dergelijke gebeurtenissen. Bewaak DNS-resoluties of TLS-handshakes zelf zonder deze te koppelen aan de tijdlijn van een specifieke aanvraag.

Interne diagnostische gegevens

Sommige onderdelen in .NET zijn geïnstrueerd met aanvullende gebeurtenissen op foutopsporingsniveau die meer inzicht bieden in wat er intern gebeurt. Deze gebeurtenissen worden geleverd met hoge overheadprestaties en hun vorm verandert voortdurend. Zoals de naam al aangeeft, maken ze geen deel uit van de openbare API en moet u daarom niet vertrouwen op hun gedrag of bestaan.

Ongeacht of deze gebeurtenissen veel inzichten kunnen bieden wanneer alle andere gebeurtenissen mislukken. De System.Net stack verzendt dergelijke gebeurtenissen uit Private.InternalDiagnostics.System.Net.* naamruimten.

Als u de voorwaarde in het EventListener bovenstaande eventSource.Name.Contains("System.Net")voorbeeld wijzigt in, ziet u meer dan 100 gebeurtenissen uit verschillende lagen in de stack. Zie het volledige voorbeeld voor meer informatie.

Voorbeelden

DNS-resoluties voor een bepaald eindpunt meten
Tijd-naar-headers meten bij het gebruik van HttpClient
Tijd om een aanvraag te verwerken in ASP.NET Core waarop Kestrel wordt uitgevoerd
De latentie van een .NET-omgekeerde proxy meten

DNS-resoluties voor een bepaald eindpunt meten

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

Tijd-naar-headers meten bij het gebruik van 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;
}

Tijd om een aanvraag te verwerken in ASP.NET Core waarop Kestrel wordt uitgevoerd

Dit is momenteel de meest nauwkeurige manier om de duur van een bepaalde aanvraag te meten.

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

De latentie van een .NET-omgekeerde proxy meten

Dit voorbeeld is van toepassing als u een omgekeerde proxy hebt die binnenkomende aanvragen ontvangt via Kestrel en uitgaande aanvragen doet via HttpClient (bijvoorbeeld YARP).

Dit voorbeeld meet de tijd van het ontvangen van de aanvraagheaders totdat deze naar de back-endserver worden verzonden.

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

Meer telemetrie nodig?

Als u suggesties hebt voor andere nuttige informatie die kan worden weergegeven via gebeurtenissen of metrische gegevens, maakt u een probleem met dotnet/runtime.

Als u de Yarp.Telemetry.Consumption bibliotheek gebruikt en suggesties hebt, maakt u een probleem met microsoft/reverse proxy.

Delen via