Partilhar via

Eventos de rede no .NET

  • Artigo

Os eventos dão-lhe acesso a:

  • Carimbos de data/hora precisos durante toda a vida útil de uma operação. Por exemplo, quanto tempo levou para se conectar ao servidor e quanto tempo levou uma solicitação HTTP para receber cabeçalhos de resposta.
  • Depurar/rastrear informações que podem não ser obtidas por outros meios. Por exemplo, que tipo de decisões o pool de conexões tomou e por quê.

A instrumentação é baseada no EventSource, permitindo que você colete essas informações de dentro e de fora do processo.

Fornecedores de eventos

As informações de rede são divididas entre os seguintes provedores de eventos:

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

A telemetria tem alguma sobrecarga de desempenho quando ativada, portanto, certifique-se de se inscrever apenas em provedores de eventos nos quais você está realmente interessado.

Consumir eventos em processo

Prefira a coleta em processo quando possível para facilitar a correlação e a análise de eventos.

EventListener

EventListener é uma API que permite ouvir eventos EventSource a partir do mesmo processo que os produziu.

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

O código anterior imprime uma saída semelhante à seguinte:

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.Telemetria.Consumo

Embora a EventListener abordagem descrita acima seja útil para experimentação e depuração rápidas, as APIs não são fortemente tipadas e forçam você a depender dos detalhes de implementação da biblioteca instrumentada.

Para resolver isso, o .NET criou uma biblioteca que facilita o consumo de eventos de rede no processo: Yarp.Telemetry.Consumption. Embora o pacote seja atualmente mantido como parte do projeto YARP , ele pode ser usado em qualquer aplicativo .NET.

Para usá-lo, implemente as interfaces e métodos (eventos) em que você está interessado:

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

E registre as implementações com seu contêiner DI:

services.AddTelemetryConsumer<MyTelemetryConsumer>();

A biblioteca fornece as seguintes interfaces fortemente tipadas:

Esses retornos de chamada são chamados como parte da operação instrumentada, portanto, a orientação geral de registro se aplica. Você deve evitar bloquear ou executar cálculos caros como parte do retorno de chamada. Descarregue qualquer trabalho de pós-processamento para threads diferentes para evitar adicionar latência à operação subjacente.

Consumir eventos de fora do processo

dotnet-trace

dotnet-trace é uma ferramenta multiplataforma que permite a coleta de rastreamentos do .NET Core de um processo em execução sem um criador de perfil 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

Para todos os comandos e parâmetros disponíveis, consulte os documentos dotnet-trace.

Você pode analisar o arquivo capturado .nettrace no Visual Studio ou PerfView. Para obter mais informações, consulte os documentos de análise dotnet-trace.

PerfView

O PerfView é uma ferramenta avançada e gratuita de análise de desempenho. Ele roda no Windows, mas também pode analisar vestígios capturados no Linux.

Para configurar a lista de eventos a capturar, especifique-os em Advanced Options / Additional Providers:

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

TraceEvent

TraceEvent é uma biblioteca que permite consumir eventos de diferentes processos em tempo real. dotnet-trace e ambos confiam PerfView nele.

Se você quiser processar eventos programaticamente e em tempo real, consulte os TraceEvent documentos.

Iniciar e Parar eventos

Operações maiores geralmente começam com um Start evento e terminam com um Stop evento. Por exemplo, você verá RequestStart/RequestStop eventos de System.Net.Http ou/ConnectStartConnectStop eventos de .System.Net.Sockets

Embora grandes operações como essas muitas vezes garantam que um Stop evento sempre estará presente, nem sempre é esse o caso. Por exemplo, ver o RequestHeadersStart evento de System.Net.Http não garante que RequestHeadersStop também será registrado.

Correlação de eventos

Agora que você sabe como observar esses eventos, muitas vezes precisa correlacioná-los juntos, geralmente à solicitação HTTP de origem.

Prefira a coleta em processo quando possível para facilitar a correlação e a análise de eventos.

Correlação em processo

Como a rede usa E/S assíncrona, você não pode assumir que o thread que concluiu uma determinada solicitação também é o thread que a iniciou. Isso significa que você não pode usar [ThreadLocal] estática para correlacionar eventos, mas pode usar um AsyncLocalarquivo . Familiarize-se, AsyncLocal pois esse tipo é fundamental para correlacionar o trabalho em diferentes threads.

AsyncLocal Permite que você acesse o mesmo estado mais profundamente no fluxo assíncrono de uma operação. AsyncLocal os valores apenas fluem para baixo (mais profundamente na pilha de chamadas assíncronas) e não propagam as alterações até o chamador.

Considere o seguinte exemplo:

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

Este código gera o seguinte resultado:

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

O valor 1 fluiu do chamador para WorkAsynco , mas a modificação em WorkAsync (2) não fluiu de volta para o chamador.

