Add SocketsHttpHandler requests-queue-duration metrics

src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.AnyOS.cs

@@ -1,6 +1,7 @@
 // Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 
+using System.Diagnostics;
 using System.Diagnostics.Tracing;
 using System.Threading;
 
@@ -21,24 +22,22 @@ internal sealed partial class HttpTelemetry
         private EventCounter? _http30RequestsQueueDurationCounter;
 
         [NonEvent]
-        public void Http11RequestLeftQueue(double timeOnQueueMilliseconds)
+        public void RequestLeftQueue(int versionMajor, TimeSpan duration)
         {
-            _http11RequestsQueueDurationCounter?.WriteMetric(timeOnQueueMilliseconds);
-            RequestLeftQueue(timeOnQueueMilliseconds, versionMajor: 1, versionMinor: 1);
-        }
+            Debug.Assert(versionMajor is 1 or 2 or 3);
 
-        [NonEvent]
-        public void Http20RequestLeftQueue(double timeOnQueueMilliseconds)
-        {
-            _http20RequestsQueueDurationCounter?.WriteMetric(timeOnQueueMilliseconds);
-            RequestLeftQueue(timeOnQueueMilliseconds, versionMajor: 2, versionMinor: 0);
-        }
+            EventCounter? counter = versionMajor switch
+            {
+                1 => _http11RequestsQueueDurationCounter,
+                2 => _http20RequestsQueueDurationCounter,
+                _ => _http30RequestsQueueDurationCounter
+            };
 
-        [NonEvent]
-        public void Http30RequestLeftQueue(double timeOnQueueMilliseconds)
-        {
-            _http30RequestsQueueDurationCounter?.WriteMetric(timeOnQueueMilliseconds);
-            RequestLeftQueue(timeOnQueueMilliseconds, versionMajor: 3, versionMinor: 0);
+            double timeOnQueueMs = duration.TotalMilliseconds;
+
+            counter?.WriteMetric(timeOnQueueMs);
+
+            RequestLeftQueue(timeOnQueueMs, (byte)versionMajor, versionMinor: versionMajor == 1 ? (byte)1 : (byte)0);
         }
 
         protected override void OnEventCommand(EventCommandEventArgs command)

src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs

@@ -173,11 +173,6 @@ public async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, lon
                     QuicConnection? conn = _connection;
                     if (conn != null)
                     {
-                        if (HttpTelemetry.Log.IsEnabled() && queueStartingTimestamp == 0)
-                        {
-                            queueStartingTimestamp = Stopwatch.GetTimestamp();
-                        }
-
                         quicStream = await conn.OpenOutboundStreamAsync(QuicStreamType.Bidirectional, cancellationToken).ConfigureAwait(false);
 
                         requestStream = new Http3RequestStream(request, this, quicStream);
@@ -198,9 +193,16 @@ public async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, lon
                 catch (QuicException e) when (e.QuicError != QuicError.OperationAborted) { }
                 finally
                 {
-                    if (HttpTelemetry.Log.IsEnabled() && queueStartingTimestamp != 0)
+                    if (queueStartingTimestamp != 0)
                     {
-                        HttpTelemetry.Log.Http30RequestLeftQueue(Stopwatch.GetElapsedTime(queueStartingTimestamp).TotalMilliseconds);
+                        TimeSpan duration = Stopwatch.GetElapsedTime(queueStartingTimestamp);
+
+                        _pool.Settings._metrics!.RequestLeftQueue(Pool, duration, versionMajor: 3);
+
+                        if (HttpTelemetry.Log.IsEnabled())
+                        {
+                            HttpTelemetry.Log.RequestLeftQueue(versionMajor: 3, duration);
+                        }
                     }
                 }
 

src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionBase.cs

@@ -42,20 +42,18 @@ public HttpConnectionBase(HttpConnectionPool pool)
                 metrics.IdleConnections.Enabled ||
                 metrics.ConnectionDuration.Enabled)
             {
+                // While requests may report HTTP/1.0 as the protocol, we treat all HTTP/1.X connections as HTTP/1.1.
                 string protocol =
                     this is HttpConnection ? "HTTP/1.1" :
                     this is Http2Connection ? "HTTP/2" :
                     "HTTP/3";
 
-                int port = pool.OriginAuthority.Port;
-                int defaultPort = pool.IsSecure ? HttpConnectionPool.DefaultHttpsPort : HttpConnectionPool.DefaultHttpPort;
-
                 _connectionMetrics = new ConnectionMetrics(
                     metrics,
                     protocol,
                     pool.IsSecure ? "https" : "http",
                     pool.OriginAuthority.HostValue,
-                    port == defaultPort ? null : port);
+                    pool.IsDefaultPort ? null : pool.OriginAuthority.Port);
 
                 _connectionMetrics.ConnectionEstablished();
 

src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs

