Événements de mise en réseau dans .NET

Article
12/07/2023

Les événements vous donnent accès à :

Des horodatages exacts tout au long de la durée de vie d’une opération. Par exemple, combien de temps a pris la connexion au serveur et combien de temps a pris une requête HTTP pour la réception des en-têtes de réponse.
Des informations de débogage/suivi qui peuvent ne pas être obtenues par d’autres moyens. Par exemple, le type de décisions qui sont prises par le pool de connexions et pourquoi.

L’instrumentation est basée sur EventSource, ce qui vous permet de collecter ces informations dans le processus et en dehors du processus.

Fournisseurs d’événements

Les informations de mise n réseau sont réparties entre les fournisseurs d’événements suivants :

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

Étant donné que la télémétrie entraîne une certaine surcharge du niveau de performance quand elle est activée, abonnez-vous uniquement aux fournisseurs d’événements qui vous intéressent réellement.

Consommer des événements dans le processus

Préférez la collecte dans le processus si possible pour faciliter la mise en corrélation et l’analyse des événements.

EventListener

EventListener est une API qui vous permet d’écouter les événements EventSource à partir du processus qui les a générés.

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

Le code précédent imprime une sortie similaire à la suivante :

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

Bien que l’approche EventListener décrite ci-dessus soit utile pour une expérimentation et un débogage rapides, les API ne sont pas fortement typées et vous obligent à dépendre des détails d’implémentation de la bibliothèque instrumentée.

Pour résoudre ce problème, .NET a créé une bibliothèque qui facilite la consommation des événements de réseau dans le processus : Yarp.Telemetry.Consumption. Bien que le package soit actuellement géré dans le cadre du projet YARP, il peut être utilisé dans n’importe quelle application .NET.

Pour l’utiliser, implémentez les interfaces et les méthodes (événements) qui vous intéressent :

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

Inscrivez ensuite les implémentations dans votre conteneur DI :

services.AddTelemetryConsumer<MyTelemetryConsumer>();

La bibliothèque fournit les interfaces fortement typées suivantes :

Ces rappels étant appelés dans le cadre de l’opération instrumentée, les directives générales de journalisation s’appliquent. Vous devez éviter de bloquer ou d’effectuer des calculs coûteux dans le cadre du rappel. Déchargez tout le travail de post-traitement sur différents threads pour éviter d’ajouter de la latence à l’opération sous-jacente.

Consommer des événements en dehors du processus

dotnet-trace

dotnet-trace est un outil multiplateforme qui permet de collecter des traces .NET Core dans un processus en cours d’exécution sans profileur natif.

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

Pour voir toutes les commandes et paramètres disponibles, consultez la documentation de dotnet-trace.

Vous pouvez analyser le fichier .nettrace capturé dans Visual Studio ou PerfView. Pour plus d’informations, consultez la documentation sur l’analyse de dotnet-trace.

PerfView

PerfView est un outil d’analyse des performances avancé gratuit. Il s’exécute sur Windows, mais peut également analyser les traces capturées sur Linux.

Pour configurer la liste des événements à capturer, spécifiez-les sous Advanced Options / Additional Providers :

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

TraceEvent

TraceEvent est une bibliothèque qui vous permet de consommer des événements de différents processus en temps réel. dotnet-trace et PerfView s’appuient sur elle.

Si vous voulez traiter des événements programmatiquement et en temps réel, consultez la documentation TraceEvent.

Événements Start et Stop

Les opérations plus grandes commencent souvent par un événement Start et se terminent par un événement Stop. Par exemple, vous voyez des événements RequestStart/RequestStop de System.Net.Http ou des événements ConnectStart/ConnectStop de System.Net.Sockets.

Bien que ce type de grandes opérations garantissent souvent la présence constante d’un événement Stop, ce n’est pas toujours le cas. Par exemple, l’événement RequestHeadersStart de System.Net.Http ne garantit pas forcément la journalisation de RequestHeadersStop.

Corrélation entre les événements

Maintenant que vous savez comment observer ces événements, vous devez souvent les mettre en corrélation, généralement avec la requête HTTP d’origine.

Préférez la collecte dans le processus si possible pour faciliter la mise en corrélation et l’analyse des événements.

Mise en corrélation dans le processus

Comme le réseau utilise des E/S asynchrones, vous ne pouvez pas supposer que le thread qui a traité une demande donnée est également le thread qui l’a démarrée. Cela signifie que vous ne pouvez pas utiliser de statiques [ThreadLocal] pour mettre en corrélation les événements, mais vous pouvez utiliser un AsyncLocal. Familiarisez-vous avec AsyncLocal, car ce type est essentiel pour mettre en corrélation le travail de différents threads.

AsyncLocal vous permet d’accéder au même état plus profondément dans le flux asynchrone d’une opération. Les valeurs AsyncLocal descendent uniquement (plus profondément dans la pile des appels asynchrones) et ne propagent pas les changements à l’appelant.

Prenons l’exemple suivant :

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

Ce code génère la sortie suivante :

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

La valeur 1 est passée de l’appelant à WorkAsync, mais la modification dans WorkAsync (2) n’est pas remontée à l’appelant.

