Eventos de rede no .NET

Artigo
12/06/2023

Os eventos dão acesso a:

Carimbos de data/hora precisos ao longo do tempo de vida de uma operação. Por exemplo, quanto tempo levou para se conectar ao servidor e quanto tempo levou para uma solicitação HTTP receber cabeçalhos de resposta.
Informações de depuração/rastreamento 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 em EventSource, permitindo que você colete essas informações de dentro e de fora do processo.

Provedores de eventos

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

System.Net.Http (HttpClient 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 habilitada, portanto, certifique-se de assinar apenas provedor 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

O EventListener é uma API que permite escutar eventos EventSource de dentro 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.Telemetry.Consumption

Embora a abordagem EventListener 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 em processo: Yarp.Telemetry.Consumption. Embora o pacote seja mantido atualmente como parte do projeto YARP, ele pode ser usado em qualquer aplicativo .NET.

Para usá-lo, implemente as interfaces e os métodos (eventos) nos quais 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 de 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, as diretrizes gerais de registro em log se aplicam. Você deve evitar bloquear ou executar cálculos caros como parte do retorno de chamada. Descarregue qualquer trabalho pós-processamento em threads diferentes para evitar adicionar latência à operação subjacente.

Consumir eventos de fora do processo

dotnet-trace

dotnet-trace é uma ferramenta multiplataforma que habilita a coleção 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 conhecer todos os comandos e parâmetros disponíveis, consulte a documentação do dotnet-trace.

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

PerfView

PerfView é uma ferramenta de análise de desempenho avançada e gratuita. Ele é executado no Windows, mas também pode analisar rastreamentos capturados no Linux.

Para configurar a lista de eventos a serem capturados, 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 que você consuma eventos de processos diferentes em tempo real. dotnet-trace e PerfView dependem dele.

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

Iniciar e parar eventos

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

Embora operações grandes como essas geralmente garantam que um evento Stop sempre estará presente, nem sempre é o caso. Por exemplo, ver o evento RequestHeadersStart 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 você precisa correlacioná-los, geralmente com a 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 estática [ThreadLocal] para correlacionar eventos, mas pode usar um AsyncLocal. Familiarize-se com 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. Os valores AsyncLocal fluem apenas para baixo (mais profundamente na pilha de chamadas assíncronas) e não propagam alterações para 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 produz a seguinte saída:

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

O valor 1 fluiu do chamador para WorkAsync, 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 ocorrem dentro do mesmo escopo assíncrono que o 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 poderá observá-lo mais adiante na pilha.

As etapas a seguir mostram o padrão geral.

Crie uma classe mutável que pode ser atualizada de dentro de retornos de chamada de evento.
```
public sealed class RequestInfo
{
    public DateTime StartTime, HeadersSent;
}
```

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

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 tiver sido 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;
}
```

Processe as informações coletadas após concluir a operação.

await _client.GetStringAsync(url);

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

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

Correlação fora do processo

Cada evento tem uma porção de dados anexado a ele chamada ActivityID. Essa ID codifica a hierarquia assíncrona no momento em que o evento foi produzido.

Se você examinar um arquivo de rastreamento em 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 eles compartilham o prefixo /#14396/1/1/.

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

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

Solicitação HttpClient versus 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ê poderá ver a seguinte ordem de eventos:

Início da solicitação
Início do DNS
Parada da solicitação
Parada do 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 de TLS – a solicitação de origem pode ser concluída antes disso.

Pense nesses eventos separadamente. Monitore as resoluções DNS ou handshakes TLS por conta própria sem vinculá-los à linha do tempo de uma solicitação específica.

Diagnóstico interno

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á mudando constantemente. 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 todos os outros falham. A pilha System.Net emite esses eventos de namespaces Private.InternalDiagnostics.System.Net.*.

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

Exemplos

Medir resoluções DNS para um determinado ponto de extremidade
Medir o tempo de cabeçalhos ao usar HttpClient
Tempo para processar uma solicitação no ASP.NET Core executando o Kestrel
Medir a latência de um proxy reverso do .NET

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

Medir o tempo de 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 uma solicitação no ASP.NET Core executando o Kestrel

Atualmente, essa é a maneira mais precisa de medir a duração de uma determinada solicitação.

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 do .NET

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

Este exemplo mede o tempo de recebimento dos cabeçalhos de solicitação até que eles sejam enviados ao 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 de dotnet/runtime.

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

Compartilhar via