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..c9d0fb1bbce83c --- /dev/null +++ b/src/libraries/System.Net.Http/src/System/Net/Http/HttpTelemetry.cs @@ -0,0 +1,154 @@ +// 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; + +namespace System.Net.Http +{ + [EventSource(Name = "System.Net.Http")] + internal sealed class HttpTelemetry : EventSource + { + public static readonly HttpTelemetry Log = new HttpTelemetry(); + + private IncrementingPollingCounter? _startedRequestsPerSecondCounter; + private IncrementingPollingCounter? _abortedRequestsPerSecondCounter; + private PollingCounter? _startedRequestsCounter; + private PollingCounter? _currentRequestsCounter; + private PollingCounter? _abortedRequestsCounter; + + private long _startedRequests; + private long _stoppedRequests; + 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 scheme, string host, int port, string pathAndQuery, int versionMajor, int versionMinor) + { + Interlocked.Increment(ref _startedRequests); + WriteEvent(eventId: 1, scheme, host, port, pathAndQuery, versionMajor, versionMinor); + } + + [Event(2, Level = EventLevel.Informational)] + public void RequestStop() + { + Interlocked.Increment(ref _stoppedRequests); + WriteEvent(eventId: 2); + } + + [Event(3, Level = EventLevel.Error)] + public void RequestAborted() + { + Interlocked.Increment(ref _abortedRequests); + WriteEvent(eventId: 3); + } + + 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, () => Interlocked.Read(ref _startedRequests)) + { + DisplayName = "Requests Started", + }; + + // The number of HTTP requests started per second since the process started. + _startedRequestsPerSecondCounter ??= new IncrementingPollingCounter("requests-started-rate", this, () => Interlocked.Read(ref _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, () => Interlocked.Read(ref _abortedRequests)) + { + DisplayName = "Requests Aborted" + }; + + // The number of HTTP requests aborted per second since the process started. + _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. + // 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" + }; + } + } + + [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..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 @@ -339,6 +339,44 @@ 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 (Exception e) when (LogException(e)) + { + // This code should never run. + throw; + } + + static bool LogException(Exception e) + { + HttpTelemetry.Log.RequestAborted(); + HttpTelemetry.Log.RequestStop(); + + // 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; + } + } + + 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; }