Сетевые события в .NET

События предоставляют доступ к следующим объектам:

• Точные метки времени в течение всего времени существования операции. Например, сколько времени потребовалось для подключения к серверу и сколько времени потребовалось HTTP-запрос для получения заголовков ответов.
• Сведения об отладке и трассировки, которые могут быть недоступны другими средствами. Например, какие решения принимает пул подключений и почему.

Инструментирование основано на EventSource, что позволяет собирать эти сведения как внутри, так и за пределами процесса.

Поставщики событий

Сведения о сети разделены по следующим поставщикам событий:

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

Данные телеметрии имеют некоторые издержки на производительность при включении, поэтому не забудьте подписаться только на поставщиков событий, которые вы действительно заинтересованы.

Использование событий в процессе

Предпочитайте коллекцию внутрипроцессных процессов, если это возможно для упрощения корреляции событий и анализа.

EventListener

EventListener — это API, который позволяет прослушивать события EventSource из того же процесса, который создал их.

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

Предыдущий код выводит выходные данные, аналогичные следующему:

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 описанный выше подход полезен для быстрого экспериментирования и отладки, API-интерфейсы не строго типизированы и принудительно зависят от сведений о реализации инструментизированной библиотеки.

Для решения этой проблемы .NET создал библиотеку, которая упрощает использование сетевых событий в процессе: Yarp.Telemetry.Consumption Хотя пакет в настоящее время поддерживается в рамках проекта YARP , его можно использовать в любом приложении .NET.

Чтобы использовать его, реализуйте интересующие вас интерфейсы и методы (события):

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

И зарегистрируйте реализации в контейнере DI:

services.AddTelemetryConsumer<MyTelemetryConsumer>();

Библиотека предоставляет следующие строго типизированные интерфейсы:

• IHttpTelemetryConsumer
• INameResolutionTelemetryConsumer
• INetSecurityTelemetryConsumer
• ISocketsTelemetryConsumer
• IKestrelTelemetryConsumer

Эти обратные вызовы вызываются как часть инструментированных операций, поэтому применяется общее руководство по ведению журнала. Следует избегать блокировки или выполнения дорогостоящих вычислений в рамках обратного вызова. Выгрузите все операции после обработки в разные потоки, чтобы избежать добавления задержки в базовую операцию.

Использование событий вне процесса

dotnet-trace

dotnet-trace — это кроссплатформенное средство, которое включает коллекцию трассировок .NET Core выполняющегося процесса без собственного профилировщика.

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

Все доступные команды и параметры см. в документации dotnet-trace.

Вы можете проанализировать захваченный .nettrace файл в Visual Studio или PerfView. Дополнительные сведения см. в документации по анализу dotnet-trace.

PerfView

PerfView — это бесплатное средство расширенного анализа производительности. Он работает в Windows, но также может анализировать трассировки, захваченные в Linux.

Чтобы настроить список событий для записи, укажите их в разделе Advanced Options / Additional Providers:

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

TraceEvent

TraceEvent — это библиотека, которая позволяет использовать события из различных процессов в режиме реального времени. dotnet-trace и PerfView оба полагаются на него.

Если вы хотите программно обрабатывать события и в режиме реального времени, см TraceEvent . в документации.

События запуска и остановки

Крупные операции часто начинаются с Start события и заканчиваются событием Stop . Например, вы увидите RequestStart/RequestStop события из System.Net.Http или/ConnectStartConnectStop из событий.System.Net.Sockets

Хотя такие крупные операции часто гарантируют, что Stop событие всегда будет присутствовать, это не всегда так. Например, просмотр RequestHeadersStart события System.Net.Http не гарантирует, что RequestHeadersStop он также будет зарегистрирован.

Корреляция событий

Теперь, когда вы знаете, как наблюдать за этими событиями, часто необходимо сопоставить их вместе, как правило, с источником HTTP-запроса.

Предпочитайте коллекцию внутрипроцессных процессов, если это возможно для упрощения корреляции событий и анализа.

Корреляция в процессе

Так как сеть использует асинхронный ввод-вывод, вы не можете предположить, что поток, завершший заданный запрос, также является потоком, который он запустил. Это означает, что вы не можете использовать [ThreadLocal] статические данные для сопоставления событий, но можно использовать AsyncLocal. Ознакомьтесь с AsyncLocal тем, что этот тип является ключом для сопоставления работы между различными потоками.

AsyncLocal позволяет получить доступ к тому же состоянию более глубоко в асинхронном потоке операции. AsyncLocal значения передаются только вниз (глубже в асинхронный стек вызовов) и не распространяют изменения до вызывающего элемента.

Рассмотрим следующий пример:

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

Этот код возвращает следующие выходные данные:

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

Значение 1 , перетекающееся из вызывающего объекта WorkAsync, но изменение в WorkAsync (2) не перетекалось обратно в вызывающий объект.

