Eventi di rete in .NET

Articolo
07/12/2024

Gli eventi consentono di accedere a:

Timestamp accurati per tutta la durata di un'operazione. Ad esempio, quanto tempo è necessario per connettersi al server e quanto tempo è necessario affinché una richiesta HTTP riceva le intestazioni della risposta.
Informazioni di debug/traccia che non possono essere recuperate con altri mezzi. come ad esempio quale tipo di decisioni sono state prese dal pool di connessioni e la relativa motivazione.

La strumentazione è basata su EventSource, consentendo di raccogliere queste informazioni sia all'interno che al di fuori del processo.

Provider di eventi

Le informazioni di rete sono suddivise tra i provider di eventi seguenti:

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

La telemetria presenta un sovraccarico delle prestazioni quando è abilitata, quindi assicurarsi di sottoscrivere solo i provider di eventi a cui si è effettivamente interessati.

Utilizzare eventi in-process

Preferire la raccolta in-process quando possibile per facilitare la correlazione e l'analisi degli eventi.

EventListener

EventListener è un'API che consente di ascoltare gli eventi EventSource nello stesso processo che li ha generati.

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

Il precedente codice stampa un output simile al seguente:

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

Sebbene l'approccio EventListener descritto in precedenza sia utile per una sperimentazione e un debug rapidi, le API non sono fortemente tipizzate e costringono l'utente a dipendere dai dettagli di implementazione della libreria instrumentata.

Per risolvere questo problema, .NET ha creato una libreria che facilita l'utilizzo degli eventi di rete in-process: Yarp.Telemetry.Consumption. Sebbene il pacchetto sia attualmente gestito come parte del progetto YARP, può essere usato in qualsiasi applicazione .NET.

Per usarlo, implementare le interfacce e i metodi (eventi) a cui si è interessati:

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

Quindi registrare le implementazioni con il contenitore DI:

services.AddTelemetryConsumer<MyTelemetryConsumer>();

La libreria fornisce le seguenti interfacce fortemente tipizzate:

Queste callback vengono chiamate come parte dell'operazione instrumentata, quindi si applicano le indicazioni generali per la registrazione. È consigliabile evitare di bloccare o eseguire calcoli costosi come parte della callback. Scaricare il lavoro di post-elaborazione in thread diversi per evitare di aggiungere latenza all'operazione sottostante.

Utilizzare eventi dall'esterno del processo

dotnet-trace

dotnet-trace è uno strumento multipiattaforma che abilita la raccolta di tracce .NET Core di un processo in esecuzione senza un profiler nativo.

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

Per tutti i comandi e i parametri disponibili, vedere la documentazione di dotnet-trace.

È possibile analizzare il file .nettrace acquisito in Visual Studio o in PerfView. Per maggiori informazioni, vedere la documentazione sull'analisi di dotnet-trace.

PerfView

PerfView è uno strumento di analisi delle prestazioni gratuito e avanzato. Funziona su Windows, ma può anche analizzare le tracce acquisite su Linux.

Per configurare l'elenco degli eventi da acquisire, specificarli in Advanced Options / Additional Providers:

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

TraceEvent

TraceEvent è una libreria che consente di utilizzare eventi da processi diversi in tempo reale. dotnet-trace e PerfView si basano entrambi su di essa.

Se si desidera elaborare gli eventi a livello di codice e in tempo reale, vedere la documentazione di TraceEvent.

Eventi di avvio e arresto

Le operazioni più complesse iniziano spesso con un evento Start e terminano con un evento Stop. Ad esempio, si potranno vedere eventi RequestStart/RequestStop da System.Net.Http o eventi ConnectStart/ConnectStop da System.Net.Sockets.

Sebbene operazioni più complesse come queste spesso garantiscano che un evento Stop sarà sempre presente, non è sempre così. Ad esempio, vedere l'evento RequestHeadersStart da System.Net.Http non garantisce che venga registrato anche RequestHeadersStop.

Correlazione degli eventi

Ora che si sa come osservare questi eventi, è spesso necessario correlarli tra loro, generalmente alla richiesta HTTP di origine.

Preferire la raccolta in-process quando possibile per facilitare la correlazione e l'analisi degli eventi.

Correlazione in-process

Poiché la rete utilizza operazioni di I/O asincrone, non è possibile presumere che il thread che ha completato una determinata richiesta sia anche il thread che l'ha avviata. Ciò significa che non è possibile usare [ThreadLocal] statici per correlare gli eventi, ma è possibile usare AsyncLocal. Acquisire familiarità con AsyncLocal poiché questo tipo è fondamentale per correlare il lavoro tra thread diversi.

AsyncLocal consente di accedere allo stesso stato più in profondità nel flusso asincrono di un'operazione. I valori AsyncLocal passano ai livelli inferiori (più in profondità nello stack di chiamate asincrone) e non propagano le modifiche fino al chiamante.

Si consideri l'esempio seguente:

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

Questo codice genera l'output seguente:

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

Il valore 1 è passato ai livelli inferiori dal chiamante verso WorkAsync, ma la modifica in WorkAsync (2) non è ritornata al chiamante.

