diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs b/src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs index 957a96117182c8..5ec178d2c0a878 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs @@ -19,7 +19,8 @@ internal sealed class HttpTelemetry : EventSource private PollingCounter? _abortedRequestsCounter; private PollingCounter? _totalHttp11ConnectionsCounter; private PollingCounter? _totalHttp20ConnectionsCounter; - private EventCounter? _requestsQueueDurationCounter; + private EventCounter? _http11RequestsQueueDurationCounter; + private EventCounter? _http20RequestsQueueDurationCounter; private long _startedRequests; private long _stoppedRequests; @@ -57,46 +58,71 @@ public void RequestAborted() } [Event(4, Level = EventLevel.Informational)] + private void ConnectionEstablished(byte versionMajor, byte versionMinor) + { + WriteEvent(eventId: 4, versionMajor, versionMinor); + } + + [Event(5, Level = EventLevel.Informational)] + private void ConnectionClosed(byte versionMajor, byte versionMinor) + { + WriteEvent(eventId: 5, versionMajor, versionMinor); + } + + [Event(6, Level = EventLevel.Informational)] + private void RequestLeftQueue(double timeOnQueueMilliseconds, byte versionMajor, byte versionMinor) + { + WriteEvent(eventId: 6, timeOnQueueMilliseconds, versionMajor, versionMinor); + } + + [Event(7, Level = EventLevel.Informational)] + public void ResponseHeadersBegin() + { + WriteEvent(eventId: 7); + } + + [NonEvent] public void Http11ConnectionEstablished() { Interlocked.Increment(ref _openedHttp11Connections); - WriteEvent(eventId: 4); + ConnectionEstablished(versionMajor: 1, versionMinor: 1); } - [Event(5, Level = EventLevel.Informational)] + [NonEvent] public void Http11ConnectionClosed() { long count = Interlocked.Decrement(ref _openedHttp11Connections); Debug.Assert(count >= 0); - WriteEvent(eventId: 5); + ConnectionClosed(versionMajor: 1, versionMinor: 1); } - [Event(6, Level = EventLevel.Informational)] + [NonEvent] public void Http20ConnectionEstablished() { Interlocked.Increment(ref _openedHttp20Connections); - WriteEvent(eventId: 6); + ConnectionEstablished(versionMajor: 2, versionMinor: 0); } - [Event(7, Level = EventLevel.Informational)] + [NonEvent] public void Http20ConnectionClosed() { long count = Interlocked.Decrement(ref _openedHttp20Connections); Debug.Assert(count >= 0); - WriteEvent(eventId: 7); + ConnectionClosed(versionMajor: 2, versionMinor: 0); } - [Event(8, Level = EventLevel.Informational)] + [NonEvent] public void Http11RequestLeftQueue(double timeOnQueueMilliseconds) { - _requestsQueueDurationCounter!.WriteMetric(timeOnQueueMilliseconds); - WriteEvent(eventId: 8, timeOnQueueMilliseconds); + _http11RequestsQueueDurationCounter!.WriteMetric(timeOnQueueMilliseconds); + RequestLeftQueue(timeOnQueueMilliseconds, versionMajor: 1, versionMinor: 1); } - [Event(9, Level = EventLevel.Informational)] - public void ResponseHeadersBegin() + [NonEvent] + public void Http20RequestLeftQueue(double timeOnQueueMilliseconds) { - WriteEvent(eventId: 9); + _http20RequestsQueueDurationCounter!.WriteMetric(timeOnQueueMilliseconds); + RequestLeftQueue(timeOnQueueMilliseconds, versionMajor: 2, versionMinor: 0); } protected override void OnEventCommand(EventCommandEventArgs command) @@ -152,11 +178,17 @@ protected override void OnEventCommand(EventCommandEventArgs command) DisplayName = "Current Http 2.0 Connections" }; - _requestsQueueDurationCounter ??= new EventCounter("http11-requests-queue-duration", this) + _http11RequestsQueueDurationCounter ??= new EventCounter("http11-requests-queue-duration", this) { DisplayName = "HTTP 1.1 Requests Queue Duration", DisplayUnits = "ms" }; + + _http20RequestsQueueDurationCounter ??= new EventCounter("http20-requests-queue-duration", this) + { + DisplayName = "HTTP 2.0 Requests Queue Duration", + DisplayUnits = "ms" + }; } } @@ -174,7 +206,7 @@ private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3 fixed (char* arg4Ptr = arg4) { const int NumEventDatas = 6; - var descrs = stackalloc EventData[NumEventDatas]; + EventData* descrs = stackalloc EventData[NumEventDatas]; descrs[0] = new EventData { @@ -213,17 +245,53 @@ private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3 } [NonEvent] - private unsafe void WriteEvent(int eventId, double arg1) + private unsafe void WriteEvent(int eventId, double arg1, byte arg2, byte arg3) { if (IsEnabled()) { - EventData descr = new EventData + const int NumEventDatas = 3; + EventData* descrs = stackalloc EventData[NumEventDatas]; + + descrs[0] = new EventData { DataPointer = (IntPtr)(&arg1), Size = sizeof(double) }; + descrs[1] = new EventData + { + DataPointer = (IntPtr)(&arg2), + Size = sizeof(byte) + }; + descrs[2] = new EventData + { + DataPointer = (IntPtr)(&arg3), + Size = sizeof(byte) + }; + + WriteEventCore(eventId, NumEventDatas, descrs); + } + } + + [NonEvent] + private unsafe void WriteEvent(int eventId, byte arg1, byte arg2) + { + if (IsEnabled()) + { + const int NumEventDatas = 2; + EventData* descrs = stackalloc EventData[NumEventDatas]; + + descrs[0] = new EventData + { + DataPointer = (IntPtr)(&arg1), + Size = sizeof(byte) + }; + descrs[1] = new EventData + { + DataPointer = (IntPtr)(&arg2), + Size = sizeof(byte) + }; - WriteEventCore(eventId, eventDataCount: 1, &descr); + WriteEventCore(eventId, NumEventDatas, descrs); } } } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs index b01878edf34f5c..7d1dc3ec962425 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs @@ -16,6 +16,7 @@ using System.Threading; using System.Threading.Channels; using System.Threading.Tasks; +using Microsoft.Extensions.Internal; namespace System.Net.Http { @@ -1308,16 +1309,24 @@ private async ValueTask SendHeadersAsync(HttpRequestMessage request // in order to avoid consuming resources in potentially many requests waiting for access. try { - if (_pool.EnableMultipleHttp2Connections) + if (!_concurrentStreams.TryRequestCreditNoWait(1)) { - if (!_concurrentStreams.TryRequestCreditNoWait(1)) + if (_pool.EnableMultipleHttp2Connections) { throw new HttpRequestException(null, null, RequestRetryType.RetryOnNextConnection); } - } - else - { - await _concurrentStreams.RequestCreditAsync(1, cancellationToken).ConfigureAwait(false); + + if (HttpTelemetry.Log.IsEnabled()) + { + // Only log Http20RequestLeftQueue if we spent time waiting on the queue + ValueStopwatch stopwatch = ValueStopwatch.StartNew(); + await _concurrentStreams.RequestCreditAsync(1, cancellationToken).ConfigureAwait(false); + HttpTelemetry.Log.Http20RequestLeftQueue(stopwatch.GetElapsedTime().TotalMilliseconds); + } + else + { + await _concurrentStreams.RequestCreditAsync(1, cancellationToken).ConfigureAwait(false); + } } } catch (ObjectDisposedException) diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs index 351f1595da2df4..f9263b317de4b4 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs @@ -3,6 +3,7 @@ using System.Collections.Concurrent; using System.Collections.Generic; +using System.Diagnostics; using System.Diagnostics.Tracing; using System.Linq; using System.Net.Test.Common; @@ -70,16 +71,7 @@ await server.AcceptConnectionAsync(async connection => Assert.DoesNotContain(events, e => e.EventName == "RequestAborted"); - if (version.Major == 1) - { - Assert.Single(events, e => e.EventName == "Http11ConnectionEstablished"); - Assert.Single(events, e => e.EventName == "Http11ConnectionClosed"); - } - else - { - Assert.Single(events, e => e.EventName == "Http20ConnectionEstablished"); - Assert.Single(events, e => e.EventName == "Http20ConnectionClosed"); - } + ValidateConnectionEstablishedClosed(events, version.Major, version.Minor); Assert.Single(events, e => e.EventName == "ResponseHeadersBegin"); @@ -148,7 +140,28 @@ protected static void ValidateStartEventPayload(EventWrittenEventArgs startEvent Assert.True(startEvent.Payload[5] is int versionMinor && (versionMinor == 1 || versionMinor == 0)); } - protected static void VerifyEventCounters(ConcurrentQueue events, int requestCount, bool shouldHaveFailures, bool shouldHaveQueuedRequests = false) + protected static void ValidateConnectionEstablishedClosed(ConcurrentQueue events, int versionMajor, int versionMinor, int count = 1) + { + EventWrittenEventArgs[] connectionsEstablished = events.Where(e => e.EventName == "ConnectionEstablished").ToArray(); + Assert.Equal(count, connectionsEstablished.Length); + foreach (EventWrittenEventArgs connectionEstablished in connectionsEstablished) + { + Assert.Equal(2, connectionEstablished.Payload.Count); + Assert.Equal(versionMajor, (byte)connectionEstablished.Payload[0]); + Assert.Equal(versionMinor, (byte)connectionEstablished.Payload[1]); + } + + EventWrittenEventArgs[] connectionsClosed = events.Where(e => e.EventName == "ConnectionClosed").ToArray(); + Assert.Equal(count, connectionsClosed.Length); + foreach (EventWrittenEventArgs connectionClosed in connectionsClosed) + { + Assert.Equal(2, connectionClosed.Payload.Count); + Assert.Equal(versionMajor, (byte)connectionClosed.Payload[0]); + Assert.Equal(versionMinor, (byte)connectionClosed.Payload[1]); + } + } + + protected static void VerifyEventCounters(ConcurrentQueue events, int requestCount, bool shouldHaveFailures, int requestsLeftQueueVersion = -1) { Dictionary eventCounters = events .Where(e => e.EventName == "EventCounters") @@ -187,30 +200,38 @@ protected static void VerifyEventCounters(ConcurrentQueue Assert.All(http20ConnectionsTotal, c => Assert.True(c >= 0)); Assert.Equal(0, http20ConnectionsTotal[^1]); - Assert.True(eventCounters.TryGetValue("http11-requests-queue-duration", out double[] requestQueueDurations)); - Assert.Equal(0, requestQueueDurations[^1]); - if (shouldHaveQueuedRequests) + Assert.True(eventCounters.TryGetValue("http11-requests-queue-duration", out double[] http11requestQueueDurations)); + Assert.Equal(0, http11requestQueueDurations[^1]); + if (requestsLeftQueueVersion == 1) { - Assert.Contains(requestQueueDurations, d => d > 0); - Assert.All(requestQueueDurations, d => Assert.True(d >= 0)); + Assert.Contains(http11requestQueueDurations, d => d > 0); + Assert.All(http11requestQueueDurations, d => Assert.True(d >= 0)); } else { - Assert.All(requestQueueDurations, d => Assert.True(d == 0)); + Assert.All(http11requestQueueDurations, d => Assert.True(d == 0)); } - } - } - public sealed class TelemetryTest_Http11 : TelemetryTest - { - public TelemetryTest_Http11(ITestOutputHelper output) : base(output) { } + Assert.True(eventCounters.TryGetValue("http20-requests-queue-duration", out double[] http20requestQueueDurations)); + Assert.Equal(0, http20requestQueueDurations[^1]); + if (requestsLeftQueueVersion == 2) + { + Assert.Contains(http20requestQueueDurations, d => d > 0); + Assert.All(http20requestQueueDurations, d => Assert.True(d >= 0)); + } + else + { + Assert.All(http20requestQueueDurations, d => Assert.True(d == 0)); + } + } [OuterLoop] [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] public void EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue() { - RemoteExecutor.Invoke(async () => + RemoteExecutor.Invoke(async useVersionString => { + Version version = Version.Parse(useVersionString); using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d); var events = new ConcurrentQueue(); @@ -219,15 +240,17 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => var firstRequestReceived = new SemaphoreSlim(0, 1); var secondRequestSent = new SemaphoreSlim(0, 1); - await LoopbackServer.CreateClientAndServerAsync( + await GetFactoryForVersion(version).CreateClientAndServerAsync( async uri => { - using var handler = new SocketsHttpHandler - { - MaxConnectionsPerServer = 1 - }; + using HttpClientHandler handler = CreateHttpClientHandler(useVersionString); + using HttpClient client = CreateHttpClient(handler, useVersionString); - using var client = new HttpClient(handler); + var socketsHttpHandler = GetUnderlyingSocketsHttpHandler(handler) as SocketsHttpHandler; + socketsHttpHandler.MaxConnectionsPerServer = 1; + + // Dummy request to ensure that the MaxConcurrentStreams setting has been acknowledged + await client.GetStringAsync(uri); Task firstRequest = client.GetStringAsync(uri); Assert.True(await firstRequestReceived.WaitAsync(TimeSpan.FromSeconds(10))); @@ -240,16 +263,34 @@ await LoopbackServer.CreateClientAndServerAsync( }, async server => { - await server.AcceptConnectionAsync(async connection => + GenericLoopbackConnection connection; + if (server is Http2LoopbackServer http2Server) { + http2Server.AllowMultipleConnections = true; + connection = await http2Server.EstablishConnectionAsync(new SettingsEntry { SettingId = SettingId.MaxConcurrentStreams, Value = 1 }); + } + else + { + connection = await server.EstablishGenericConnectionAsync(); + } + + using (connection) + { + // Dummy request to ensure that the MaxConcurrentStreams setting has been acknowledged + await connection.ReadRequestDataAsync(readBody: false); + await connection.SendResponseAsync(); + + // First request + await connection.ReadRequestDataAsync(readBody: false); firstRequestReceived.Release(); - await connection.ReadRequestDataAsync(); Assert.True(await secondRequestSent.WaitAsync(TimeSpan.FromSeconds(10))); await Task.Delay(100); await connection.SendResponseAsync(); - }); - await server.HandleRequestAsync(); + // Second request + await connection.ReadRequestDataAsync(readBody: false); + await connection.SendResponseAsync(); + }; }); await Task.Delay(300); @@ -257,36 +298,37 @@ await server.AcceptConnectionAsync(async connection => Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself EventWrittenEventArgs[] starts = events.Where(e => e.EventName == "RequestStart").ToArray(); - Assert.Equal(2, starts.Length); + Assert.Equal(3, starts.Length); Assert.All(starts, s => ValidateStartEventPayload(s)); EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "RequestStop").ToArray(); - Assert.Equal(2, stops.Length); + Assert.Equal(3, stops.Length); Assert.All(stops, s => Assert.Empty(s.Payload)); Assert.DoesNotContain(events, e => e.EventName == "RequestAborted"); - EventWrittenEventArgs[] connectionsEstablished = events.Where(e => e.EventName == "Http11ConnectionEstablished").ToArray(); - Assert.Equal(2, connectionsEstablished.Length); - Assert.All(connectionsEstablished, c => Assert.Empty(c.Payload)); - - EventWrittenEventArgs[] connectionsClosed = events.Where(e => e.EventName == "Http11ConnectionClosed").ToArray(); - Assert.Equal(2, connectionsClosed.Length); - Assert.All(connectionsClosed, c => Assert.Empty(c.Payload)); + ValidateConnectionEstablishedClosed(events, version.Major, version.Minor); - EventWrittenEventArgs requestLeftQueue = Assert.Single(events, e => e.EventName == "Http11RequestLeftQueue"); - double duration = Assert.IsType(Assert.Single(requestLeftQueue.Payload)); - Assert.True(duration > 0); + EventWrittenEventArgs requestLeftQueue = Assert.Single(events, e => e.EventName == "RequestLeftQueue"); + Assert.Equal(3, requestLeftQueue.Payload.Count); + Assert.True((double)requestLeftQueue.Payload.Count > 0); // timeSpentOnQueue + Assert.Equal(version.Major, (byte)requestLeftQueue.Payload[1]); + Assert.Equal(version.Minor, (byte)requestLeftQueue.Payload[2]); EventWrittenEventArgs[] responseHeadersBegin = events.Where(e => e.EventName == "ResponseHeadersBegin").ToArray(); - Assert.Equal(2, responseHeadersBegin.Length); + Assert.Equal(3, responseHeadersBegin.Length); Assert.All(responseHeadersBegin, r => Assert.Empty(r.Payload)); - VerifyEventCounters(events, requestCount: 2, shouldHaveFailures: false, shouldHaveQueuedRequests: true); - }).Dispose(); + VerifyEventCounters(events, requestCount: 3, shouldHaveFailures: false, requestsLeftQueueVersion: version.Major); + }, UseVersion.ToString()).Dispose(); } } + public sealed class TelemetryTest_Http11 : TelemetryTest + { + public TelemetryTest_Http11(ITestOutputHelper output) : base(output) { } + } + public sealed class TelemetryTest_Http20 : TelemetryTest { protected override Version UseVersion => HttpVersion.Version20; diff --git a/src/libraries/System.Net.Security/src/System/Net/Security/NetSecurityTelemetry.cs b/src/libraries/System.Net.Security/src/System/Net/Security/NetSecurityTelemetry.cs index f283faf6ee46e5..0c393405bfc4ca 100644 --- a/src/libraries/System.Net.Security/src/System/Net/Security/NetSecurityTelemetry.cs +++ b/src/libraries/System.Net.Security/src/System/Net/Security/NetSecurityTelemetry.cs @@ -133,7 +133,7 @@ public void HandshakeStart(bool isServer, string targetHost) } [Event(2, Level = EventLevel.Informational)] - private void HandshakeStop(string protocol) + private void HandshakeStop(SslProtocols protocol) { if (IsEnabled(EventLevel.Informational, EventKeywords.None)) { @@ -159,7 +159,7 @@ public void HandshakeFailed(bool isServer, ValueStopwatch stopwatch, string exce HandshakeFailed(isServer, stopwatch.GetElapsedTime().TotalMilliseconds, exceptionMessage); } - HandshakeStop(protocol: string.Empty); + HandshakeStop(SslProtocols.None); } [NonEvent] @@ -206,10 +206,7 @@ public void HandshakeCompleted(SslProtocols protocol, ValueStopwatch stopwatch, handshakeDurationCounter?.WriteMetric(duration); _handshakeDurationCounter!.WriteMetric(duration); - if (IsEnabled(EventLevel.Informational, EventKeywords.None)) - { - HandshakeStop(protocol.ToString()); - } + HandshakeStop(protocol); } [NonEvent] @@ -271,6 +268,21 @@ private unsafe void WriteEvent(int eventId, bool arg1, string? arg2) } } + [NonEvent] + private unsafe void WriteEvent(int eventId, SslProtocols arg1) + { + if (IsEnabled()) + { + var data = new EventData + { + DataPointer = (IntPtr)(&arg1), + Size = sizeof(SslProtocols) + }; + + WriteEventCore(eventId, eventDataCount: 1, &data); + } + } + [NonEvent] private unsafe void WriteEvent(int eventId, bool arg1, double arg2, string? arg3) { diff --git a/src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs index 1ce02cf14a1c71..72b71d04637815 100644 --- a/src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs +++ b/src/libraries/System.Net.Security/tests/FunctionalTests/TelemetryTest.cs @@ -5,6 +5,7 @@ using System.Collections.Generic; using System.Diagnostics.Tracing; using System.Linq; +using System.Security.Authentication; using System.Threading.Tasks; using Microsoft.DotNet.RemoteExecutor; using Xunit; @@ -51,8 +52,7 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "HandshakeStop").ToArray(); Assert.Equal(2, stops.Length); - Assert.All(stops, s => Assert.Equal(1, s.Payload.Count)); - Assert.All(stops, s => Assert.NotEmpty(s.Payload[0] as string)); + Assert.All(stops, s => ValidateHandshakeStopEventPayload(s, failure: false)); Assert.DoesNotContain(events, e => e.EventName == "HandshakeFailed"); @@ -92,13 +92,30 @@ await listener.RunWithCallbackAsync(events.Enqueue, async () => EventWrittenEventArgs[] stops = events.Where(e => e.EventName == "HandshakeStop").ToArray(); Assert.Equal(2, stops.Length); - Assert.All(stops, s => Assert.Equal(1, s.Payload.Count)); - Assert.All(stops, s => Assert.Empty(s.Payload[0] as string)); + Assert.All(stops, s => ValidateHandshakeStopEventPayload(s, failure: true)); VerifyEventCounters(events, shouldHaveFailures: true); }).Dispose(); } + private static void ValidateHandshakeStopEventPayload(EventWrittenEventArgs stopEvent, bool failure) + { + Assert.Equal("HandshakeStop", stopEvent.EventName); + Assert.Equal(1, stopEvent.Payload.Count); + + var protocol = (SslProtocols)stopEvent.Payload[0]; + Assert.True(Enum.IsDefined(protocol)); + + if (failure) + { + Assert.Equal(SslProtocols.None, protocol); + } + else + { + Assert.NotEqual(SslProtocols.None, protocol); + } + } + private static void VerifyEventCounters(ConcurrentQueue events, bool shouldHaveFailures) { Dictionary eventCounters = events