.NET 中的網路事件

事件可讓您存取：

• 整個作業存留期的精確時間戳記。 例如，連線至伺服器所花費的時間，以及 HTTP 要求接收回應標頭所花費的時間。
• 可能無法透過其他方法取得的偵錯/追蹤資訊。 例如，連線集區所做的決策類型及原因。

檢測以 EventSource 為基礎，可讓您從處理程序內部和外部收集此資訊。

事件提供者

網路資訊會分割到下列事件提供者：

• System.Net.Http (HttpClient 和 SocketsHttpHandler)
• 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 docs 文件。

您可以在 Visual Studio 或 .nettracePerfView 中分析所擷取的 檔案。 如需詳細資訊，請參閱 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。 此識別碼會在產生事件時編碼非同步階層。

如果您在 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 反向 Proxy 的延遲

測量指定端點的 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 反向 Proxy 的延遲

如果您有反向 Proxy 可透過 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/reverse-proxy 問題。