Zdarzenia sieciowe na platformie .NET

Artykuł
12/06/2023

Zdarzenia zapewniają dostęp do:

Dokładne znaczniki czasu przez cały okres istnienia operacji. Na przykład czas nawiązywania połączenia z serwerem i czas odbierania nagłówków odpowiedzi przez żądanie HTTP.
Informacje debugowania/śledzenia, które mogą nie być dostępne w inny sposób. Na przykład jakie decyzje podejmuje pula połączeń i dlaczego.

Instrumentacja jest oparta na usłudze EventSource, umożliwiając zbieranie tych informacji zarówno z wewnątrz, jak i poza procesem.

Dostawcy zdarzeń

Informacje o sieci są podzielone między następujących dostawców zdarzeń:

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

Dane telemetryczne mają pewne obciążenie związane z wydajnością po włączeniu, dlatego upewnij się, że subskrybujesz tylko dostawców zdarzeń, których rzeczywiście interesujesz.

Korzystanie ze zdarzeń w procesie

Preferuj zbieranie w procesie, jeśli jest to możliwe, aby ułatwić korelację i analizę zdarzeń.

EventListener

EventListener to interfejs API, który umożliwia nasłuchiwanie zdarzeń EventSource z poziomu tego samego procesu, który je wygenerował.

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

Powyższy kod wyświetla dane wyjściowe podobne do następujących:

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

EventListener Chociaż opisane powyżej podejście jest przydatne w przypadku szybkiego eksperymentowania i debugowania, interfejsy API nie są silnie typizowane i wymuszają zależność od szczegółów implementacji instrumentowanej biblioteki.

Aby rozwiązać ten problem, platforma .NET utworzyła bibliotekę, która ułatwia przetwarzanie zdarzeń sieciowych: Yarp.Telemetry.Consumption. Pakiet jest obecnie obsługiwany w ramach projektu YARP , ale może być używany w dowolnej aplikacji platformy .NET.

Aby go użyć, zaimplementuj interfejsy i metody (zdarzenia), które cię interesują:

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

I zarejestruj implementacje w kontenerze DI:

services.AddTelemetryConsumer<MyTelemetryConsumer>();

Biblioteka udostępnia następujące silnie typizowane interfejsy:

Te wywołania zwrotne są wywoływane w ramach operacji instrumentowanej, więc mają zastosowanie ogólne wskazówki dotyczące rejestrowania. Należy unikać blokowania lub wykonywania kosztownych obliczeń w ramach wywołania zwrotnego. Odciążaj wszystkie zadania po przetwarzaniu do różnych wątków, aby uniknąć dodawania opóźnień do podstawowej operacji.

Korzystanie ze zdarzeń spoza procesu

dotnet-trace

dotnet-trace to międzyplatformowe narzędzie, które umożliwia zbieranie śladów platformy .NET Core działającego procesu bez natywnego profilera.

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

Wszystkie dostępne polecenia i parametry można znaleźć w dokumentacji dotnet-trace.

Przechwycony .nettrace plik można analizować w programie Visual Studio lub Programie PerfView. Aby uzyskać więcej informacji, zobacz dokumentację dotnet-trace analysis.

Narzędzie PerfView

Narzędzie PerfView to bezpłatne, zaawansowane narzędzie do analizy wydajności. Działa on w systemie Windows, ale może również analizować ślady przechwycone w systemie Linux.

Aby skonfigurować listę zdarzeń do przechwycenia, określ je w obszarze Advanced Options / Additional Providers:

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

TraceEvent

TraceEvent to biblioteka, która umożliwia korzystanie ze zdarzeń z różnych procesów w czasie rzeczywistym. dotnet-trace i PerfView oba polegają na nim.

Jeśli chcesz przetwarzać zdarzenia programowo i w czasie rzeczywistym, zobacz dokumentację TraceEvent .

Uruchamianie i zatrzymywanie zdarzeń

Większe operacje często zaczynają się od Start zdarzenia i kończą się zdarzeniem Stop . Na przykład zobaczysz RequestStart/RequestStop zdarzenia z lub System.Net.Http/ConnectStartConnectStop zdarzenia z .System.Net.Sockets

