Skip to content

Commit

Permalink
Add SocketsHttpHandler requests-queue-duration metrics (#88981)
Browse files Browse the repository at this point in the history 
* Add SocketsHttpHandler requests-queue-duration metrics

* Use the IsDefaultPort helper in more places

* PR feedback

* Simplify queueStartingTimestamp logic in Http3Connection
  • Loading branch information
@MihaZupan
MihaZupan authored Jul 17, 2023
1 parent 15e9370 commit 9ffdb53
Show file tree
Hide file tree
Showing 6 changed files with 133 additions and 57 deletions.
29 changes: 14 additions & 15 deletions src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.AnyOS.cs
View file
Original file line number Diff line number Diff line change
@@ -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;

Expand All @@ -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)
Expand Down
16 changes: 9 additions & 7 deletions src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -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);
}
}
}

Expand Down
6 changes: 2 additions & 4 deletions src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionBase.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();

Expand Down
46 changes: 27 additions & 19 deletions src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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;]
Expand All @@ -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}");
}
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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 ||
Expand Down Expand Up @@ -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
{
Expand Down Expand Up @@ -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.
Expand All @@ -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);
}
}
}
Expand Down
34 changes: 34 additions & 0 deletions ...stem.Net.Http/src/System/Net/Http/SocketsHttpHandler/Metrics/SocketsHttpHandlerMetrics.cs
View file
Original file line number Diff line number Diff line change
@@ -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
Expand All @@ -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);
}
}
}
}
Loading

0 comments on commit 9ffdb53

Please sign in to comment.