Skip to content

Commit 9ffdb53

Browse files
authored
Add SocketsHttpHandler requests-queue-duration metrics (#88981)
* Add SocketsHttpHandler requests-queue-duration metrics * Use the IsDefaultPort helper in more places * PR feedback * Simplify queueStartingTimestamp logic in Http3Connection
1 parent 15e9370 commit 9ffdb53

File tree

6 files changed

+133
-57
lines changed

6 files changed

+133
-57
lines changed

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

Lines changed: 14 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
// Licensed to the .NET Foundation under one or more agreements.
22
// The .NET Foundation licenses this file to you under the MIT license.
33

4+
using System.Diagnostics;
45
using System.Diagnostics.Tracing;
56
using System.Threading;
67

@@ -21,24 +22,22 @@ internal sealed partial class HttpTelemetry
2122
private EventCounter? _http30RequestsQueueDurationCounter;
2223

2324
[NonEvent]
24-
public void Http11RequestLeftQueue(double timeOnQueueMilliseconds)
25+
public void RequestLeftQueue(int versionMajor, TimeSpan duration)
2526
{
26-
_http11RequestsQueueDurationCounter?.WriteMetric(timeOnQueueMilliseconds);
27-
RequestLeftQueue(timeOnQueueMilliseconds, versionMajor: 1, versionMinor: 1);
28-
}
27+
Debug.Assert(versionMajor is 1 or 2 or 3);
2928

30-
[NonEvent]
31-
public void Http20RequestLeftQueue(double timeOnQueueMilliseconds)
32-
{
33-
_http20RequestsQueueDurationCounter?.WriteMetric(timeOnQueueMilliseconds);
34-
RequestLeftQueue(timeOnQueueMilliseconds, versionMajor: 2, versionMinor: 0);
35-
}
29+
EventCounter? counter = versionMajor switch
30+
{
31+
1 => _http11RequestsQueueDurationCounter,
32+
2 => _http20RequestsQueueDurationCounter,
33+
_ => _http30RequestsQueueDurationCounter
34+
};
3635

37-
[NonEvent]
38-
public void Http30RequestLeftQueue(double timeOnQueueMilliseconds)
39-
{
40-
_http30RequestsQueueDurationCounter?.WriteMetric(timeOnQueueMilliseconds);
41-
RequestLeftQueue(timeOnQueueMilliseconds, versionMajor: 3, versionMinor: 0);
36+
double timeOnQueueMs = duration.TotalMilliseconds;
37+
38+
counter?.WriteMetric(timeOnQueueMs);
39+
40+
RequestLeftQueue(timeOnQueueMs, (byte)versionMajor, versionMinor: versionMajor == 1 ? (byte)1 : (byte)0);
4241
}
4342

4443
protected override void OnEventCommand(EventCommandEventArgs command)

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

Lines changed: 9 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -173,11 +173,6 @@ public async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, lon
173173
QuicConnection? conn = _connection;
174174
if (conn != null)
175175
{
176-
if (HttpTelemetry.Log.IsEnabled() && queueStartingTimestamp == 0)
177-
{
178-
queueStartingTimestamp = Stopwatch.GetTimestamp();
179-
}
180-
181176
quicStream = await conn.OpenOutboundStreamAsync(QuicStreamType.Bidirectional, cancellationToken).ConfigureAwait(false);
182177

183178
requestStream = new Http3RequestStream(request, this, quicStream);
@@ -198,9 +193,16 @@ public async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, lon
198193
catch (QuicException e) when (e.QuicError != QuicError.OperationAborted) { }
199194
finally
200195
{
201-
if (HttpTelemetry.Log.IsEnabled() && queueStartingTimestamp != 0)
196+
if (queueStartingTimestamp != 0)
202197
{
203-
HttpTelemetry.Log.Http30RequestLeftQueue(Stopwatch.GetElapsedTime(queueStartingTimestamp).TotalMilliseconds);
198+
TimeSpan duration = Stopwatch.GetElapsedTime(queueStartingTimestamp);
199+
200+
_pool.Settings._metrics!.RequestLeftQueue(Pool, duration, versionMajor: 3);
201+
202+
if (HttpTelemetry.Log.IsEnabled())
203+
{
204+
HttpTelemetry.Log.RequestLeftQueue(versionMajor: 3, duration);
205+
}
204206
}
205207
}
206208

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

Lines changed: 2 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -42,20 +42,18 @@ public HttpConnectionBase(HttpConnectionPool pool)
4242
metrics.IdleConnections.Enabled ||
4343
metrics.ConnectionDuration.Enabled)
4444
{
45+
// While requests may report HTTP/1.0 as the protocol, we treat all HTTP/1.X connections as HTTP/1.1.
4546
string protocol =
4647
this is HttpConnection ? "HTTP/1.1" :
4748
this is Http2Connection ? "HTTP/2" :
4849
"HTTP/3";
4950

50-
int port = pool.OriginAuthority.Port;
51-
int defaultPort = pool.IsSecure ? HttpConnectionPool.DefaultHttpsPort : HttpConnectionPool.DefaultHttpPort;
52-
5351
_connectionMetrics = new ConnectionMetrics(
5452
metrics,
5553
protocol,
5654
pool.IsSecure ? "https" : "http",
5755
pool.OriginAuthority.HostValue,
58-
port == defaultPort ? null : port);
56+
pool.IsDefaultPort ? null : pool.OriginAuthority.Port);
5957

6058
_connectionMetrics.ConnectionEstablished();
6159

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

Lines changed: 27 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -236,10 +236,9 @@ public HttpConnectionPool(HttpConnectionPoolManager poolManager, HttpConnectionK
236236
{
237237
// Precalculate ASCII bytes for Host header
238238
// Note that if _host is null, this is a (non-tunneled) proxy connection, and we can't cache the hostname.
239-
hostHeader =
240-
(_originAuthority.Port != (sslHostName == null ? DefaultHttpPort : DefaultHttpsPort)) ?
241-
$"{_originAuthority.HostValue}:{_originAuthority.Port}" :
242-
_originAuthority.HostValue;
239+
hostHeader = IsDefaultPort
240+
? _originAuthority.HostValue
241+
: $"{_originAuthority.HostValue}:{_originAuthority.Port}";
243242

244243
// Note the IDN hostname should always be ASCII, since it's already been IDNA encoded.
245244
byte[] hostHeaderLine = new byte[6 + hostHeader.Length + 2]; // Host: foo\r\n
@@ -363,6 +362,7 @@ private static SslClientAuthenticationOptions ConstructSslOptions(HttpConnection
363362
public ICredentials? ProxyCredentials => _poolManager.ProxyCredentials;
364363
public byte[]? HostHeaderLineBytes => _hostHeaderLineBytes;
365364
public CredentialCache? PreAuthCredentials { get; }
365+
public bool IsDefaultPort => OriginAuthority.Port == (IsSecure ? DefaultHttpsPort : DefaultHttpPort);
366366

367367
/// <summary>
368368
/// 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
381381
sb.Append(IsSecure ? "https://" : "http://")
382382
.Append(_originAuthority.IdnHost);
383383

384-
if (_originAuthority.Port != (IsSecure ? DefaultHttpsPort : DefaultHttpPort))
384+
if (!IsDefaultPort)
385385
{
386386
sb.Append(CultureInfo.InvariantCulture, $":{_originAuthority.Port}");
387387
}
@@ -998,16 +998,10 @@ private async ValueTask<Http3Connection> GetHttp3ConnectionAsync(HttpRequestMess
998998
ThrowGetVersionException(request, 3, reasonException);
999999
}
10001000

1001-
long queueStartingTimestamp = HttpTelemetry.Log.IsEnabled() ? Stopwatch.GetTimestamp() : 0;
1001+
long queueStartingTimestamp = HttpTelemetry.Log.IsEnabled() || Settings._metrics!.RequestsQueueDuration.Enabled ? Stopwatch.GetTimestamp() : 0;
10021002

10031003
ValueTask<Http3Connection> connectionTask = GetHttp3ConnectionAsync(request, authority, cancellationToken);
10041004

1005-
if (HttpTelemetry.Log.IsEnabled() && connectionTask.IsCompleted)
1006-
{
1007-
// We avoid logging RequestLeftQueue if a stream was available immediately (synchronously)
1008-
queueStartingTimestamp = 0;
1009-
}
1010-
10111005
Http3Connection connection = await connectionTask.ConfigureAwait(false);
10121006

10131007
HttpResponseMessage response = await connection.SendAsync(request, queueStartingTimestamp, cancellationToken).ConfigureAwait(false);
@@ -1089,7 +1083,7 @@ public async ValueTask<HttpResponseMessage> SendWithVersionDetectionAndRetryAsyn
10891083
if (!TryGetPooledHttp2Connection(request, out Http2Connection? connection, out http2ConnectionWaiter) &&
10901084
http2ConnectionWaiter != null)
10911085
{
1092-
connection = await http2ConnectionWaiter.WaitForConnectionAsync(async, cancellationToken).ConfigureAwait(false);
1086+
connection = await http2ConnectionWaiter.WaitForConnectionAsync(this, async, cancellationToken).ConfigureAwait(false);
10931087
}
10941088

10951089
Debug.Assert(connection is not null || !_http2Enabled);
@@ -1121,7 +1115,7 @@ public async ValueTask<HttpResponseMessage> SendWithVersionDetectionAndRetryAsyn
11211115
// Use HTTP/1.x.
11221116
if (!TryGetPooledHttp11Connection(request, async, out HttpConnection? connection, out http11ConnectionWaiter))
11231117
{
1124-
connection = await http11ConnectionWaiter.WaitForConnectionAsync(async, cancellationToken).ConfigureAwait(false);
1118+
connection = await http11ConnectionWaiter.WaitForConnectionAsync(this, async, cancellationToken).ConfigureAwait(false);
11251119
}
11261120

11271121
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
11991193
}
12001194

12011195
private void CancelIfNecessary<T>(HttpConnectionWaiter<T>? waiter, bool requestCancelled)
1196+
where T : HttpConnectionBase?
12021197
{
12031198
int timeout = GlobalHttpSettings.SocketsHttpHandler.PendingConnectionTimeoutOnRequestCompletion;
12041199
if (waiter?.ConnectionCancellationTokenSource is null ||
@@ -2430,6 +2425,7 @@ private void Trace(string? message, [CallerMemberName] string? memberName = null
24302425
message); // message
24312426

24322427
private struct RequestQueue<T>
2428+
where T : HttpConnectionBase?
24332429
{
24342430
public struct QueueItem
24352431
{
@@ -2599,6 +2595,7 @@ public QueueItem PeekNextRequestForConnectionAttempt()
25992595
}
26002596

26012597
private sealed class HttpConnectionWaiter<T> : TaskCompletionSourceWithCancellation<T>
2598+
where T : HttpConnectionBase?
26022599
{
26032600
// When a connection attempt is pending, reference the connection's CTS, so we can tear it down if the initiating request is cancelled
26042601
// or completes on a different connection.
@@ -2607,21 +2604,32 @@ private sealed class HttpConnectionWaiter<T> : TaskCompletionSourceWithCancellat
26072604
// Distinguish connection cancellation that happens because the initiating request is cancelled or completed on a different connection.
26082605
public bool CancelledByOriginatingRequestCompletion { get; set; }
26092606

2610-
public async ValueTask<T> WaitForConnectionAsync(bool async, CancellationToken requestCancellationToken)
2607+
public ValueTask<T> WaitForConnectionAsync(HttpConnectionPool pool, bool async, CancellationToken requestCancellationToken)
26112608
{
2609+
return HttpTelemetry.Log.IsEnabled() || pool.Settings._metrics!.RequestsQueueDuration.Enabled
2610+
? WaitForConnectionWithTelemetryAsync(pool, async, requestCancellationToken)
2611+
: WaitWithCancellationAsync(async, requestCancellationToken);
2612+
}
2613+
2614+
private async ValueTask<T> WaitForConnectionWithTelemetryAsync(HttpConnectionPool pool, bool async, CancellationToken requestCancellationToken)
2615+
{
2616+
Debug.Assert(typeof(T) == typeof(HttpConnection) || typeof(T) == typeof(Http2Connection));
2617+
26122618
long startingTimestamp = Stopwatch.GetTimestamp();
26132619
try
26142620
{
26152621
return await WaitWithCancellationAsync(async, requestCancellationToken).ConfigureAwait(false);
26162622
}
26172623
finally
26182624
{
2625+
TimeSpan duration = Stopwatch.GetElapsedTime(startingTimestamp);
2626+
int versionMajor = typeof(T) == typeof(HttpConnection) ? 1 : 2;
2627+
2628+
pool.Settings._metrics!.RequestLeftQueue(pool, duration, versionMajor);
2629+
26192630
if (HttpTelemetry.Log.IsEnabled())
26202631
{
2621-
if (typeof(T) == typeof(HttpConnection))
2622-
HttpTelemetry.Log.Http11RequestLeftQueue(Stopwatch.GetElapsedTime(startingTimestamp).TotalMilliseconds);
2623-
else if (typeof(T) == typeof(Http2Connection))
2624-
HttpTelemetry.Log.Http20RequestLeftQueue(Stopwatch.GetElapsedTime(startingTimestamp).TotalMilliseconds);
2632+
HttpTelemetry.Log.RequestLeftQueue(versionMajor, duration);
26252633
}
26262634
}
26272635
}

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

Lines changed: 34 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
// Licensed to the .NET Foundation under one or more agreements.
22
// The .NET Foundation licenses this file to you under the MIT license.
33

4+
using System.Diagnostics;
45
using System.Diagnostics.Metrics;
56

67
namespace System.Net.Http.Metrics
@@ -19,5 +20,38 @@ internal sealed class SocketsHttpHandlerMetrics(Meter meter)
1920
name: "http-client-connection-duration",
2021
unit: "s",
2122
description: "The duration of outbound HTTP connections.");
23+
24+
public readonly Histogram<double> RequestsQueueDuration = meter.CreateHistogram<double>(
25+
name: "http-client-requests-queue-duration",
26+
unit: "s",
27+
description: "The amount of time requests spent on a queue waiting for an available connection.");
28+
29+
public void RequestLeftQueue(HttpConnectionPool pool, TimeSpan duration, int versionMajor)
30+
{
31+
Debug.Assert(versionMajor is 1 or 2 or 3);
32+
33+
if (RequestsQueueDuration.Enabled)
34+
{
35+
TagList tags = default;
36+
37+
// While requests may report HTTP/1.0 as the protocol, we treat all HTTP/1.X connections as HTTP/1.1.
38+
tags.Add("protocol", versionMajor switch
39+
{
40+
1 => "HTTP/1.1",
41+
2 => "HTTP/2",
42+
_ => "HTTP/3"
43+
});
44+
45+
tags.Add("scheme", pool.IsSecure ? "https" : "http");
46+
tags.Add("host", pool.OriginAuthority.HostValue);
47+
48+
if (!pool.IsDefaultPort)
49+
{
50+
tags.Add("port", pool.OriginAuthority.Port);
51+
}
52+
53+
RequestsQueueDuration.Record(duration.TotalSeconds, tags);
54+
}
55+
}
2256
}
2357
}

0 commit comments

Comments
 (0)