Chociaż duże operacje, takie jak te, często gwarantują, że Stop zdarzenie zawsze będzie obecne, nie zawsze jest tak. Na przykład wyświetlanie RequestHeadersStart zdarzenia z System.Net.Http programu nie gwarantuje, że RequestHeadersStop również zostanie zarejestrowane.

Korelacja zdarzeń

Teraz, gdy już wiesz, jak obserwować te zdarzenia, często trzeba je skorelować ze sobą, zazwyczaj do źródłowego żądania HTTP.

Preferuj zbieranie w procesie, jeśli jest to możliwe, aby ułatwić korelację i analizę zdarzeń.

Korelacja w procesie

Ponieważ sieć używa asynchronicznego we/wy, nie można założyć, że wątek, który zakończył określone żądanie, jest również wątkiem, który go uruchomił. Oznacza to, że nie można używać [ThreadLocal] statycznych do korelowania zdarzeń, ale można użyć elementu AsyncLocal. Zapoznaj się z AsyncLocal tym typem, ponieważ ten typ jest kluczem do korelowania pracy w różnych wątkach.

AsyncLocal umożliwia uzyskanie dostępu do tego samego stanu bardziej szczegółowego w przepływie asynchronicznego operacji. AsyncLocal wartości przepływają tylko w dół (głębiej do stosu wywołań asynchronicznych) i nie propagują zmian do elementu wywołującego.

Rozważmy następujący przykład:

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

Ten kod spowoduje wygenerowanie następujących danych wyjściowych:

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

Wartość 1 przepływa z obiektu wywołującego do WorkAsyncelementu , ale modyfikacja w WorkAsync pliku (2) nie przepływa z powrotem do obiektu wywołującego.

Ponieważ zdarzenia telemetrii (i odpowiadające im wywołania zwrotne) występują w ramach operacji bazowej, występują one w tym samym zakresie asynchronicznym co obiekt wywołujący, który zainicjował żądanie. Oznacza to, że można obserwować asyncLocal.Value z poziomu wywołania zwrotnego, ale jeśli ustawisz wartość wywołania zwrotnego, nic nie będzie w stanie obserwować go dalej w górę stosu.

W poniższych krokach przedstawiono ogólny wzorzec.

Utwórz modyfikowalny klasę, którą można zaktualizować z wewnątrz wywołań zwrotnych zdarzeń.
```
public sealed class RequestInfo
{
    public DateTime StartTime, HeadersSent;
}
```

Ustaw wartość AsyncLocal.Value przed operacją główną, aby stan przepływał do operacji.

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

Wewnątrz wywołań zwrotnych zdarzeń sprawdź, czy stan udostępniony jest dostępny, i zaktualizuj go. AsyncLocal.Value będzie to null , jeśli żądanie zostało wysłane przez składnik, który nie ustawił AsyncLocal.Value elementu w pierwszej kolejności.
```
public void OnRequestHeadersStop(DateTime timestamp)
{
    if (_requestInfo.Value is { } info) info.HeadersSent = timestamp;
}
```

Przetwarzaj zebrane informacje po zakończeniu operacji.

await _client.GetStringAsync(url);

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

Aby uzyskać więcej sposobów, zobacz sekcję przykłady.

Korelacja poza procesem

Każde zdarzenie ma dołączony element danych o nazwie ActivityID. Ten identyfikator koduje hierarchię asynchroniową w momencie utworzenia zdarzenia.

Jeśli spojrzysz na plik śledzenia w programie PerfView, zobaczysz zdarzenia takie jak:

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

Będziesz wiedzieć, że te zdarzenia należą do tego samego żądania, ponieważ współużytkują /#14396/1/1/ prefiks.

Podczas wykonywania ręcznych badań przydatną sztuczką jest wyszukanie System.Net.Http/Request/Start zdarzenia interesującego Cię żądania, a następnie wklejenie go ActivityID w polu tekstowym Text Filter . Jeśli teraz wybierzesz wszystkich dostępnych dostawców, zobaczysz listę wszystkich zdarzeń, które zostały wygenerowane w ramach tego żądania.