Como os eventos de telemetria (e seus retornos de chamada correspondentes) ocorrem como parte da operação subjacente, eles acontecem dentro do mesmo escopo assíncrono do chamador que iniciou a solicitação. Isso significa que você pode observar asyncLocal.Value de dentro do retorno de chamada, mas se você definir o valor no retorno de chamada, nada será capaz de observá-lo mais acima na pilha.

As etapas a seguir mostram o padrão geral.

  1. Crie uma classe mutável que possa ser atualizada de dentro de retornos de chamada de eventos.

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

  2. Defina o AsyncLocal.Value antes da operação principal para que o estado flua para a operação.

    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. Dentro dos retornos de chamada do evento, verifique se o estado compartilhado está disponível e atualize-o. AsyncLocal.Value será null se a solicitação foi enviada por um componente que não definiu o AsyncLocal.Value em primeiro lugar.

    public void OnRequestHeadersStop(DateTime timestamp)
{
    if (_requestInfo.Value is { } info) info.HeadersSent = timestamp;
}

  4. Processar a informação recolhida após terminar a operação.

    await _client.GetStringAsync(url);

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

Para obter mais maneiras de fazer isso, consulte a seção de exemplos.

Correlação fora do processo

Cada evento tem um dado anexado a ele chamado ActivityID. Esse ID codifica a hierarquia assíncrona no momento em que o evento foi produzido.

Se você examinar um arquivo de rastreamento no PerfView, verá eventos como:

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

Você saberá que esses eventos pertencem à mesma solicitação porque compartilham o prefixo /#14396/1/1/ .

Ao fazer investigações manuais, um truque útil é procurar o System.Net.Http/Request/Start evento de uma solicitação em que você está interessado e, em seguida, colá-la ActivityID na Text Filter caixa de texto. Se você selecionar todos os provedores disponíveis, verá a lista de todos os eventos que foram produzidos como parte dessa solicitação.

O PerfView coleta automaticamente o ActivityID, mas se você usar ferramentas como dotnet-trace, deverá habilitar explicitamente o provedor (veja dotnet-trace o System.Threading.Tasks.TplEventSource:0x80:4 exemplo acima).

Solicitação HttpClient vs. tempo de vida da conexão

Desde o .NET 6, uma solicitação HTTP não está mais vinculada a uma conexão específica. Em vez disso, a solicitação será atendida assim que qualquer conexão estiver disponível.

Isso significa que você pode ver a seguinte ordem de eventos:

  1. Solicitar início
  2. Início do Dns
  3. Solicitar paragem
  4. Paragem Dns

Isso indica que a solicitação disparou uma resolução DNS, mas foi processada por uma conexão diferente antes da chamada DNS ser concluída. O mesmo vale para conexões de soquete ou handshakes TLS - a solicitação de origem pode ser concluída antes que eles o façam.

Você deve pensar sobre esses eventos separadamente. Monitore resoluções de DNS ou handshakes TLS por conta própria, sem vinculá-los à linha do tempo de uma solicitação específica.

Diagnósticos internos

Alguns componentes no .NET são instrumentados com eventos adicionais de nível de depuração que fornecem mais informações sobre exatamente o que está acontecendo internamente. Esses eventos vêm com sobrecarga de alto desempenho e sua forma está em constante mudança. Como o nome sugere, eles não fazem parte da API pública e, portanto, você não deve confiar em seu comportamento ou existência.

Independentemente disso, esses eventos podem oferecer muitos insights quando tudo o resto falha. A System.Net pilha emite esses eventos de Private.InternalDiagnostics.System.Net.* namespaces.

Se você alterar a EventListener condição no exemplo acima para eventSource.Name.Contains("System.Net"), você verá 100+ eventos de diferentes camadas na pilha. Para obter mais informações, consulte o exemplo completo.

Exemplos

Medir resoluções DNS para um determinado ponto de extremidade

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

Meça o tempo até cabeçalhos ao usar 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 para processar um pedido no ASP.NET Core que executa o Kestrel

Esta é atualmente a forma mais precisa de medir a duração de um determinado pedido.

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

Medir a latência de um proxy reverso .NET

Este exemplo é aplicável se você tiver um proxy reverso que recebe solicitações de entrada via Kestrel e faz solicitações de saída via HttpClient (por exemplo, YARP).

Este exemplo mede o tempo desde o recebimento dos cabeçalhos de solicitação até que eles sejam enviados para o servidor 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);
        }
    }
}

Precisa de mais telemetria?

Se você tiver sugestões para outras informações úteis que possam ser expostas por meio de eventos ou métricas, crie um problema dotnet/runtime.

Se você estiver usando a Yarp.Telemetry.Consumption biblioteca e tiver sugestões, crie um problema de microsoft/proxy reverso.