Condividi tramite

Eventi di rete in .NET

  • Articolo

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. Ad esempio, quale tipo di decisioni sono state prese dal pool di connessioni e perché.

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 semplificare 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 codice precedente 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 forzano l'utente a dipendere dai dettagli di implementazione della libreria instrumentata.

Per risolvere questo problema, .NET ha creato una libreria che semplifica l'uso degli eventi di rete in-process: Yarp.Telemetry.Consumption. Anche se il pacchetto è 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}");
    }
}

Registrare le implementazioni con il contenitore DI:

services.AddTelemetryConsumer<MyTelemetryConsumer>();

La libreria fornisce le interfacce fortemente tipizzate seguenti:

Questi callback vengono chiamati come parte dell'operazione instrumentata, quindi si applicano le linee guida generali per la registrazione. È consigliabile evitare di bloccare o eseguire calcoli costosi come parte del callback. Scaricare il lavoro di post-elaborazione in thread diversi per evitare l'aggiunta di latenza all'operazione sottostante.

Utilizzare eventi al di fuori del processo

dotnet-trace

dotnet-trace è uno strumento multipiattaforma che abilita la raccolta di analisi .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 PerfView. Per altre informazioni, vedere la documentazione sull'analisi di dotnet-trace.

PerfView

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

Per configurare l'elenco di 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 di processi diversi in tempo reale. dotnet-trace e PerfView si basano entrambi su di essa.

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

Eventi di avvio e arresto

Le operazioni più grandi iniziano spesso con un evento Start e terminano con un evento Stop. Ad esempio, verranno visualizzati eventi RequestStart/RequestStop di System.Net.Http o eventi ConnectStart/ConnectStop di System.Net.Sockets.

Anche se le operazioni di grandi dimensioni come queste spesso garantiscono che un evento Stop sarà sempre presente, non è sempre così. Ad esempio, la visualizzazione dell'evento RequestHeadersStart da System.Net.Http non garantisce che verrà registrato anche RequestHeadersStop.

Correlazione degli eventi

Ora che si sa come osservare questi eventi, spesso è necessario correlarli insieme, in genere alla richiesta HTTP di origine.

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

Correlazione in-process

Poiché la rete usa operazioni di I/O asincrone, non è possibile presupporre che il thread che ha completato una determinata richiesta sia anche il thread che la ha avviata. Ciò significa che non è possibile usare statistiche [ThreadLocal] per correlare gli eventi, ma è possibile usare AsyncLocal. Acquisire familiarità con AsyncLocal in quanto 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 in WorkAsync, ma la modifica in WorkAsync (2) non è ritornata al chiamante.

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

I passaggi seguenti illustrano il modello generale.

  1. Creare una classe modificabile che può essere aggiornata all'interno dei callback degli eventi.

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

  2. Impostare il valore AsyncLocal.Valueprima 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);

  3. All'interno dei 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;
}

  4. Elaborare le informazioni raccolte dopo aver completato l'operazione.

    await _client.GetStringAsync(url);

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

Per altri modi in cui eseguire questa operazione, vedere la sezione degli esempi.

Correlazione all'esterno del processo

A 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, verranno visualizzati 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 sa che questi eventi appartengono alla stessa richiesta perché condividono il prefisso /#14396/1/1/.

Quando si eseguono indagini manuali, è utile cercare l'evento System.Net.Http/Request/Start di una richiesta a cui si è interessati, quindi incollare ActivityID nella casella di testo Text Filter. Se ora si selezionano tutti i provider disponibili, verrà visualizzato l'elenco di tutti gli eventi 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 precedente).

Richiesta HttpClient e durata della connessione

A partire da .NET 6, una richiesta HTTP non è più associata a una connessione specifica. La richiesta verrà invece eseguita non appena è disponibile una connessione.

Ciò significa che è possibile che venga visualizzato l'ordine di eventi seguente:

  1. Inizio della richiesta
  2. Avvio di DNS
  3. Arresto della richiesta
  4. Arresto di 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 questi 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 presentano un sovraccarico di prestazioni elevate e la loro forma cambia costantemente. Come suggerisce il nome, non fanno parte dell'API pubblica e pertanto non è consigliabile basarsi sul loro comportamento o sulla loro esistenza.

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

Se si modifica la condizione nell'esempio EventListener precedente in eventSource.Name.Contains("System.Net"), verranno visualizzati più di 100 eventi da livelli diversi nello stack. Per altre informazioni, vedi l'esempio completo.

Esempi

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ù preciso 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 una segnalazione di un problema relativo a dotnet/runtime.

Se si usa la libreria Yarp.Telemetry.Consumption e si hanno suggerimenti, creare una segnalazione di un problema relativo a microsoft/proxy inverso.