.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 文档。

可以在 Visual Studio 或 PerfView 中分析捕获的 .nettrace 文件。 有关详细信息，请参阅 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 事件结束。 例如，你将看到来自 System.Net.Http 的 RequestStart/RequestStop 事件或来自 System.Net.Sockets 的 ConnectStart/ConnectStop 事件。

虽然此类大型操作通常保证 Stop 事件始终存在，但这种情况并不总是如此。 例如，查看来自 System.Net.Http 的 RequestHeadersStart 事件并不能保证也会记录 RequestHeadersStop。

事件关联

现在你已知道如何观察这些事件，通常需要将它们关联在一起，一般与原始 HTTP 请求相关联。

尽可能选择进程内收集，以便更轻松地进行事件关联和分析。

进程内关联

由于网络使用异步 I/O，因此不能假定完成给定请求的线程也是启动该请求的线程。 这意味着不能使用 [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 的组件发送的，则 AsyncLocal.Value 将为 null。

   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。 此 ID 在生成事件时对异步层次结构进行编码。

如果在 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 时测量标头时间
• 在运行 Kestrel 的 ASP.NET Core 中处理请求的时间
• 测量 .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;
}

在运行 Kestrel 的 ASP.NET Core 中处理请求的时间

这是目前测量给定请求持续时间的最准确方法。

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/运行时问题。

如果使用的是 Yarp.Telemetry.Consumption 库并有任何建议，请创建 microsoft/反向代理问题。