.NET 中的网络事件

通过事件,你可以访问:

  • 操作整个生存期内的准确时间戳。 例如,连接到服务器所需的时间以及 HTTP 请求接收响应标头所需的时间。
  • 可能无法通过其他方式获取的调试/跟踪信息。 例如,连接池做出的决策类型以及原因。

检测基于 EventSource,使你能够从进程内部和外部收集此信息。

事件提供程序

网络信息在以下事件提供程序进行拆分:

  • System.Net.HttpHttpClientSocketsHttpHandler
  • 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>();

该库提供以下强类型接口:

这些回调作为检测操作的一部分调用,因此常规日志记录指南适用。 作为回调的一部分,应避免阻止或执行任何昂贵的计算。 将任何后处理工作卸载到不同的线程,以避免增加基础操作的延迟。

使用来自进程外部的事件

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-tracePerfView 都依赖它。

如果要以编程方式实时处理事件,请参阅 TraceEvent 文档。

启动和停止事件

较大的操作通常从 Start 事件开始,以 Stop 事件结束。 例如,你将看到来自 System.Net.HttpRequestStart/RequestStop 事件或来自 System.Net.SocketsConnectStart/ConnectStop 事件。

虽然此类大型操作通常保证 Stop 事件始终存在,但这种情况并不总是如此。 例如,查看来自 System.Net.HttpRequestHeadersStart 事件并不能保证也会记录 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 解析

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/反向代理问题