C# HttpClient 响应时间分解

Question

C# HttpClient 响应时间分解

Hag*_*hen 6 c# httpclient .net-core

我正在尝试使用运行.net 6HttpClient客户端来测量特定请求的服务器响应时间。

在调用之前放置秒表GetAsync通常会在120-140毫秒之间返回。

Url在浏览器（Chrome 和 FireFox、开发人员工具上的网络选项卡）上检查 Same 大约会在30-40毫秒后正常返回。

查看服务器日志通常显示20-25毫秒。（仅显示纯服务器响应时间）

我认为造成巨大差距的原因是因为在我的HttpClient测量中我还计算了 DNS 查找、TLS 握手等。

使用 Curl 我可以得到时间的细分：

time_namelookup:  0.003154s
time_connect:  0.049069s
time_appconnect:  0.121174s
time_pretransfer:  0.121269s
time_redirect:  0.000000s
time_starttransfer:  0.170894s
time_total:  0.171033s

Run Code Online (Sandbox Code Playgroud)

我可以使用 C# 执行这种时间分解吗HttpClient？

DelegatingHandler我在使用和放置Stopwatchbefore方面取得了一些进展SendAsync。（比总时间少了大约 5 毫秒 - 我猜是在 dns 查找之后）

我发现关于此的文档很少，有什么指示吗？

提前致谢。

Answer 1

Evk*_*Evk 4

您可以按照此处HttpClient所述使用遥测事件：

class Program
{
    private static readonly HttpClient _client = new HttpClient();

    static async Task Main()
    {
        // Instantiate the listener which subscribes to the events. 
        using var listener = new HttpEventListener();

        // Send an HTTP request.
        using var response = await _client.GetAsync("https://github.com/runtime");
    }
}

internal sealed class HttpEventListener : EventListener
{
    // Constant necessary for attaching ActivityId to the events.
    public const EventKeywords TasksFlowActivityIds = (EventKeywords)0x80;

    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        // List of event source names provided by networking in .NET 5.
        if (eventSource.Name == "System.Net.Http" ||
            eventSource.Name == "System.Net.Sockets" ||
            eventSource.Name == "System.Net.Security" ||
            eventSource.Name == "System.Net.NameResolution")
        {
            EnableEvents(eventSource, EventLevel.LogAlways);
        }
        // Turn on ActivityId.
        else if (eventSource.Name == "System.Threading.Tasks.TplEventSource")
        {
            // Attach ActivityId to the events.
            EnableEvents(eventSource, EventLevel.LogAlways, TasksFlowActivityIds);
        }
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        var sb = new StringBuilder().Append($"{eventData.TimeStamp:HH:mm:ss.fffffff}  {eventData.ActivityId}.{eventData.RelatedActivityId}  {eventData.EventSource.Name}.{eventData.EventName}(");
        for (int i = 0; i < eventData.Payload?.Count; i++)
        {
            sb.Append(eventData.PayloadNames?[i]).Append(": ").Append(eventData.Payload[i]);
            if (i < eventData.Payload?.Count - 1)
            {
                sb.Append(", ");
            }
        }

        sb.Append(")");
        Console.WriteLine(sb.ToString());
    }
}

Run Code Online (Sandbox Code Playgroud)

这会产生以下日志（我删除了长事件 ID 以使其更短）：

08:25:27.6440324 System.Net.Http.RequestStart(scheme: https, host: github.com, port: 443, pathAndQuery: /runtime, versionMajor: 1, versionMinor: 1, versionPolicy: 0)
08:25:27.6782964 System.Net.NameResolution.ResolutionStart(hostNameOrAddress: github.com)
08:25:27.8075834 System.Net.NameResolution.ResolutionStop()
08:25:27.8082958 System.Net.Sockets.ConnectStart(address: InterNetworkV6:28:{1,187,0,0,0,0,0,0,0,0,0,0,0,0,0,0,255,255,140,82,121,3,0,0,0,0})
08:25:27.8805709 System.Net.Sockets.ConnectStop()
08:25:27.8829670 System.Net.Security.HandshakeStart(isServer: False, targetHost: github.com)
08:25:28.1419994 System.Net.Security.HandshakeStop(protocol: 12288)
08:25:28.1431643 System.Net.Http.ConnectionEstablished(versionMajor: 1, versionMinor: 1)
08:25:28.1443727 System.Net.Http.RequestLeftQueue(timeOnQueueMilliseconds: 474,269, versionMajor: 1, versionMinor: 1)
08:25:28.1454417 System.Net.Http.RequestHeadersStart()
08:25:28.1461159 System.Net.Http.RequestHeadersStop()
08:25:28.6777661 System.Net.Http.ResponseHeadersStart()
08:25:28.6783369 System.Net.Http.ResponseHeadersStop()
08:25:28.6826666 System.Net.Http.ResponseContentStart()
08:25:28.8978144 System.Net.Http.ResponseContentStop()
08:25:28.8978472 System.Net.Http.RequestStop()

