Síťové události v .NET

Článek
12/06/2023

Události poskytují přístup k:

Přesná časová razítka po celou dobu životnosti operace. Například jak dlouho trvalo připojení k serveru a jak dlouho trvalo přijetí hlaviček odpovědi požadavek HTTP.
Informace o ladění/trasování, které nelze získat jinými prostředky. Jaký druh rozhodnutí například fond připojení udělal a proč.

Instrumentace je založená na EventSource a umožňuje shromažďovat tyto informace z procesu i mimo tento proces.

Poskytovatelé událostí

Informace o sítích jsou rozdělené mezi následující poskytovatele událostí:

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

Telemetrie má při povolení určité režijní náklady na výkon, proto se ujistěte, že se přihlašujete jenom k odběru poskytovatelů událostí, které vás skutečně zajímají.

Zpracování událostí v procesu

Pokud je to možné, upřednostněte shromažďování v procesu, aby se usnadnila korelace a analýza událostí.

EventListener

EventListener je rozhraní API, které umožňuje naslouchat událostem EventSource ze stejného procesu, který je vytvořil.

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

Předchozí kód vytiskne výstup podobný následujícímu:

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

I když je EventListener výše uvedený přístup užitečný pro rychlé experimentování a ladění, rozhraní API nejsou silně napsaná a vynutí vás, abyste záviseli na podrobnostech implementace instrumentované knihovny.

Aby bylo možné tento problém vyřešit, rozhraní .NET vytvořilo knihovnu, která usnadňuje používání síťových událostí v procesu: Yarp.Telemetry.Consumption. I když se balíček v současné době udržuje jako součást projektu YARP , lze ho použít v libovolné aplikaci .NET.

Pokud ho chcete použít, implementujte rozhraní a metody (události), které vás zajímají:

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

A zaregistrujte implementace v kontejneru DI:

services.AddTelemetryConsumer<MyTelemetryConsumer>();

Knihovna poskytuje následující rozhraní silného typu:

Tyto zpětná volání se volají jako součást instrumentované operace, takže platí obecné pokyny k protokolování. V rámci zpětného volání byste se měli vyhnout blokování nebo provádění drahých výpočtů. Přesměrujte veškerou práci po zpracování na různá vlákna, abyste se vyhnuli latenci související operace.

Využívání událostí mimo proces

dotnet-trace

dotnet-trace je multiplatformní nástroj, který umožňuje shromažďování trasování .NET Core spuštěného procesu bez nativního profileru.

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

Všechny dostupné příkazy a parametry najdete v dokumentaci k dotnet-trace.

Zachycený .nettrace soubor můžete analyzovat v sadě Visual Studio nebo PerfView. Další informace najdete v dokumentaci k analýze dotnet-trace.

PerfView

PerfView je bezplatný a pokročilý nástroj pro analýzu výkonu. Běží ve Windows, ale může také analyzovat trasování zachycená v Linuxu.

Pokud chcete nakonfigurovat seznam událostí, které se mají zachytit, zadejte je v části Advanced Options / Additional Providers:

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

TraceEvent

TraceEvent je knihovna, která umožňuje využívat události z různých procesů v reálném čase. dotnet-trace a PerfView oba se na něj spoléhají.

Pokud chcete události zpracovávat programově a v reálném čase, podívejte se na TraceEvent dokumentaci.

Spuštění a zastavení událostí

Větší operace často začínají událostí Start a končí událostí Stop . Zobrazí se RequestStart/RequestStop například události z System.Net.Http události nebo/ConnectStartConnectStop události z .System.Net.Sockets

I když velké operace, jako jsou tyto, často zaručují, že Stop událost bude vždy přítomna, není to vždy případ. Například zobrazení RequestHeadersStart události z System.Net.Http nezaručuje, že RequestHeadersStop se zaprotokoluje také.

Korelace událostí

Teď, když víte, jak tyto události sledovat, je často potřeba je vzájemně korelovat, obecně s původní požadavkem HTTP.

Pokud je to možné, upřednostněte shromažďování v procesu, aby se usnadnila korelace a analýza událostí.

Korelace v procesu

Protože sítě používají asynchronní vstupně-výstupní operace, nemůžete předpokládat, že vlákno, které dokončilo daný požadavek, je také vlákno, které ho spustilo. To znamená, že ke korelaci událostí nemůžete použít [ThreadLocal] statické objekty, ale můžete použít funkci AsyncLocal. Seznamte se s AsyncLocal tím, jak je tento typ klíčem k korelaci práce napříč různými vlákny.

AsyncLocal umožňuje přístup ke stejnému stavu hlouběji v asynchronním toku operace. AsyncLocal hodnoty proudí dolů (hlouběji do zásobníku asynchronních volání) a nešířují změny do volajícího.

Představte si následující příklad:

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

Výsledkem tohoto kódu je následující výstup:

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

Hodnota 1 , která se z volajícího WorkAsyncdostala dolů, ale změny v WorkAsync (2) neprotékaly zpět volajícímu.

