Eventos de red en .NET

Artículo
12/06/2023

Los eventos proporcionan acceso a lo siguiente:

Marcas de tiempo exactas a lo largo de la duración de una operación Por ejemplo, cuánto tiempo se ha tardado en conectar con el servidor y cuánto tiempo ha tardado una solicitud HTTP en recibir encabezados de respuesta.
Información de depuración/seguimiento que no se puede obtener por otros medios (por ejemplo, qué tipo de decisiones ha tomado el grupo de conexiones y por qué).

La instrumentación se basa en EventSource, lo que permite recopilar esta información tanto desde dentro como desde fuera del proceso.

Proveedores de eventos

La información de red se divide en los siguientes proveedores de eventos:

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

La telemetría conlleva cierta sobrecarga de rendimiento cuando está habilitada, así que procure suscribirse únicamente a los proveedor de eventos que realmente le interesen.

Consumo de eventos desde dentro del proceso

Siempre que sea posible, decántese por la recopilación en proceso para facilitar la correlación y el análisis de eventos.

EventListener

EventListener es una API que permite escuchar eventos EventSource desde dentro del mismo proceso que los generó.

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

El código anterior imprime una salida similar a la siguiente:

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

Aunque el enfoque de EventListener descrito anteriormente es útil para una experimentación y depuración rápidas, las API no están fuertemente tipadas y obligan a depender de los detalles de implementación de la biblioteca instrumentada.

Para abordar esto, .NET creó una biblioteca que facilita el uso de eventos de red en proceso: Yarp.Telemetry.Consumption. Aunque actualmente el paquete se mantiene como parte del proyecto YARP, se puede usar en cualquier aplicación .NET.

Para usarlo, implemente las interfaces y los métodos (eventos) de su interés:

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

Luego, registre las implementaciones con el contenedor de inserción de dependencias:

services.AddTelemetryConsumer<MyTelemetryConsumer>();

La biblioteca proporciona las siguientes interfaces fuertemente tipadas:

A estas devoluciones de llamada se las llama como parte de la operación instrumentada, por lo que las directrices de registro generales son de aplicación. Absténgase de bloquear o realizar cálculos costosos como parte de la devolución de llamada. Descargue cualquier trabajo posterior al procesamiento en subprocesos diferentes para evitar agregar latencia a la operación subyacente.

Consumo de eventos desde fuera del proceso

dotnet-trace

dotnet-trace es una herramienta multiplataforma que permite la recolección de seguimientos de .NET Core de un proceso en ejecución sin un generador de perfiles 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 ver todos los comandos y parámetros disponibles, vea la documentación de dotnet-trace.

Puede analizar el archivo .nettrace capturado en Visual Studio o en PerfView. Para obtener más información, consulte la documentación de análisis de dotnet-trace.

PerfView

PerfView es una herramienta de análisis de rendimiento avanzado gratuita. Funciona con Windows, pero también puede analizar los seguimientos capturados en Linux.

Para configurar la lista de eventos que capturar, especifíquelos en Advanced Options / Additional Providers:

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

TraceEvent

TraceEvent es una biblioteca que permite consumir eventos de diferentes procesos en tiempo real. Tanto dotnet-trace como PerfView se basan en ella.

Si desea procesar eventos mediante programación y en tiempo real, consulte la documentación de TraceEvent.

Inicio y detención de eventos

Las operaciones más grandes suelen comenzar con un evento Start y terminar con un evento Stop. Por ejemplo, verá eventos RequestStart/RequestStop de System.Net.Http o eventos ConnectStart/ConnectStop de System.Net.Sockets.

Aunque las operaciones de gran tamaño como estas suelen garantizar que siempre va a haber presente un evento Stop, esto no siempre es así. Por ejemplo, ver el evento RequestHeadersStart de System.Net.Http no garantiza que también vaya a registrarse RequestHeadersStop.

Correlación de eventos

Ahora que sabe cómo analizar estos eventos, a menudo deberá correlacionarlos entre sí, por lo general con la solicitud HTTP de origen.

Siempre que sea posible, decántese por la recopilación en proceso para facilitar la correlación y el análisis de eventos.

Correlación desde dentro del proceso

Como las redes usan E/S asincrónica, no se puede dar por hecho que un subproceso que haya completado una solicitud determinada es también el subproceso que la ha iniciado. Esto significa que no se pueden usar estáticos [ThreadLocal] para correlacionar eventos, pero sí usar AsyncLocal. Acostúmbrese a usar AsyncLocal, ya que este tipo es clave para correlacionar el trabajo entre diferentes subprocesos.

AsyncLocal permite acceder al mismo estado más profundamente hacia el flujo asincrónico de una operación. Los valores de AsyncLocal solo fluyen hacia abajo (más profundamente hacia la pila de llamadas asincrónicas) y no propagan los cambios hasta el autor de la llamada.

Considere el ejemplo siguiente:

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 genera la siguiente salida:

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

El valor de 1 fluye hacia abajo desde el autor de la llamada a WorkAsync, pero la modificación de WorkAsync (2) no fluye hacia el autor de la llamada.