Run Code Online (Sandbox Code Playgroud)

如您所见，这些事件包含您需要的所有信息：DNS 查找时间、连接时间、SSL 握手时间和实际请求计时。

更新：关于您担心使用这种方法您可能会收到与您感兴趣的特定 Web 请求无关的事件。您可以使用AsyncLocal变量进行关联，如文档中提到的here。这个想法很简单 -AsyncLocal在使用进行请求之前，您使用变量并将其值设置为某些内容（例如保存计时信息的类）HttpClient。然后你执行请求。现在，当新事件出现时 - 您检查变量的值AsyncLocal。如果它不为空 - 那么这个事件与当前请求相关，否则你可以忽略它。

这是上面代码的扩展版本，考虑到了这种方法：

class Program
{
    private static readonly HttpClient _client = new HttpClient();

    static async Task Main()
    {
        using (var listener = new HttpEventListener())
        {
            // we start new listener scope here
            // only this specific request timings will be measured
            // this implementation assumes usage of exactly one HttpEventListener per request
            using var response = await _client.GetAsync("https://github.com/runtime");
            var timings = listener.GetTimings();
            if (timings.Request != null)
                Console.WriteLine($"Total time: {timings.Request.Value.TotalMilliseconds:N0}ms");
            if (timings.Dns != null)
                Console.WriteLine($"DNS: {timings.Dns.Value.TotalMilliseconds:N0}ms");
            if (timings.SocketConnect != null)
                Console.WriteLine($"Socket connect: {timings.SocketConnect.Value.TotalMilliseconds:N0}ms");
            if (timings.SslHandshake != null)
                Console.WriteLine($"SSL Handshake: {timings.SslHandshake.Value.TotalMilliseconds:N0}ms");
            if (timings.RequestHeaders != null)
                Console.WriteLine($"Request headers: {timings.RequestHeaders.Value.TotalMilliseconds:N0}ms");
            if (timings.ResponseHeaders != null)
                Console.WriteLine($"Response headers: {timings.ResponseHeaders.Value.TotalMilliseconds:N0}ms");
            if (timings.ResponseContent != null)
                Console.WriteLine($"Response content: {timings.ResponseContent.Value.TotalMilliseconds:N0}ms");
        }
    }
}

internal sealed class HttpEventListener : EventListener
{
    // Constant necessary for attaching ActivityId to the events.
    public const EventKeywords TasksFlowActivityIds = (EventKeywords)0x80;
    private AsyncLocal<HttpRequestTimingDataRaw> _timings = new AsyncLocal<HttpRequestTimingDataRaw>();

    internal HttpEventListener()
    {
        // set variable here
        _timings.Value = new HttpRequestTimingDataRaw();
    }

    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        // List of event source names provided by networking in .NET 5.
        if (eventSource.Name == "System.Net.Http" ||
            eventSource.Name == "System.Net.Sockets" ||
            eventSource.Name == "System.Net.Security" ||
            eventSource.Name == "System.Net.NameResolution")
        {
            EnableEvents(eventSource, EventLevel.LogAlways);
        }
        // Turn on ActivityId.
        else if (eventSource.Name == "System.Threading.Tasks.TplEventSource")
        {
            // Attach ActivityId to the events.
            EnableEvents(eventSource, EventLevel.LogAlways, TasksFlowActivityIds);
        }
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        var timings = _timings.Value;
        if (timings == null)
            return; // some event which is not related to this scope, ignore it
        var fullName = eventData.EventSource.Name + "." + eventData.EventName;
        