Poiché gli eventi di telemetria (e le callback corrispondenti) si verificano come parte dell'operazione sottostante, avvengono nello stesso ambito asincrono del chiamante che ha avviato la richiesta. Ciò significa che è possibile osservare asyncLocal.Value dall'interno della callback, ma se si imposta il valore nella callback, non sarà possibile osservarlo più in alto nello stack.

I passaggi seguenti illustrano il modello generale.

Creare una classe modificabile che può essere aggiornata dall'interno delle callback degli eventi.
```
public sealed class RequestInfo
{
    public DateTime StartTime, HeadersSent;
}
```

Impostare AsyncLocal.Value prima dell'operazione principale in modo che lo stato passi nell'operazione.

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

All'interno delle callback degli eventi verificare se lo stato condiviso è disponibile e aggiornarlo. AsyncLocal.Value sarà null se la richiesta è stata inviata da un componente che non ha impostato AsyncLocal.Value come prima cosa.
```
public void OnRequestHeadersStop(DateTime timestamp)
{
    if (_requestInfo.Value is { } info) info.HeadersSent = timestamp;
}
```

Elaborare le informazioni raccolte al termine dell'operazione.

await _client.GetStringAsync(url);

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

Per ulteriori modi per eseguire questa operazione, vedere la sezione degli esempi.

Correlazione all'esterno del processo

Ad ogni evento è associato un dato denominato ActivityID. Questo ID codifica la gerarchia asincrona al momento della generazione dell'evento.

Se si esamina un file di traccia in PerfView, sarà possibile vedere eventi come:

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

Si potrà capire che questi eventi appartengono alla stessa richiesta perché condividono il prefisso /#14396/1/1/.

Quando si eseguono indagini manuali, un suggerimento utile è quello di cercare l'evento System.Net.Http/Request/Start di una richiesta a cui si è interessati, quindi incollare il relativo ActivityID nella casella di testo Text Filter. Se ora si selezionano tutti i provider disponibili, si vedrà l'elenco di tutti gli eventi che sono stati generati come parte di tale richiesta.

PerfView raccoglie automaticamente ActivityID, ma se si usano strumenti come dotnet-trace, è necessario abilitare in modo esplicito il provider System.Threading.Tasks.TplEventSource:0x80:4 (vedere l'esempio dotnet-trace sopra).

Richiesta HttpClient rispetto alla durata della connessione

A partire da .NET 6, una richiesta HTTP non è più legata a una connessione specifica, ma verrà invece gestita non appena sarà disponibile una connessione.

Ciò significa che si potrebbe vedere il seguente ordine di eventi:

Avvio della richiesta
Avvio del DNS
Arresto della richiesta
Arresto del DNS

Ciò indica che la richiesta ha attivato una risoluzione DNS, ma è stata elaborata da una connessione diversa prima del completamento della chiamata DNS. Lo stesso vale per le connessioni dei socket o gli handshake TLS: la richiesta di origine può essere completata prima che gli stessi vengano completati.

È consigliabile considerare questi eventi separatamente. Monitorare le risoluzioni DNS o gli handshake TLS autonomamente senza legarli alla sequenza temporale di una richiesta specifica.

Diagnostica interna

Alcuni componenti in .NET sono instrumentati con eventi aggiuntivi a livello di debug che forniscono maggiori informazioni dettagliate su ciò che accade internamente. Questi eventi comportano costi elevati in termini di prestazioni e la loro forma è in costante cambiamento. Come suggerisce il nome, non fanno parte dell'API pubblica e non si dovrebbe quindi fare affidamento sul loro comportamento o sulla loro esistenza.

Indipendentemente da ciò, questi eventi possono offrire molte informazioni dettagliate quando tutto il resto fallisce. Lo stack System.Net genera tali eventi dagli spazi dei nomi Private.InternalDiagnostics.System.Net.*.

Se si modifica la condizione nell'esempio EventListener di cui sopra in eventSource.Name.Contains("System.Net"), si vedranno oltre 100 eventi da livelli diversi nello stack. Per altre informazioni, vedi l'esempio completo.

Esempi

Misurare le risoluzioni DNS per un determinato endpoint
Misurare il tempo necessario per ottenere le intestazioni quando si usa HttpClient
Tempo necessario per elaborare una richiesta in ASP.NET Core che esegue Kestrel
Misurare la latenza di un proxy inverso .NET

Misurare le risoluzioni DNS per un determinato endpoint

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

Misurare il tempo necessario per ottenere le intestazioni quando si usa 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;
}

Tempo necessario per elaborare una richiesta in ASP.NET Core che esegue Kestrel

Questo è attualmente il modo più accurato per misurare la durata di una determinata richiesta.

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

Misurare la latenza di un proxy inverso .NET

Questo esempio è applicabile se si dispone di un proxy inverso che riceve richieste in ingresso tramite Kestrel ed effettua richieste in uscita tramite HttpClient, ad esempio YARP.

Questo esempio misura il tempo trascorso dalla ricezione delle intestazioni della richiesta fino a quando queste non vengono inviate al server back-end.

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

Sono necessari altri dati di telemetria?

Se si hanno suggerimenti per altre informazioni utili che potrebbero essere esposte tramite eventi o metriche, creare un problema dotnet/runtime.

Se si sta usando la libreria Yarp.Telemetry.Consumption e nascono dei suggerimenti, creare un problema microsoft/proxy inverso.

Condividi tramite