Vzhledem k tomu, že události telemetrie (a jejich odpovídající zpětná volání) probíhají jako součást základní operace, probíhají ve stejném asynchronním oboru jako volající, který žádost inicioval. To znamená, že se můžete podívat asyncLocal.Value z zpětného volání, ale pokud nastavíte hodnotu v zpětném volání, nic ho nebude moct dál sledovat v zásobníku.

Následující kroky ukazují obecný vzor.

Vytvořte proměnlivou třídu, kterou lze aktualizovat z zpětných volání událostí.
```
public sealed class RequestInfo
{
    public DateTime StartTime, HeadersSent;
}
```

AsyncLocal.Value Nastavte před hlavní operaci tak, aby stav do operace proudil.

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

V zpětných voláních událostí zkontrolujte, jestli je sdílený stav dostupný, a aktualizujte ho. AsyncLocal.Value bude null v případě, že požadavek odeslala komponenta, která nenastavila AsyncLocal.Value na prvním místě.
```
public void OnRequestHeadersStop(DateTime timestamp)
{
    if (_requestInfo.Value is { } info) info.HeadersSent = timestamp;
}
```

Po dokončení operace zpracujte shromážděné informace.

await _client.GetStringAsync(url);

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

Další způsoby, jak to udělat, najdete v části s ukázkami.

Korelace mimo proces

Každá událost má připojenou část dat, která je k ní připojena ActivityID. Toto ID kóduje asynchronní hierarchii v době, kdy byla událost vytvořena.

Pokud se podíváte na trasovací soubor v nástroji PerfView, zobrazí se události jako:

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

Budete vědět, že tyto události patří do stejného požadavku, protože sdílejí předponu /#14396/1/1/ .

Při ručním šetření je užitečným trikem vyhledat System.Net.Http/Request/Start událost žádosti, kterou vás zajímá, a vložit ji ActivityID do textového Text Filter pole. Pokud teď vyberete všechny dostupné poskytovatele, zobrazí se seznam všech událostí, které byly vytvořeny jako součást této žádosti.

PerfView automaticky shromažďuje ActivityID, ale pokud používáte nástroje jako dotnet-trace, musíte explicitně povolit System.Threading.Tasks.TplEventSource:0x80:4 poskytovatele (viz dotnet-trace příklad výše).

Požadavek HttpClient vs. životnost připojení

Vzhledem k tomu, že .NET 6, požadavek HTTP už není svázaný s konkrétním připojením. Místo toho bude žádost obsluhována, jakmile bude k dispozici jakékoli připojení.

To znamená, že se může zobrazit následující pořadí událostí:

Zahájení žádosti
Spuštění Dns
Zastávka na znamení
Zastavení DNS

To znamená, že požadavek aktivoval překlad DNS, ale před dokončením volání DNS se zpracoval jiným připojením. Totéž platí pro připojení soketů nebo handshake tls – původní požadavek může být dokončen dříve, než se dokončí.

Tyto události byste měli zvážit samostatně. Monitorujte překlady DNS nebo handshake tls samostatně, aniž byste je svázali na časovou osu konkrétního požadavku.

Interní diagnostika

Některé komponenty v .NET jsou instrumentované s dalšími událostmi na úrovni ladění, které poskytují lepší přehled o tom, co se děje interně. Tyto události mají vysokou režii na výkon a jejich tvar se neustále mění. Jak název napovídá, nejsou součástí veřejného rozhraní API a proto byste se neměli spoléhat na jejich chování nebo existenci.

Bez ohledu na to, že tyto události můžou nabídnout spoustu přehledů, když všechno ostatní selže. Zásobník System.Net generuje takové události z Private.InternalDiagnostics.System.Net.* oborů názvů.

Pokud změníte podmínku v předchozím EventListener příkladu na eventSource.Name.Contains("System.Net"), zobrazí se v zásobníku 100 a více událostí z různých vrstev. Další informace najdete v úplném příkladu.

Ukázky

Měření překladů DNS pro daný koncový bod
Měření hlaviček mezi časem při použití HttpClient
Doba zpracování požadavku v ASP.NET Core, na kterém běží Kestrel
Měření latence reverzního proxy serveru .NET

Měření překladů DNS pro daný koncový bod

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

Měření hlaviček mezi časem při použití 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;
}

Doba zpracování požadavku v ASP.NET Core, na kterém běží Kestrel

Jedná se o nejpřesnější způsob měření doby trvání daného požadavku.

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

Měření latence reverzního proxy serveru .NET

Tato ukázka se dá použít, pokud máte reverzní proxy, který přijímá příchozí požadavky přes Kestrel a provádí odchozí požadavky přes HttpClient (například YARP).

Tato ukázka měří čas od přijetí hlaviček požadavků, dokud nebudou odeslány na back-endový server.

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

Potřebujete další telemetrii?

Pokud máte návrhy na další užitečné informace, které by mohly být vystaveny prostřednictvím událostí nebo metrik, vytvořte problém s dotnet/runtime.

Pokud knihovnu Yarp.Telemetry.Consumption používáte a máte nějaké návrhy, vytvořte problém s microsoftem nebo reverzním proxy serverem.

Sdílet prostřednictvím