You can use HttpClient telemetry events as described here:
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());
}
}
This produces the following log (I removed long event ids to make it shorter):
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()
As you can see, these events contain all information you need: DNS lookup time, connection time, SSL handshake time, and actual request timings.
Update: regarding your concern that with this approach you might receive events not related to the specific web request you are interested in. You can do the correlation using AsyncLocal variable, as documentation mentions here. The idea is simple - you use AsyncLocal variable and set its value to something (such as class holding your timing information) before doing request with HttpClient. Then you perform request. Now, when new event comes in - you check the value of AsyncLocal variable. If it's not null - then this event is related to the current request, otherwise you can ignore it.
Here is extended version of the code above with this approach in mind:
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; }
}
}
In this version I also collect only timings without unrelated info from events. Note that there might be more events for different http requests (for example ones with body).