        switch (fullName)
        {
            case "System.Net.Http.RequestStart":
                timings.RequestStart = eventData.TimeStamp;
                break;
            case "System.Net.Http.RequestStop":
                timings.RequestStop = eventData.TimeStamp;
                break;
            case "System.Net.NameResolution.ResolutionStart":
                timings.DnsStart = eventData.TimeStamp;
                break;
            case "System.Net.NameResolution.ResolutionStop":
                timings.DnsStop = eventData.TimeStamp;
                break;
            case "System.Net.Sockets.ConnectStart":
                timings.SocketConnectStart = eventData.TimeStamp;
                break;
            case "System.Net.Sockets.ConnectStop":
                timings.SocketConnectStop = eventData.TimeStamp;
                break;
            case "System.Net.Security.HandshakeStart":
                timings.SslHandshakeStart = eventData.TimeStamp;
                break;
            case "System.Net.Security.HandshakeStop":
                timings.SslHandshakeStop = eventData.TimeStamp;
                break;
            case "System.Net.Http.RequestHeadersStart":
                timings.RequestHeadersStart = eventData.TimeStamp;
                break;
            case "System.Net.Http.RequestHeadersStop":
                timings.RequestHeadersStop = eventData.TimeStamp;
                break;
            case "System.Net.Http.ResponseHeadersStart":
                timings.ResponseHeadersStart = eventData.TimeStamp;
                break;
            case "System.Net.Http.ResponseHeadersStop":
                timings.ResponseHeadersStop = eventData.TimeStamp;
                break;
            case "System.Net.Http.ResponseContentStart":
                timings.ResponseContentStart = eventData.TimeStamp;
                break;
            case "System.Net.Http.ResponseContentStop":
                timings.ResponseContentStop = eventData.TimeStamp;
                break;
        }
    }

    public HttpRequestTimings GetTimings(){
        var raw = _timings.Value!;
        return new HttpRequestTimings{
            Request = raw.RequestStop - raw.RequestStart,
            Dns = raw.DnsStop - raw.DnsStart,
            SslHandshake = raw.SslHandshakeStop - raw.SslHandshakeStart,
            SocketConnect = raw.SocketConnectStop - raw.SocketConnectStart,
            RequestHeaders = raw.RequestHeadersStop - raw.RequestHeadersStart,
            ResponseHeaders = raw.ResponseHeadersStop - raw.ResponseHeadersStart,
            ResponseContent = raw.ResponseContentStop - raw.ResponseContentStart
        };
    }

    public class HttpRequestTimings{
        public TimeSpan? Request{get;set;}
        public TimeSpan? Dns{get;set;}
        public TimeSpan? SslHandshake{get;set;}        
        public TimeSpan? SocketConnect {get;set;}
        public TimeSpan? RequestHeaders{get;set;}
        public TimeSpan? ResponseHeaders{get;set;}
        public TimeSpan? ResponseContent{get;set;}
    }

    private class HttpRequestTimingDataRaw
    {
        public DateTime? DnsStart { get; set; }
        public DateTime? DnsStop { get; set; }
        public DateTime? RequestStart { get; set; }
        public DateTime? RequestStop { get; set; }
        public DateTime? SocketConnectStart { get; set; }
        public DateTime? SocketConnectStop { get; set; }
        public DateTime? SslHandshakeStart { get; set; }
        public DateTime? SslHandshakeStop { get; set; }
        public DateTime? RequestHeadersStart { get; set; }
        public DateTime? RequestHeadersStop { get; set; }
        public DateTime? ResponseHeadersStart { get; set; }
        public DateTime? ResponseHeadersStop { get; set; }
        public DateTime? ResponseContentStart { get; set; }
        public DateTime? ResponseContentStop { get; set; }
    }
}

Run Code Online (Sandbox Code Playgroud)

在此版本中，我还仅收集时间，而不收集事件中的无关信息。请注意，不同的 http 请求（例如带有正文的请求）可能有更多事件。

归档时间：	2 年，10 月前
查看次数：	1362 次
最近记录：	2 年，10 月前