Так как события телеметрии (и соответствующие обратные вызовы) происходят в рамках базовой операции, они происходят в той же асинхронной области, что и вызывающий объект, инициирующий запрос. Это означает, что вы можете наблюдать asyncLocal.Value из обратного вызова, но если задать значение в обратном вызове, ничего не сможет наблюдать за ним дальше по стеку.

В следующих шагах показан общий шаблон.

1. Создайте изменяемый класс, который можно обновить из внутренних обратных вызовов событий.

   public sealed class RequestInfo
   {
       public DateTime StartTime, HeadersSent;
   }
   

2. AsyncLocal.Value Задайте перед основной операцией, чтобы состояние перешло в операцию.

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

3. В обратных вызовах событий проверьте, доступно ли общее состояние и обновите его. AsyncLocal.ValueЗначение <a0/>, если запрос был отправлен компонентом, который не установил его AsyncLocal.Value в первую очередь.

   public void OnRequestHeadersStop(DateTime timestamp)
   {
       if (_requestInfo.Value is { } info) info.HeadersSent = timestamp;
   }
   

4. Обработайте собранные сведения после завершения операции.

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

Дополнительные способы этого см. в разделе примеров.

Корреляция вне процесса

Каждое событие содержит часть данных, подключенных к ней ActivityID. Этот идентификатор кодирует асинхронную иерархию во время производства события.

При просмотре файла трассировки в PerfView вы увидите такие события:

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

Вы узнаете, что эти события относятся к тому же запросу, так как они совместно используют /#14396/1/1/ префикс.

При выполнении ручного исследования полезно искать System.Net.Http/Request/Start событие запроса, которое вы хотите, а затем вставьте его ActivityID в текстовое Text Filter поле. Если вы выберете всех доступных поставщиков, вы увидите список всех событий, созданных в рамках этого запроса.

PerfView автоматически собирает такие ActivityIDсредства, но при использовании таких dotnet-traceсредств необходимо явно включить System.Threading.Tasks.TplEventSource:0x80:4 поставщик (см dotnet-trace . пример выше).

Время существования запроса HttpClient и времени существования подключения

Так как .NET 6 HTTP-запрос больше не привязан к конкретному подключению. Вместо этого запрос будет обслуживаться сразу после того, как будет доступно любое подключение.

Это означает, что может отображаться следующий порядок событий:

1. Запуск запроса
2. Запуск Dns
3. Остановка запроса
4. Остановка DNS

Это означает, что запрос активировал разрешение DNS, но был обработан другим подключением до завершения вызова DNS. То же самое касается подключений сокетов или подтверждения TLS - исходный запрос может завершиться до их выполнения.

Вы должны думать о таких событиях отдельно. Отслеживайте разрешения DNS или подтверждения TLS самостоятельно, не привязывая их к временной шкале определенного запроса.

Внутренние диагностика

Некоторые компоненты в .NET инструментируются с дополнительными событиями уровня отладки, которые обеспечивают более подробное представление о том, что происходит внутри. Эти события приходят с высокими затратами на производительность, и их форма постоянно меняется. Как предполагает имя, они не являются частью общедоступного API, поэтому вы не должны полагаться на их поведение или существование.

Независимо от того, эти события могут предложить много аналитических сведений, когда все остальное завершается сбоем. Стек System.Net выдает такие события из Private.InternalDiagnostics.System.Net.* пространств имен.

Если изменить условие в приведенном EventListener выше eventSource.Name.Contains("System.Net")примере, вы увидите 100+ событий из разных слоев в стеке. Дополнительные сведения см. в полном примере.

Примеры

• Измерение разрешений DNS для данной конечной точки
• Измерение времени до заголовков при использовании HttpClient
• Время обработки запроса в ASP.NET Core под управлением Kestrel
• Измерение задержки обратного прокси-сервера .NET

Измерение разрешений DNS для данной конечной точки

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

Измерение времени до заголовков при использовании 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;
}

Время обработки запроса в ASP.NET Core под управлением Kestrel

В настоящее время это самый точный способ измерения длительности заданного запроса.

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

Измерение задержки обратного прокси-сервера .NET

Этот пример применим, если у вас есть обратный прокси-сервер, который получает входящие запросы через Kestrel и выполняет исходящие запросы через HttpClient (например, YARP).

Этот пример измеряет время получения заголовков запроса до отправки на внутренний сервер.

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

Требуется больше данных телеметрии?

Если у вас есть предложения по другим полезным сведениям, которые могут быть предоставлены с помощью событий или метрик, создайте проблему dotnet/runtime.

Если вы используете библиотеку Yarp.Telemetry.Consumption и имеете какие-либо предложения, создайте проблему с microsoft или обратным прокси-сервером.