From b7e7c2db09b2f9ae9b1a54650a3deed9cec2c3da Mon Sep 17 00:00:00 2001 From: David Shulman Date: Wed, 20 May 2020 21:09:45 -0700 Subject: [PATCH 1/6] [WIP] Add telemetry to System.Net.Http This is the first of several PRs to add telemetry focused events and counters. A few things to note: * Added a new dedicated namespace for telemetry. Current feedback from partners is that our existing events are "confusing and a mess" due to their focus on low-level diagnostics and verbose debugging. See discussion in #37428 regarding reasons for a new namespace. * Please comment on the naming patterns for the events, counters, and display names, etc. I looked at ASP.NET events/counters and @anurse older guidance in https://gist.github.com/anurse/af1859663ac91c6cf69c820cebe92303. But there are inconsistencies between all of that. So, I'd like to get agreement on naming patterns for events/counters (i.e. noun-verb vs. verb-noun, present tense vs. past tense, etc.). * No automated tests were added at this time. The current discussions with others (reverse proxy team) is that automated tests are brittle in CI. But manual tests will be run. Contributes to #37428 --- .../src/System.Net.Http.csproj | 1 + .../src/System/Net/Http/HttpTelemetry.cs | 104 ++++++++++++++++++ .../SocketsHttpHandler/SocketsHttpHandler.cs | 20 +++- 3 files changed, 124 insertions(+), 1 deletion(-) create mode 100644 src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs diff --git a/src/libraries/System.Net.Http/src/System.Net.Http.csproj b/src/libraries/System.Net.Http/src/System.Net.Http.csproj index e7ebd8c441c0d2..804d10de22a86f 100644 --- a/src/libraries/System.Net.Http/src/System.Net.Http.csproj +++ b/src/libraries/System.Net.Http/src/System.Net.Http.csproj @@ -43,6 +43,7 @@ + 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 new file mode 100644 index 00000000000000..7356ef30f9706f --- /dev/null +++ b/src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs @@ -0,0 +1,104 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using System.Diagnostics.Tracing; +using System.Runtime.CompilerServices; +using System.Threading; + +// TODO: Get rid of this once I figure out how to handle build errors like these given the current lazy creation pattern: +// System\Net\Http\HttpTelemetry.cs(19,32): error CS8618: Non-nullable field '_startedRequestsCounter' is uninitialized. +// Consider declaring the field as nullable. [S:\GitHub\runtime\src\libraries\System.Net.Http\src\System.Net.Http.csproj] +#nullable disable + +namespace System.Net.Http +{ + [EventSource(Name = "System.Net.Http")] + internal sealed class HttpTelemetry : EventSource + { + public static readonly HttpTelemetry Log = new HttpTelemetry(); + + private IncrementingPollingCounter _requestsPerSecondCounter; + private PollingCounter _startedRequestsCounter; + private PollingCounter _currentRequestsCounter; + private PollingCounter _abortedRequestsCounter; + + private long _startedRequests; + private long _currentRequests; + private long _abortedRequests; + + public static new bool IsEnabled => Log.IsEnabled(); + + // NOTE + // - The 'Start' and 'Stop' suffixes on the following event names have special meaning in EventSource. They + // enable creating 'activities'. + // For more information, take a look at the following blog post: + // https://blogs.msdn.microsoft.com/vancem/2015/09/14/exploring-eventsource-activity-correlation-and-causation-features/ + // - A stop event's event id must be next one after its start event. + + [Event(1, Level = EventLevel.Informational)] + public void RequestStart(string host, int port) + { + Interlocked.Increment(ref _startedRequests); + Interlocked.Increment(ref _currentRequests); + WriteEvent(1, host, port); + } + + [Event(2, Level = EventLevel.Informational)] + public void RequestStop(string host, int port) + { + Interlocked.Decrement(ref _currentRequests); + WriteEvent(2, host, port); + } + + [NonEvent] + public void RequestAbort() + { + Interlocked.Increment(ref _abortedRequests); + } + + protected override void OnEventCommand(EventCommandEventArgs command) + { + if (command.Command == EventCommand.Enable) + { + // This is the convention for initializing counters in the RuntimeEventSource (lazily on the first enable command). + // They aren't disabled afterwards... + + // The cumulative number of HTTP requests started since the process started. + _startedRequestsCounter ??= new PollingCounter("requests-started", this, () => _startedRequests) + { + DisplayName = "Requests Started", + }; + + // The number of HTTP requests started per second since the process started. + _requestsPerSecondCounter ??= new IncrementingPollingCounter("requests-started-per-second", this, () => _startedRequests) + { + DisplayName = "Requests Started Rate", + DisplayRateTimeScale = TimeSpan.FromSeconds(1) + }; + + // The cumulative number of HTTP requests aborted since the process started. + // Aborted means that an exception occurred during the handler's Send(Async) call as a result of a + // connection related error, timeout, or explicitly cancelled. + _abortedRequestsCounter ??= new PollingCounter("requests-aborted", this, () => _abortedRequests) + { + DisplayName = "Requests Aborted" + }; + + // The number of HTTP requests aborted per second since the process started. + _requestsPerSecondCounter ??= new IncrementingPollingCounter("requests-aborted-per-second", this, () => _abortedRequests) + { + DisplayName = "Requests Aborted Rate", + DisplayRateTimeScale = TimeSpan.FromSeconds(1) + }; + + // The current number of active HTTP requests that have started but not yet completed or aborted. + _currentRequestsCounter ??= new PollingCounter("current-requests", this, () => _currentRequests) + { + DisplayName = "Current Requests" + }; + } + } + } +} diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs index 3f6ec70d07da93..c2fdafe76ccad1 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs @@ -345,7 +345,25 @@ protected internal override Task SendAsync( return Task.FromException(error); } - return handler.SendAsync(request, cancellationToken); + if (HttpTelemetry.IsEnabled && request.RequestUri != null) + { + // Wrap the task for event activity-id threading. + HttpTelemetry.Log.RequestStart(request.RequestUri.IdnHost, request.RequestUri.Port); + Task task = handler.SendAsync(request, cancellationToken); + task.ContinueWith( + t => HttpTelemetry.Log.RequestAbort(), + cancellationToken, + TaskContinuationOptions.OnlyOnCanceled | TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default); + task.ContinueWith( + t => HttpTelemetry.Log.RequestStop(request.RequestUri.IdnHost, request.RequestUri.Port), + cancellationToken, + TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default); + return task; + } + else + { + return handler.SendAsync(request, cancellationToken); + } } private Exception? ValidateAndNormalizeRequest(HttpRequestMessage request) From 8756a0d2926f0a018867f1f210064108d89a427a Mon Sep 17 00:00:00 2001 From: David Shulman Date: Wed, 10 Jun 2020 14:20:20 -0700 Subject: [PATCH 2/6] Address PR feedback * PR feedback * Added RequestAbort as separate event method with dimensions (host, port) --- .../src/System/Net/Http/HttpTelemetry.cs | 28 +++++++-------- .../SocketsHttpHandler/SocketsHttpHandler.cs | 36 ++++++++++--------- 2 files changed, 32 insertions(+), 32 deletions(-) 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 7356ef30f9706f..2b8533f9d653e0 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 @@ -7,11 +7,6 @@ using System.Runtime.CompilerServices; using System.Threading; -// TODO: Get rid of this once I figure out how to handle build errors like these given the current lazy creation pattern: -// System\Net\Http\HttpTelemetry.cs(19,32): error CS8618: Non-nullable field '_startedRequestsCounter' is uninitialized. -// Consider declaring the field as nullable. [S:\GitHub\runtime\src\libraries\System.Net.Http\src\System.Net.Http.csproj] -#nullable disable - namespace System.Net.Http { [EventSource(Name = "System.Net.Http")] @@ -19,10 +14,10 @@ internal sealed class HttpTelemetry : EventSource { public static readonly HttpTelemetry Log = new HttpTelemetry(); - private IncrementingPollingCounter _requestsPerSecondCounter; - private PollingCounter _startedRequestsCounter; - private PollingCounter _currentRequestsCounter; - private PollingCounter _abortedRequestsCounter; + private IncrementingPollingCounter? _requestsPerSecondCounter; + private PollingCounter? _startedRequestsCounter; + private PollingCounter? _currentRequestsCounter; + private PollingCounter? _abortedRequestsCounter; private long _startedRequests; private long _currentRequests; @@ -52,10 +47,11 @@ public void RequestStop(string host, int port) WriteEvent(2, host, port); } - [NonEvent] - public void RequestAbort() + [Event(3, Level = EventLevel.Error)] + public void RequestAbort(string host, int port) { Interlocked.Increment(ref _abortedRequests); + WriteEvent(3, host, port); } protected override void OnEventCommand(EventCommandEventArgs command) @@ -66,13 +62,13 @@ protected override void OnEventCommand(EventCommandEventArgs command) // They aren't disabled afterwards... // The cumulative number of HTTP requests started since the process started. - _startedRequestsCounter ??= new PollingCounter("requests-started", this, () => _startedRequests) + _startedRequestsCounter ??= new PollingCounter("requests-started", this, () => Interlocked.Read(ref _startedRequests)) { DisplayName = "Requests Started", }; // The number of HTTP requests started per second since the process started. - _requestsPerSecondCounter ??= new IncrementingPollingCounter("requests-started-per-second", this, () => _startedRequests) + _requestsPerSecondCounter ??= new IncrementingPollingCounter("requests-started-per-second", this, () => Interlocked.Read(ref _startedRequests)) { DisplayName = "Requests Started Rate", DisplayRateTimeScale = TimeSpan.FromSeconds(1) @@ -81,20 +77,20 @@ protected override void OnEventCommand(EventCommandEventArgs command) // The cumulative number of HTTP requests aborted since the process started. // Aborted means that an exception occurred during the handler's Send(Async) call as a result of a // connection related error, timeout, or explicitly cancelled. - _abortedRequestsCounter ??= new PollingCounter("requests-aborted", this, () => _abortedRequests) + _abortedRequestsCounter ??= new PollingCounter("requests-aborted", this, () => Interlocked.Read(ref _abortedRequests)) { DisplayName = "Requests Aborted" }; // The number of HTTP requests aborted per second since the process started. - _requestsPerSecondCounter ??= new IncrementingPollingCounter("requests-aborted-per-second", this, () => _abortedRequests) + _requestsPerSecondCounter ??= new IncrementingPollingCounter("requests-aborted-per-second", this, () => Interlocked.Read(ref _abortedRequests)) { DisplayName = "Requests Aborted Rate", DisplayRateTimeScale = TimeSpan.FromSeconds(1) }; // The current number of active HTTP requests that have started but not yet completed or aborted. - _currentRequestsCounter ??= new PollingCounter("current-requests", this, () => _currentRequests) + _currentRequestsCounter ??= new PollingCounter("current-requests", this, () => Interlocked.Read(ref _currentRequests)) { DisplayName = "Current Requests" }; diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs index c2fdafe76ccad1..62b8ebc28caeb3 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs @@ -6,6 +6,7 @@ using System.Net.Security; using System.Threading; using System.Threading.Tasks; +using System.Diagnostics; using System.Diagnostics.CodeAnalysis; namespace System.Net.Http @@ -345,24 +346,27 @@ protected internal override Task SendAsync( return Task.FromException(error); } - if (HttpTelemetry.IsEnabled && request.RequestUri != null) + return HttpTelemetry.IsEnabled && request.RequestUri != null ? + WithLogging(handler, request, cancellationToken) : + handler.SendAsync(request, cancellationToken); + + static async Task WithLogging(HttpMessageHandler handler, HttpRequestMessage request, CancellationToken cancellationToken) { - // Wrap the task for event activity-id threading. + Debug.Assert(request.RequestUri != null); HttpTelemetry.Log.RequestStart(request.RequestUri.IdnHost, request.RequestUri.Port); - Task task = handler.SendAsync(request, cancellationToken); - task.ContinueWith( - t => HttpTelemetry.Log.RequestAbort(), - cancellationToken, - TaskContinuationOptions.OnlyOnCanceled | TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default); - task.ContinueWith( - t => HttpTelemetry.Log.RequestStop(request.RequestUri.IdnHost, request.RequestUri.Port), - cancellationToken, - TaskContinuationOptions.ExecuteSynchronously, TaskScheduler.Default); - return task; - } - else - { - return handler.SendAsync(request, cancellationToken); + try + { + return await handler.SendAsync(request, cancellationToken).ConfigureAwait(false); + } + catch + { + HttpTelemetry.Log.RequestAbort(request.RequestUri.IdnHost, request.RequestUri.Port); + throw; + } + finally + { + HttpTelemetry.Log.RequestStop(request.RequestUri.IdnHost, request.RequestUri.Port); + } } } From 0c67b6cd317320fb0b0b594e0591415304e0be71 Mon Sep 17 00:00:00 2001 From: David Shulman Date: Mon, 15 Jun 2020 11:53:13 -0700 Subject: [PATCH 3/6] Address PR feedback 2 * RequestStart now includes host, port, scheme, path and version * RequestStart and RequestStop now bracket the lifetime of the request including reading the response body stream. If the response body is not complete read then disposing the stream will trigger RequestStop as well. --- .../src/System/Net/Http/HttpTelemetry.cs | 78 +++++++++++++++---- .../ChunkedEncodingReadStream.cs | 2 + .../ConnectionCloseReadStream.cs | 3 + .../ContentLengthReadStream.cs | 3 + .../Http/SocketsHttpHandler/Http2Stream.cs | 4 + .../Http/SocketsHttpHandler/HttpConnection.cs | 2 + .../HttpConnectionPoolManager.cs | 29 +++++++ .../SocketsHttpHandler/HttpContentStream.cs | 13 ++++ .../SocketsHttpHandler/RawConnectionStream.cs | 3 + .../SocketsHttpHandler/SocketsHttpHandler.cs | 23 +----- 10 files changed, 125 insertions(+), 35 deletions(-) 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 2b8533f9d653e0..18f8029f66cad6 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 @@ -14,13 +14,14 @@ internal sealed class HttpTelemetry : EventSource { public static readonly HttpTelemetry Log = new HttpTelemetry(); - private IncrementingPollingCounter? _requestsPerSecondCounter; + private IncrementingPollingCounter? _startedRequestsPerSecondCounter; + private IncrementingPollingCounter? _abortedRequestsPerSecondCounter; private PollingCounter? _startedRequestsCounter; private PollingCounter? _currentRequestsCounter; private PollingCounter? _abortedRequestsCounter; private long _startedRequests; - private long _currentRequests; + private long _stoppedRequests; private long _abortedRequests; public static new bool IsEnabled => Log.IsEnabled(); @@ -33,25 +34,24 @@ internal sealed class HttpTelemetry : EventSource // - A stop event's event id must be next one after its start event. [Event(1, Level = EventLevel.Informational)] - public void RequestStart(string host, int port) + public void RequestStart(string scheme, string host, int port, string pathAndQuery, int versionMajor, int versionMinor) { Interlocked.Increment(ref _startedRequests); - Interlocked.Increment(ref _currentRequests); - WriteEvent(1, host, port); + WriteEvent(1, scheme, host, port, pathAndQuery, versionMajor, versionMinor); } [Event(2, Level = EventLevel.Informational)] - public void RequestStop(string host, int port) + public void RequestStop() { - Interlocked.Decrement(ref _currentRequests); - WriteEvent(2, host, port); + Interlocked.Increment(ref _stoppedRequests); + WriteEvent(2); } [Event(3, Level = EventLevel.Error)] - public void RequestAbort(string host, int port) + public void RequestAborted() { Interlocked.Increment(ref _abortedRequests); - WriteEvent(3, host, port); + WriteEvent(3); } protected override void OnEventCommand(EventCommandEventArgs command) @@ -68,7 +68,7 @@ protected override void OnEventCommand(EventCommandEventArgs command) }; // The number of HTTP requests started per second since the process started. - _requestsPerSecondCounter ??= new IncrementingPollingCounter("requests-started-per-second", this, () => Interlocked.Read(ref _startedRequests)) + _startedRequestsPerSecondCounter ??= new IncrementingPollingCounter("requests-started-rate", this, () => Interlocked.Read(ref _startedRequests)) { DisplayName = "Requests Started Rate", DisplayRateTimeScale = TimeSpan.FromSeconds(1) @@ -83,18 +83,70 @@ protected override void OnEventCommand(EventCommandEventArgs command) }; // The number of HTTP requests aborted per second since the process started. - _requestsPerSecondCounter ??= new IncrementingPollingCounter("requests-aborted-per-second", this, () => Interlocked.Read(ref _abortedRequests)) + _abortedRequestsPerSecondCounter ??= new IncrementingPollingCounter("requests-aborted-rate", this, () => Interlocked.Read(ref _abortedRequests)) { DisplayName = "Requests Aborted Rate", DisplayRateTimeScale = TimeSpan.FromSeconds(1) }; // The current number of active HTTP requests that have started but not yet completed or aborted. - _currentRequestsCounter ??= new PollingCounter("current-requests", this, () => Interlocked.Read(ref _currentRequests)) + _currentRequestsCounter ??= new PollingCounter("current-requests", this, () => Interlocked.Read(ref _startedRequests) - Interlocked.Read(ref _stoppedRequests)) { DisplayName = "Current Requests" }; } } + + [NonEvent] + private unsafe void WriteEvent(int eventId, string? arg1, string? arg2, int arg3, string? arg4, int arg5, int arg6) + { + if (IsEnabled()) + { + if (arg1 == null) arg1 = ""; + if (arg2 == null) arg2 = ""; + if (arg4 == null) arg4 = ""; + + fixed (char* arg1Ptr = arg1) + fixed (char* arg2Ptr = arg2) + fixed (char* arg4Ptr = arg4) + { + const int NumEventDatas = 6; + var descrs = stackalloc EventData[NumEventDatas]; + + descrs[0] = new EventData + { + DataPointer = (IntPtr)(arg1Ptr), + Size = (arg1.Length + 1) * sizeof(char) + }; + descrs[1] = new EventData + { + DataPointer = (IntPtr)(arg2Ptr), + Size = (arg2.Length + 1) * sizeof(char) + }; + descrs[2] = new EventData + { + DataPointer = (IntPtr)(&arg3), + Size = sizeof(int) + }; + descrs[3] = new EventData + { + DataPointer = (IntPtr)(arg4Ptr), + Size = (arg4.Length + 1) * sizeof(char) + }; + descrs[4] = new EventData + { + DataPointer = (IntPtr)(&arg5), + Size = sizeof(int) + }; + descrs[5] = new EventData + { + DataPointer = (IntPtr)(&arg6), + Size = sizeof(int) + }; + + WriteEventCore(eventId, NumEventDatas, descrs); + } + } + } } } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs index 72c5858a9a7af8..8ab8dfe0ab5f51 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs @@ -57,6 +57,7 @@ public override int Read(Span buffer) if (_connection == null) { // Fully consumed the response in ReadChunksFromConnectionBuffer. + if (HttpTelemetry.IsEnabled) LogRequestStop(); return 0; } @@ -362,6 +363,7 @@ private ReadOnlyMemory ReadChunkFromConnectionBuffer(int maxBytesToRead, C cancellationRegistration.Dispose(); CancellationHelper.ThrowIfCancellationRequested(cancellationRegistration.Token); + if (HttpTelemetry.IsEnabled) LogRequestStop(); _state = ParsingState.Done; _connection.CompleteResponse(); _connection = null; diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionCloseReadStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionCloseReadStream.cs index 99f9c235b5add0..c199c65f19a9fa 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionCloseReadStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionCloseReadStream.cs @@ -29,6 +29,7 @@ public override int Read(Span buffer) if (bytesRead == 0) { // We cannot reuse this connection, so close it. + if (HttpTelemetry.IsEnabled) LogRequestStop(); _connection = null; connection.Dispose(); } @@ -81,6 +82,7 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation CancellationHelper.ThrowIfCancellationRequested(cancellationToken); // We cannot reuse this connection, so close it. + if (HttpTelemetry.IsEnabled) LogRequestStop(); _connection = null; connection.Dispose(); } @@ -142,6 +144,7 @@ private async Task CompleteCopyToAsync(Task copyTask, HttpConnection connection, private void Finish(HttpConnection connection) { // We cannot reuse this connection, so close it. + if (HttpTelemetry.IsEnabled) LogRequestStop(); _connection = null; connection.Dispose(); } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs index cae7197bf0b057..ad6bff5783e312 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs @@ -48,6 +48,7 @@ public override int Read(Span buffer) if (_contentBytesRemaining == 0) { // End of response body + if (HttpTelemetry.IsEnabled) LogRequestStop(); _connection.CompleteResponse(); _connection = null; } @@ -110,6 +111,7 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation if (_contentBytesRemaining == 0) { // End of response body + if (HttpTelemetry.IsEnabled) LogRequestStop(); _connection.CompleteResponse(); _connection = null; } @@ -164,6 +166,7 @@ private async Task CompleteCopyToAsync(Task copyTask, CancellationToken cancella private void Finish() { + if (HttpTelemetry.IsEnabled) LogRequestStop(); _contentBytesRemaining = 0; _connection!.CompleteResponse(); _connection = null; diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs index 146a48da27d186..77890eff4ea801 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs @@ -346,6 +346,8 @@ private void Complete() w.Dispose(); _creditWaiter = null; } + + if (HttpTelemetry.IsEnabled) HttpTelemetry.Log.RequestStop(); } private void Cancel() @@ -380,6 +382,8 @@ private void Cancel() { _waitSource.SetResult(true); } + + if (HttpTelemetry.IsEnabled) HttpTelemetry.Log.RequestAborted(); } // Returns whether the waiter should be signalled or not. diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs index 04b6f4eb4f3d75..028502357a628c 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs @@ -606,6 +606,7 @@ public async Task SendAsyncCore(HttpRequestMessage request, Stream responseStream; if (ReferenceEquals(normalizedMethod, HttpMethod.Head) || response.StatusCode == HttpStatusCode.NoContent || response.StatusCode == HttpStatusCode.NotModified) { + if (HttpTelemetry.IsEnabled) HttpTelemetry.Log.RequestStop(); responseStream = EmptyReadStream.Instance; CompleteResponse(); } @@ -628,6 +629,7 @@ public async Task SendAsyncCore(HttpRequestMessage request, long contentLength = response.Content.Headers.ContentLength.GetValueOrDefault(); if (contentLength <= 0) { + if (HttpTelemetry.IsEnabled) HttpTelemetry.Log.RequestStop(); responseStream = EmptyReadStream.Instance; CompleteResponse(); } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs index 252c3e5795c998..6de5fff8e0d2ae 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs @@ -339,6 +339,35 @@ public Task SendProxyConnectAsync(HttpRequestMessage reques } public Task SendAsync(HttpRequestMessage request, bool doRequestAuth, CancellationToken cancellationToken) + { + return HttpTelemetry.IsEnabled && request.RequestUri != null ? + SendAsyncWithLogging(request, doRequestAuth, cancellationToken) : + SendAsyncHelper(request, doRequestAuth, cancellationToken); + } + + private async Task SendAsyncWithLogging(HttpRequestMessage request, bool doRequestAuth, CancellationToken cancellationToken) + { + Debug.Assert(request.RequestUri != null); + HttpTelemetry.Log.RequestStart( + request.RequestUri.Scheme, + request.RequestUri.IdnHost, + request.RequestUri.Port, + request.RequestUri.PathAndQuery, + request.Version.Major, + request.Version.Minor); + try + { + return await SendAsyncHelper(request, doRequestAuth, cancellationToken).ConfigureAwait(false); + } + catch + { + HttpTelemetry.Log.RequestAborted(); + HttpTelemetry.Log.RequestStop(); + throw; + } + } + + private Task SendAsyncHelper(HttpRequestMessage request, bool doRequestAuth, CancellationToken cancellationToken) { if (_proxy == null) { diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpContentStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpContentStream.cs index 294389040edcec..319523dc36d5c7 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpContentStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpContentStream.cs @@ -2,12 +2,17 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using System.Threading; + namespace System.Net.Http { internal abstract class HttpContentStream : HttpBaseStream { protected HttpConnection? _connection; + // Makes sure we don't call HttpTelemetry events more than once. + private int _requestStopCalled; // 0==no, 1==yes + public HttpContentStream(HttpConnection connection) { _connection = connection; @@ -36,6 +41,14 @@ protected HttpConnection GetConnectionOrThrow() ThrowObjectDisposedException(); } + protected void LogRequestStop() + { + if (Interlocked.Exchange(ref _requestStopCalled, 1) == 0) + { + HttpTelemetry.Log.RequestStop(); + } + } + private HttpConnection ThrowObjectDisposedException() => throw new ObjectDisposedException(GetType().Name); } } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RawConnectionStream.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RawConnectionStream.cs index 9d1184dd38320c..cd014ec19b584c 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RawConnectionStream.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RawConnectionStream.cs @@ -34,6 +34,7 @@ public override int Read(Span buffer) if (bytesRead == 0) { // We cannot reuse this connection, so close it. + if (HttpTelemetry.IsEnabled) LogRequestStop(); _connection = null; connection.Dispose(); } @@ -81,6 +82,7 @@ public override async ValueTask ReadAsync(Memory buffer, Cancellation CancellationHelper.ThrowIfCancellationRequested(cancellationToken); // We cannot reuse this connection, so close it. + if (HttpTelemetry.IsEnabled) LogRequestStop(); _connection = null; connection.Dispose(); } @@ -142,6 +144,7 @@ private async Task CompleteCopyToAsync(Task copyTask, HttpConnection connection, private void Finish(HttpConnection connection) { // We cannot reuse this connection, so close it. + if (HttpTelemetry.IsEnabled) LogRequestStop(); connection.Dispose(); _connection = null; } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs index 62b8ebc28caeb3..544981a64da71a 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs @@ -346,28 +346,7 @@ protected internal override Task SendAsync( return Task.FromException(error); } - return HttpTelemetry.IsEnabled && request.RequestUri != null ? - WithLogging(handler, request, cancellationToken) : - handler.SendAsync(request, cancellationToken); - - static async Task WithLogging(HttpMessageHandler handler, HttpRequestMessage request, CancellationToken cancellationToken) - { - Debug.Assert(request.RequestUri != null); - HttpTelemetry.Log.RequestStart(request.RequestUri.IdnHost, request.RequestUri.Port); - try - { - return await handler.SendAsync(request, cancellationToken).ConfigureAwait(false); - } - catch - { - HttpTelemetry.Log.RequestAbort(request.RequestUri.IdnHost, request.RequestUri.Port); - throw; - } - finally - { - HttpTelemetry.Log.RequestStop(request.RequestUri.IdnHost, request.RequestUri.Port); - } - } + return handler.SendAsync(request, cancellationToken); } private Exception? ValidateAndNormalizeRequest(HttpRequestMessage request) From 33f731e33a7b049c7449e4b44c154f9263135a51 Mon Sep 17 00:00:00 2001 From: David Shulman Date: Fri, 19 Jun 2020 16:55:04 -0700 Subject: [PATCH 4/6] Address feedback 3 * Use exception filter to improve performance --- .../SocketsHttpHandler/HttpConnectionPoolManager.cs | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs index 6de5fff8e0d2ae..483a2587c57bf1 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs @@ -359,11 +359,20 @@ private async Task SendAsyncWithLogging(HttpRequestMessage { return await SendAsyncHelper(request, doRequestAuth, cancellationToken).ConfigureAwait(false); } - catch + catch (Exception e) when (LogException(e)) + { + // This code should never run. + throw; + } + + bool LogException(Exception e) { HttpTelemetry.Log.RequestAborted(); HttpTelemetry.Log.RequestStop(); - throw; + + // Returning false means the catch handler isn't run. + // So the exception isn't considered to be caught so it will now propagate up the stack. + return false; } } From 314dcc507435f35922e0d2da7e266d124a51333a Mon Sep 17 00:00:00 2001 From: David Shulman Date: Fri, 19 Jun 2020 19:25:34 -0700 Subject: [PATCH 5/6] Avoid negative 'current-requests' counter value --- .../System.Net.Http/src/System/Net/Http/HttpTelemetry.cs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) 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 18f8029f66cad6..aa1e68a49673e0 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 @@ -90,7 +90,9 @@ protected override void OnEventCommand(EventCommandEventArgs command) }; // The current number of active HTTP requests that have started but not yet completed or aborted. - _currentRequestsCounter ??= new PollingCounter("current-requests", this, () => Interlocked.Read(ref _startedRequests) - Interlocked.Read(ref _stoppedRequests)) + // Use (-_stoppedRequests + _startedRequests) to avoid returning a negative value if _stoppedRequests is + // incremented after reading _startedRequests due to race conditions with completing the HTTP request. + _currentRequestsCounter ??= new PollingCounter("current-requests", this, () => -Interlocked.Read(ref _stoppedRequests) + Interlocked.Read(ref _startedRequests)) { DisplayName = "Current Requests" }; From 0559242f97b58c3e929fc7ae51729ea353999c85 Mon Sep 17 00:00:00 2001 From: David Shulman Date: Tue, 23 Jun 2020 06:53:45 -0700 Subject: [PATCH 6/6] Address feedback 4 --- .../System.Net.Http/src/System/Net/Http/HttpTelemetry.cs | 6 +++--- .../Http/SocketsHttpHandler/HttpConnectionPoolManager.cs | 2 +- .../Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs | 1 - 3 files changed, 4 insertions(+), 5 deletions(-) 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 aa1e68a49673e0..c9d0fb1bbce83c 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 @@ -37,21 +37,21 @@ internal sealed class HttpTelemetry : EventSource public void RequestStart(string scheme, string host, int port, string pathAndQuery, int versionMajor, int versionMinor) { Interlocked.Increment(ref _startedRequests); - WriteEvent(1, scheme, host, port, pathAndQuery, versionMajor, versionMinor); + WriteEvent(eventId: 1, scheme, host, port, pathAndQuery, versionMajor, versionMinor); } [Event(2, Level = EventLevel.Informational)] public void RequestStop() { Interlocked.Increment(ref _stoppedRequests); - WriteEvent(2); + WriteEvent(eventId: 2); } [Event(3, Level = EventLevel.Error)] public void RequestAborted() { Interlocked.Increment(ref _abortedRequests); - WriteEvent(3); + WriteEvent(eventId: 3); } protected override void OnEventCommand(EventCommandEventArgs command) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs index 483a2587c57bf1..5c438e3070ed97 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs @@ -365,7 +365,7 @@ private async Task SendAsyncWithLogging(HttpRequestMessage throw; } - bool LogException(Exception e) + static bool LogException(Exception e) { HttpTelemetry.Log.RequestAborted(); HttpTelemetry.Log.RequestStop(); diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs index 544981a64da71a..3f6ec70d07da93 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/SocketsHttpHandler.cs @@ -6,7 +6,6 @@ using System.Net.Security; using System.Threading; using System.Threading.Tasks; -using System.Diagnostics; using System.Diagnostics.CodeAnalysis; namespace System.Net.Http