A medida que los eventos de telemetría (y sus devoluciones de llamada correspondientes) se van sucediendo como parte de la operación subyacente, se producen dentro del mismo ámbito asincrónico que el llamador que inició la solicitud. Esto significa que asyncLocal.Value se puede observar desde dentro de la devolución de llamada, pero si el valor se establece en la devolución de llamada, no se podrá observar nada más allá de la pila.

Los siguientes pasos muestran el patrón general.

Cree una clase mutable que se pueda actualizar desde dentro de las devoluciones de llamada de eventos.
```
public sealed class RequestInfo
{
    public DateTime StartTime, HeadersSent;
}
```

Establezca AsyncLocal.Valueantes de la operación principal para que el estado fluya hacia la operación.

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 de las devoluciones de llamada de eventos, compruebe si el estado compartido está disponible y actualícelo. AsyncLocal.Value será null si la solicitud se ha enviado mediante un componente donde no se estableció AsyncLocal.Value desde un principio.
```
public void OnRequestHeadersStop(DateTime timestamp)
{
    if (_requestInfo.Value is { } info) info.HeadersSent = timestamp;
}
```

Procese la información recopilada después de finalizar la operación.

await _client.GetStringAsync(url);

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

Para conocer más formas de hacerlo, consulte la sección de ejemplos.

Correlación desde fuera del proceso

Cada evento tiene adjunto un dato denominado ActivityID. Este identificador codifica la jerarquía asincrónica en el momento en que se generó el evento.

Si analiza un archivo de seguimiento en PerfView, verá eventos como los siguientes:

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

Sabrá que estos eventos pertenecen a la misma solicitud porque comparten el prefijo /#14396/1/1/.

Al realizar investigaciones manuales, un truco útil consiste en buscar el evento System.Net.Http/Request/Start de una solicitud de su interés y, a continuación, pegar su ActivityID en el cuadro de texto Text Filter. Si ahora selecciona todos los proveedores disponibles, verá la lista de todos los eventos que se generaron como parte de esa solicitud.

PerfView recopila los ActivityID automáticamente, pero si usa herramientas como dotnet-trace, deberá habilitar explícitamente el proveedor System.Threading.Tasks.TplEventSource:0x80:4 (consulte el ejemplo de dotnet-trace anterior).

Duración de la solicitud HttpClient frente a duración de la conexión

Desde .NET 6, una solicitud HTTP ya no está vinculada a una conexión específica, sino que las solicitudes se atienden en cuanto haya cualquier conexión disponible.

Esto significa que puede ver los siguiente eventos en orden:

Request start
Dns start
Request stop
Dns stop

Esto indica que la solicitud desencadenó una resolución DNS, pero se procesó mediante una conexión diferente antes de que la llamada DNS se completara. Lo mismo sucede con las conexiones de socket o los protocolos de enlace TLS: la solicitud de origen puede finalizar antes de que ellos lo hagan.

Estos eventos se deben considerar por separado. Supervise las resoluciones DNS o los protocolos de enlace TLS de manera aislada, sin vincularlos con el tiempo de una solicitud específica.

Diagnósticos internos

Algunos componentes de .NET se instrumentan con eventos de nivel de depuración adicionales que proporcionan más información sobre lo que sucede internamente. Estos eventos vienen con una sobrecarga de alto rendimiento y su forma cambia constantemente. Como el nombre sugiere, no forman parte de la API pública y, por tanto, no debe basarse en su comportamiento o existencia.

Independientemente de ello, estos eventos pueden ofrecer cuantiosa información cuando todo lo demás falla. La pila System.Net emite este tipo de eventos desde espacios de nombres Private.InternalDiagnostics.System.Net.*.

Si cambiáramos la condición del ejemplo de EventListener anterior a eventSource.Name.Contains("System.Net"), veríamos más de 100 eventos de diferentes capas de la pila. Para obtener más información, vea el ejemplo completo.

Ejemplos

Medición de resoluciones DNS de un punto de conexión determinado
Medición de los tiempos de encabezado al usar HttpClient
Tiempo para procesar una solicitud en ASP.NET Core cuando se usa Kestrel
Medición de la latencia de un proxy inverso de .NET

Medición de resoluciones DNS de un punto de conexión determinado

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

Medición de los tiempos de encabezado al 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;
}

Tiempo para procesar una solicitud en ASP.NET Core cuando se usa Kestrel

Actualmente esta es la forma más precisa de medir la duración de una solicitud determinada.

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

Medición de la latencia de un proxy inverso de .NET

Este ejemplo procede si existe un proxy inverso que recibe solicitudes entrantes a través de Kestrel y realiza solicitudes salientes a través de HttpClient (por ejemplo: YARP).

Este ejemplo mide el tiempo que transcurre desde que se reciben los encabezados de solicitud hasta que se envían al servidor backend.

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

¿Necesita más telemetría?

Si tiene alguna sugerencia relativa a otra información de utilidad que podría exponerse a través de eventos o métricas, cree una incidencia de dotnet/runtime.

Si usa la biblioteca Yarp.Telemetry.Consumption y tiene alguna sugerencia, cree una incidencia de microsoft/reverse-proxy.

Compartir a través de