@@ -236,10 +236,9 @@ public HttpConnectionPool(HttpConnectionPoolManager poolManager, HttpConnectionK
             {
                 // Precalculate ASCII bytes for Host header
                 // Note that if _host is null, this is a (non-tunneled) proxy connection, and we can't cache the hostname.
-                hostHeader =
-                    (_originAuthority.Port != (sslHostName == null ? DefaultHttpPort : DefaultHttpsPort)) ?
-                    $"{_originAuthority.HostValue}:{_originAuthority.Port}" :
-                    _originAuthority.HostValue;
+                hostHeader = IsDefaultPort
+                    ? _originAuthority.HostValue
+                    : $"{_originAuthority.HostValue}:{_originAuthority.Port}";
 
                 // Note the IDN hostname should always be ASCII, since it's already been IDNA encoded.
                 byte[] hostHeaderLine = new byte[6 + hostHeader.Length + 2]; // Host: foo\r\n
@@ -363,6 +362,7 @@ private static SslClientAuthenticationOptions ConstructSslOptions(HttpConnection
         public ICredentials? ProxyCredentials => _poolManager.ProxyCredentials;
         public byte[]? HostHeaderLineBytes => _hostHeaderLineBytes;
         public CredentialCache? PreAuthCredentials { get; }
+        public bool IsDefaultPort => OriginAuthority.Port == (IsSecure ? DefaultHttpsPort : DefaultHttpPort);
 
         /// <summary>
         /// An ASCII origin string per RFC 6454 Section 6.2, in format &lt;scheme&gt;://&lt;host&gt;[:&lt;port&gt;]
@@ -381,7 +381,7 @@ public byte[] Http2AltSvcOriginUri
                     sb.Append(IsSecure ? "https://" : "http://")
                       .Append(_originAuthority.IdnHost);
 
-                    if (_originAuthority.Port != (IsSecure ? DefaultHttpsPort : DefaultHttpPort))
+                    if (!IsDefaultPort)
                     {
                         sb.Append(CultureInfo.InvariantCulture, $":{_originAuthority.Port}");
                     }
@@ -998,16 +998,10 @@ private async ValueTask<Http3Connection> GetHttp3ConnectionAsync(HttpRequestMess
                     ThrowGetVersionException(request, 3, reasonException);
                 }
 
-                long queueStartingTimestamp = HttpTelemetry.Log.IsEnabled() ? Stopwatch.GetTimestamp() : 0;
+                long queueStartingTimestamp = HttpTelemetry.Log.IsEnabled() || Settings._metrics!.RequestsQueueDuration.Enabled ? Stopwatch.GetTimestamp() : 0;
 
                 ValueTask<Http3Connection> connectionTask = GetHttp3ConnectionAsync(request, authority, cancellationToken);
 
-                if (HttpTelemetry.Log.IsEnabled() && connectionTask.IsCompleted)
-                {
-                    // We avoid logging RequestLeftQueue if a stream was available immediately (synchronously)
-                    queueStartingTimestamp = 0;
-                }
-
                 Http3Connection connection = await connectionTask.ConfigureAwait(false);
 
                 HttpResponseMessage response = await connection.SendAsync(request, queueStartingTimestamp, cancellationToken).ConfigureAwait(false);
@@ -1089,7 +1083,7 @@ public async ValueTask<HttpResponseMessage> SendWithVersionDetectionAndRetryAsyn
                             if (!TryGetPooledHttp2Connection(request, out Http2Connection? connection, out http2ConnectionWaiter) &&
                                 http2ConnectionWaiter != null)
                             {
-                                connection = await http2ConnectionWaiter.WaitForConnectionAsync(async, cancellationToken).ConfigureAwait(false);
+                                connection = await http2ConnectionWaiter.WaitForConnectionAsync(this, async, cancellationToken).ConfigureAwait(false);
                             }
 
                             Debug.Assert(connection is not null || !_http2Enabled);
@@ -1121,7 +1115,7 @@ public async ValueTask<HttpResponseMessage> SendWithVersionDetectionAndRetryAsyn
                             // Use HTTP/1.x.
                             if (!TryGetPooledHttp11Connection(request, async, out HttpConnection? connection, out http11ConnectionWaiter))
                             {
-                                connection = await http11ConnectionWaiter.WaitForConnectionAsync(async, cancellationToken).ConfigureAwait(false);
+                                connection = await http11ConnectionWaiter.WaitForConnectionAsync(this, async, cancellationToken).ConfigureAwait(false);
                             }
 
                             connection.Acquire(); // In case we are doing Windows (i.e. connection-based) auth, we need to ensure that we hold on to this specific connection while auth is underway.
@@ -1199,6 +1193,7 @@ public async ValueTask<HttpResponseMessage> SendWithVersionDetectionAndRetryAsyn
         }
 
         private void CancelIfNecessary<T>(HttpConnectionWaiter<T>? waiter, bool requestCancelled)
+            where T : HttpConnectionBase?
         {
             int timeout = GlobalHttpSettings.SocketsHttpHandler.PendingConnectionTimeoutOnRequestCompletion;
             if (waiter?.ConnectionCancellationTokenSource is null ||
@@ -2430,6 +2425,7 @@ private void Trace(string? message, [CallerMemberName] string? memberName = null
                 message);                    // message
 
         private struct RequestQueue<T>
+            where T : HttpConnectionBase?
         {
             public struct QueueItem
             {
@@ -2599,6 +2595,7 @@ public QueueItem PeekNextRequestForConnectionAttempt()
         }
 
         private sealed class HttpConnectionWaiter<T> : TaskCompletionSourceWithCancellation<T>
+            where T : HttpConnectionBase?
         {
             // When a connection attempt is pending, reference the connection's CTS, so we can tear it down if the initiating request is cancelled
             // or completes on a different connection.
@@ -2607,21 +2604,32 @@ private sealed class HttpConnectionWaiter<T> : TaskCompletionSourceWithCancellat
             // Distinguish connection cancellation that happens because the initiating request is cancelled or completed on a different connection.
             public bool CancelledByOriginatingRequestCompletion { get; set; }
 
-            public async ValueTask<T> WaitForConnectionAsync(bool async, CancellationToken requestCancellationToken)
+            public ValueTask<T> WaitForConnectionAsync(HttpConnectionPool pool, bool async, CancellationToken requestCancellationToken)
             {
+                return HttpTelemetry.Log.IsEnabled() || pool.Settings._metrics!.RequestsQueueDuration.Enabled
+                    ? WaitForConnectionWithTelemetryAsync(pool, async, requestCancellationToken)
+                    : WaitWithCancellationAsync(async, requestCancellationToken);
+            }
+
+            private async ValueTask<T> WaitForConnectionWithTelemetryAsync(HttpConnectionPool pool, bool async, CancellationToken requestCancellationToken)
+            {
+                Debug.Assert(typeof(T) == typeof(HttpConnection) || typeof(T) == typeof(Http2Connection));
+
                 long startingTimestamp = Stopwatch.GetTimestamp();
                 try
                 {
                     return await WaitWithCancellationAsync(async, requestCancellationToken).ConfigureAwait(false);
                 }
                 finally
                 {
+                    TimeSpan duration = Stopwatch.GetElapsedTime(startingTimestamp);
+                    int versionMajor = typeof(T) == typeof(HttpConnection) ? 1 : 2;
+
+                    pool.Settings._metrics!.RequestLeftQueue(pool, duration, versionMajor);
+
                     if (HttpTelemetry.Log.IsEnabled())
                     {
-                        if (typeof(T) == typeof(HttpConnection))
-                            HttpTelemetry.Log.Http11RequestLeftQueue(Stopwatch.GetElapsedTime(startingTimestamp).TotalMilliseconds);
-                        else if (typeof(T) == typeof(Http2Connection))
-                            HttpTelemetry.Log.Http20RequestLeftQueue(Stopwatch.GetElapsedTime(startingTimestamp).TotalMilliseconds);
+                        HttpTelemetry.Log.RequestLeftQueue(versionMajor, duration);
                     }
                 }
             }

src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Metrics/SocketsHttpHandlerMetrics.cs

@@ -1,6 +1,7 @@
 // Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 
+using System.Diagnostics;
 using System.Diagnostics.Metrics;
 
 namespace System.Net.Http.Metrics
@@ -19,5 +20,38 @@ internal sealed class SocketsHttpHandlerMetrics(Meter meter)
             name: "http-client-connection-duration",
             unit: "s",
             description: "The duration of outbound HTTP connections.");
+
+        public readonly Histogram<double> RequestsQueueDuration = meter.CreateHistogram<double>(
+            name: "http-client-requests-queue-duration",
+            unit: "s",
+            description: "The amount of time requests spent on a queue waiting for an available connection.");
+
+        public void RequestLeftQueue(HttpConnectionPool pool, TimeSpan duration, int versionMajor)
+        {
+            Debug.Assert(versionMajor is 1 or 2 or 3);
+
+            if (RequestsQueueDuration.Enabled)
+            {
+                TagList tags = default;
+
+                // While requests may report HTTP/1.0 as the protocol, we treat all HTTP/1.X connections as HTTP/1.1.
+                tags.Add("protocol", versionMajor switch
+                {
+                    1 => "HTTP/1.1",
+                    2 => "HTTP/2",
+                    _ => "HTTP/3"
+                });
+
+                tags.Add("scheme", pool.IsSecure ? "https" : "http");
+                tags.Add("host", pool.OriginAuthority.HostValue);
+
+                if (!pool.IsDefaultPort)
+                {
+                    tags.Add("port", pool.OriginAuthority.Port);
+                }
+
+                RequestsQueueDuration.Record(duration.TotalSeconds, tags);
+            }
+        }
     }
 }