Comme les événements de télémétrie (et leurs rappels correspondants) se produisent dans le cadre de l’opération sous-jacente, ils se produisent dans la même étendue asynchrone que celle de l’appelant qui a lancé la demande. Cela signifie que vous pouvez observer asyncLocal.Value à partir du rappel, mais si vous définissez la valeur dans le rappel, rien ne peut l’observer plus haut dans la pile.

Les étapes suivantes montrent le modèle général.

Créez une classe mutable qui peut être mise à jour à partir de rappels d’événements.
```
public sealed class RequestInfo
{
    public DateTime StartTime, HeadersSent;
}
```

Définissez AsyncLocal.Valueavant l’opération principale, pour que l’état soit transmis à l’opération.

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

Dans les rappels d’événement, vérifiez que l’état partagé est disponible et mettez-le à jour. AsyncLocal.Value est null si la demande a été envoyée par un composant qui n’a pas défini AsyncLocal.Value en premier.
```
public void OnRequestHeadersStop(DateTime timestamp)
{
    if (_requestInfo.Value is { } info) info.HeadersSent = timestamp;
}
```

Traitez les informations collectées une fois l’opération terminée.

await _client.GetStringAsync(url);

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

Pour connaître les différentes façons de le faire, consultez la section Exemples.

Mise en corrélation en dehors du processus

Chaque événement est associé à un élément de données appelé ActivityID. Cet ID encode la hiérarchie asynchrone au moment où l’événement a été généré.

Si vous examinez un fichier de trace dans PerfView, vous voyez des événements de type :

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

Vous savez que ces événements appartiennent à la même demande, car ils partagent le préfixe /#14396/1/1/.

Quand vous faites des investigations manuelles, recherchez l’événement System.Net.Http/Request/Start d’une demande qui vous intéresse, puis collez-le ActivityID dans la zone de texte Text Filter. Si vous sélectionnez maintenant tous les fournisseurs disponibles, vous voyez la liste de tous les événements qui ont été générés dans le cadre de cette demande.

PerfView collecte automatiquement l’ActivityID, mais si vous utilisez des outils comme dotnet-trace, vous devez activer explicitement le fournisseur System.Threading.Tasks.TplEventSource:0x80:4 (voir l’exemple dotnet-trace ci-dessus).

Durée de vie de la demande HttpClient et durée de vie de la connexion

Depuis .NET 6, une requête HTTP n’est plus liée à une connexion spécifique. À la place, la demande est traitée dès qu’une connexion est disponible.

Cela signifie que vous pouvez voir l’ordre d’événements suivant :

Request start
Dns start
Request stop
Dns stop

Cela indique que la demande a déclenché une résolution DNS, mais qu’elle a été traitée par une autre connexion avant la fin de l’appel DNS. Il en va de même pour les connexions de socket ou les liaisons TLS : la demande d’origine peut se terminer avant elles.

Vous devez dissocier ce type d’événements. Monitorez les résolutions DNS ou les liaisons TLS par elles-mêmes, sans les rattacher à la chronologie d’une demande spécifique.

Diagnostics internes

Certains composants de .NET sont instrumentés avec des événements de niveau débogage supplémentaires qui fournissent plus d’informations sur ce qui se passe en interne. Ces événements ont une surcharge haute performance et leur forme change constamment. Comme leur nom l’indique, ils ne font pas partie de l’API publique et vous ne devez donc pas vous appuyer sur leur comportement ou leur existence.

Quoi qu’il en soit, ces événements peuvent offrir beaucoup d’informations quand tout le reste échoue. La pile System.Net émet ce type d’événements à partir d’espaces de noms Private.InternalDiagnostics.System.Net.*.

Si vous remplacez la condition dans l’exemple d’EventListener ci-dessus par eventSource.Name.Contains("System.Net"), vous voyez plus de 100 événements de différents couches dans la pile. Pour plus d’informations, consultez l’exemple complet.

Exemples

Mesurer les résolutions DNS pour un point de terminaison donné
Mesurer la durée de traitement des en-têtes pendant l’utilisation de HttpClient
Délai de traitement d’une demande dans ASP.NET Core exécutant Kestrel
Mesurer la latence d’un proxy inverse .NET

Mesurer les résolutions DNS pour un point de terminaison donné

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

Mesurer la durée de traitement des en-têtes pendant l’utilisation de 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;
}

Délai de traitement d’une demande dans ASP.NET Core en exécutant Kestrel

Il s’agit actuellement de la façon la plus exacte de mesurer la durée d’une demande donnée.

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

Mesurer la latence d’un proxy inverse .NET

Cet exemple s’applique si vous avez un proxy inverse qui reçoit des demandes entrantes via Kestrel et effectue des demandes sortantes via HttpClient (par exemple, YARP).

Cet exemple mesure la durée entre la réception des en-têtes de demande et leur envoi au serveur de 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);
        }
    }
}

Vous avez besoin de données de télémétrie supplémentaires ?

Si vous avez des suggestions pour d’autres informations utiles pouvant être exposées via des événements ou des métriques, créez un problème dotnet/runtime.

Si vous utilisez la bibliothèque Yarp.Telemetry.Consumption et que vous avez des suggestions, créez un problème microsoft/reverse-proxy.

Partager via