Narzędzie PerfView automatycznie zbiera element ActivityID, ale jeśli używasz narzędzi takich jak dotnet-trace, musisz jawnie włączyć dostawcę System.Threading.Tasks.TplEventSource:0x80:4 (zobacz dotnet-trace przykład powyżej).

Żądanie HttpClient a okres istnienia połączenia

Ponieważ platforma .NET 6, żądanie HTTP nie jest już powiązane z określonym połączeniem. Zamiast tego żądanie będzie obsługiwane natychmiast po udostępnieniu dowolnego połączenia.

Oznacza to, że może być widoczna następująca kolejność zdarzeń:

Rozpoczęcie żądania
Uruchamianie systemu DNS
Zatrzymywanie żądania
Zatrzymywanie dns

Oznacza to, że żądanie wyzwoliło rozpoznawanie nazw DNS, ale zostało przetworzone przez inne połączenie przed zakończeniem wywołania DNS. To samo dotyczy połączeń gniazd lub uzgadniań TLS — żądanie źródłowe może zostać ukończone przed wykonaniem.

Takie wydarzenia należy traktować oddzielnie. Monitoruj rozwiązania DNS lub uzgadniania protokołu TLS samodzielnie bez wiązania ich z osią czasu określonego żądania.

Diagnostyka wewnętrzna

Niektóre składniki platformy .NET są instrumentowane przy użyciu dodatkowych zdarzeń na poziomie debugowania, które zapewniają lepszy wgląd w dokładnie to, co dzieje się wewnętrznie. Te zdarzenia mają duże obciążenie związane z wydajnością, a ich kształt stale się zmienia. Jak sugeruje nazwa, nie są one częścią publicznego interfejsu API i dlatego nie należy polegać na ich zachowaniu ani istnieniu.

Niezależnie od tego, te zdarzenia mogą oferować wiele szczegółowych informacji, gdy wszystkie inne awarie kończą się niepowodzeniem. System.Net Stos emituje takie zdarzenia z Private.InternalDiagnostics.System.Net.* przestrzeni nazw.

Jeśli zmienisz warunek w powyższym przykładzie EventListener na eventSource.Name.Contains("System.Net"), zobaczysz 100 zdarzeń z różnych warstw w stosie. Aby uzyskać więcej informacji, zobacz pełny przykład.

Przykłady

Mierzenie rozdzielczości DNS dla danego punktu końcowego
Mierzenie nagłówków czasu do nagłówków w przypadku korzystania z obiektu HttpClient
Czas na przetworzenie żądania w ASP.NET Core z uruchomioną biblioteką Kestrel
Mierzenie opóźnienia zwrotnego serwera proxy platformy .NET

Mierzenie rozdzielczości DNS dla danego punktu końcowego

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

Mierzenie nagłówków czasu do nagłówków w przypadku korzystania z obiektu 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;
}

Czas na przetworzenie żądania w ASP.NET Core z uruchomioną biblioteką Kestrel

Jest to obecnie najbardziej dokładny sposób mierzenia czasu trwania danego żądania.

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

Mierzenie opóźnienia zwrotnego serwera proxy platformy .NET

Ten przykład ma zastosowanie, jeśli masz zwrotny serwer proxy, który odbiera żądania przychodzące za pośrednictwem usługi Kestrel i wysyła żądania wychodzące za pośrednictwem klienta HttpClient (na przykład YARP).

Ten przykład mierzy czas odbierania nagłówków żądań do momentu wysłania ich na serwer zaplecza.

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

Potrzebujesz więcej danych telemetrycznych?

Jeśli masz sugestie dotyczące innych przydatnych informacji, które mogą być uwidocznione za pośrednictwem zdarzeń lub metryk, utwórz problem z dotnet/runtime.

Jeśli używasz Yarp.Telemetry.Consumption biblioteki i masz jakiekolwiek sugestie, utwórz problem z serwerem microsoft/reverse-proxy.

Udostępnij za pośrednictwem