From e9f1da47a7fa60fa993c8bb31de40f38d231eb97 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Wed, 5 Jun 2019 00:11:27 -0700 Subject: [PATCH] Added basic event counters for hosting - Added Request Rate counter (RPS), Total Requests counter, current requests and failed requests. - Counters do nothing until enabled - Added tests for counters and improved tests to use unique event source names - Renamed EventSource to match the convention in the runtime Microsoft.AspNetCore.Hosting --- ...rosoft.AspNetCore.Hosting.netcoreapp3.0.cs | 2 +- .../Internal/HostingApplicationDiagnostics.cs | 15 ++- .../src/Internal/HostingEventSource.cs | 64 ++++++++- .../Internal/AsyncEnumerableExtensions.cs | 23 ++++ .../test/Internal/HostingEventSourceTests.cs | 124 ++++++++++++++---- .../Microsoft.AspNetCore.Hosting.Tests.csproj | 1 + 6 files changed, 199 insertions(+), 30 deletions(-) create mode 100644 src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs diff --git a/src/Hosting/Hosting/ref/Microsoft.AspNetCore.Hosting.netcoreapp3.0.cs b/src/Hosting/Hosting/ref/Microsoft.AspNetCore.Hosting.netcoreapp3.0.cs index 1b7b978add11..cbeec0f51ca1 100644 --- a/src/Hosting/Hosting/ref/Microsoft.AspNetCore.Hosting.netcoreapp3.0.cs +++ b/src/Hosting/Hosting/ref/Microsoft.AspNetCore.Hosting.netcoreapp3.0.cs @@ -145,7 +145,6 @@ public static partial class HostingEnvironmentExtensions public static void Initialize(this Microsoft.AspNetCore.Hosting.IHostingEnvironment hostingEnvironment, string contentRootPath, Microsoft.AspNetCore.Hosting.Internal.WebHostOptions options) { } public static void Initialize(this Microsoft.AspNetCore.Hosting.IWebHostEnvironment hostingEnvironment, string contentRootPath, Microsoft.AspNetCore.Hosting.Internal.WebHostOptions options) { } } - [System.Diagnostics.Tracing.EventSourceAttribute(Name="Microsoft-AspNetCore-Hosting")] public sealed partial class HostingEventSource : System.Diagnostics.Tracing.EventSource { internal HostingEventSource() { } @@ -154,6 +153,7 @@ internal HostingEventSource() { } public void HostStart() { } [System.Diagnostics.Tracing.EventAttribute(2, Level=System.Diagnostics.Tracing.EventLevel.Informational)] public void HostStop() { } + protected override void OnEventCommand(System.Diagnostics.Tracing.EventCommandEventArgs command) { } [System.Diagnostics.Tracing.EventAttribute(3, Level=System.Diagnostics.Tracing.EventLevel.Informational)] public void RequestStart(string method, string path) { } [System.Runtime.CompilerServices.MethodImpl(System.Runtime.CompilerServices.MethodImplOptions.NoInlining)][System.Diagnostics.Tracing.EventAttribute(4, Level=System.Diagnostics.Tracing.EventLevel.Informational)] diff --git a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs index 14aa54913980..9428a5667887 100644 --- a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs +++ b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs @@ -136,10 +136,19 @@ public void RequestEnd(HttpContext httpContext, Exception exception, HostingAppl StopActivity(httpContext, activity, context.HasDiagnosticListener); } - if (context.EventLogEnabled && exception != null) + if (context.EventLogEnabled) { - // Non-inline - HostingEventSource.Log.UnhandledException(); + if (exception != null) + { + // Non-inline + HostingEventSource.Log.UnhandledException(); + } + + // Count 500 as failed requests + if (httpContext.Response.StatusCode >= 500) + { + HostingEventSource.Log.RequestFailed(); + } } // Logging Scope is finshed with diff --git a/src/Hosting/Hosting/src/Internal/HostingEventSource.cs b/src/Hosting/Hosting/src/Internal/HostingEventSource.cs index 199f8aae85c7..2b8d188373d7 100644 --- a/src/Hosting/Hosting/src/Internal/HostingEventSource.cs +++ b/src/Hosting/Hosting/src/Internal/HostingEventSource.cs @@ -1,17 +1,37 @@ -// Copyright (c) .NET Foundation. All rights reserved. +// Copyright (c) .NET Foundation. All rights reserved. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. +using System; using System.Diagnostics.Tracing; using System.Runtime.CompilerServices; +using System.Threading; namespace Microsoft.AspNetCore.Hosting.Internal { - [EventSource(Name = "Microsoft-AspNetCore-Hosting")] public sealed class HostingEventSource : EventSource { public static readonly HostingEventSource Log = new HostingEventSource(); - private HostingEventSource() { } + private IncrementingPollingCounter _requestsPerSecondCounter; + private PollingCounter _totalRequestsCounter; + private PollingCounter _failedRequestsCounter; + private PollingCounter _currentRequestsCounter; + + private long _totalRequests; + private long _currentRequests; + private long _failedRequests; + + internal HostingEventSource() + : this("Microsoft.AspNetCore.Hosting") + { + + } + + // Used for testing + internal HostingEventSource(string eventSourceName) + : base(eventSourceName) + { + } // NOTE // - The 'Start' and 'Stop' suffixes on the following event names have special meaning in EventSource. They @@ -35,6 +55,8 @@ public void HostStop() [Event(3, Level = EventLevel.Informational)] public void RequestStart(string method, string path) { + Interlocked.Increment(ref _totalRequests); + Interlocked.Increment(ref _currentRequests); WriteEvent(3, method, path); } @@ -42,6 +64,7 @@ public void RequestStart(string method, string path) [Event(4, Level = EventLevel.Informational)] public void RequestStop() { + Interlocked.Decrement(ref _currentRequests); WriteEvent(4); } @@ -51,5 +74,40 @@ public void UnhandledException() { WriteEvent(5); } + + internal void RequestFailed() + { + Interlocked.Increment(ref _failedRequests); + } + + 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... + + _requestsPerSecondCounter ??= new IncrementingPollingCounter("requests-per-second", this, () => _totalRequests) + { + DisplayName = "Request Rate", + DisplayRateTimeScale = TimeSpan.FromSeconds(1) + }; + + _totalRequestsCounter ??= new PollingCounter("total-requests", this, () => _totalRequests) + { + DisplayName = "Total Requests", + }; + + _currentRequestsCounter ??= new PollingCounter("current-requests", this, () => _currentRequests) + { + DisplayName = "Current Requests" + }; + + _failedRequestsCounter ??= new PollingCounter("failed-requests", this, () => _failedRequests) + { + DisplayName = "Failed Requests" + }; + } + } } } diff --git a/src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs b/src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs new file mode 100644 index 000000000000..c51ab06bbed7 --- /dev/null +++ b/src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs @@ -0,0 +1,23 @@ +using System; +using System.Text; +using System.Threading; +using System.Threading.Tasks; + +namespace System.Collections.Generic +{ + internal static class AsyncEnumerableExtensions + { + public static async Task FirstOrDefault(this IAsyncEnumerator values, Func filter) + { + while (await values.MoveNextAsync()) + { + if (filter(values.Current)) + { + return values.Current; + } + } + + return default; + } + } +} diff --git a/src/Hosting/Hosting/test/Internal/HostingEventSourceTests.cs b/src/Hosting/Hosting/test/Internal/HostingEventSourceTests.cs index a32433720bf5..b3405a1e21cd 100644 --- a/src/Hosting/Hosting/test/Internal/HostingEventSourceTests.cs +++ b/src/Hosting/Hosting/test/Internal/HostingEventSourceTests.cs @@ -2,8 +2,11 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; +using System.Collections.Generic; using System.Diagnostics.Tracing; -using System.Reflection; +using System.Threading; +using System.Threading.Channels; +using System.Threading.Tasks; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Testing; using Microsoft.AspNetCore.Testing.xunit; @@ -17,16 +20,11 @@ public class HostingEventSourceTests public void MatchesNameAndGuid() { // Arrange & Act - var eventSourceType = typeof(WebHost).GetTypeInfo().Assembly.GetType( - "Microsoft.AspNetCore.Hosting.Internal.HostingEventSource", - throwOnError: true, - ignoreCase: false); + var eventSource = new HostingEventSource(); // Assert - Assert.NotNull(eventSourceType); - Assert.Equal("Microsoft-AspNetCore-Hosting", EventSource.GetName(eventSourceType)); - Assert.Equal(Guid.Parse("9e620d2a-55d4-5ade-deb7-c26046d245a8"), EventSource.GetGuid(eventSourceType)); - Assert.NotEmpty(EventSource.GenerateManifest(eventSourceType, "assemblyPathToIncludeInManifest")); + Assert.Equal("Microsoft.AspNetCore.Hosting", eventSource.Name); + Assert.Equal(Guid.Parse("9ded64a4-414c-5251-dcf7-1e4e20c15e70"), eventSource.Guid); } [Fact] @@ -35,7 +33,7 @@ public void HostStart() // Arrange var expectedEventId = 1; var eventListener = new TestEventListener(expectedEventId); - var hostingEventSource = HostingEventSource.Log; + var hostingEventSource = GetHostingEventSource(); eventListener.EnableEvents(hostingEventSource, EventLevel.Informational); // Act @@ -58,7 +56,7 @@ public void HostStop() // Arrange var expectedEventId = 2; var eventListener = new TestEventListener(expectedEventId); - var hostingEventSource = HostingEventSource.Log; + var hostingEventSource = GetHostingEventSource(); eventListener.EnableEvents(hostingEventSource, EventLevel.Informational); // Act @@ -115,7 +113,7 @@ public void RequestStart(DefaultHttpContext httpContext, string[] expected) // Arrange var expectedEventId = 3; var eventListener = new TestEventListener(expectedEventId); - var hostingEventSource = HostingEventSource.Log; + var hostingEventSource = GetHostingEventSource(); eventListener.EnableEvents(hostingEventSource, EventLevel.Informational); // Act @@ -144,7 +142,7 @@ public void RequestStop() // Arrange var expectedEventId = 4; var eventListener = new TestEventListener(expectedEventId); - var hostingEventSource = HostingEventSource.Log; + var hostingEventSource = GetHostingEventSource(); eventListener.EnableEvents(hostingEventSource, EventLevel.Informational); // Act @@ -166,7 +164,7 @@ public void UnhandledException() // Arrange var expectedEventId = 5; var eventListener = new TestEventListener(expectedEventId); - var hostingEventSource = HostingEventSource.Log; + var hostingEventSource = GetHostingEventSource(); eventListener.EnableEvents(hostingEventSource, EventLevel.Informational); // Act @@ -182,16 +180,65 @@ public void UnhandledException() Assert.Empty(eventData.Payload); } - private static Exception GetException() + [Fact] + public async Task VerifyCountersFireWithCorrectValues() { - try - { - throw new InvalidOperationException("An invalid operation has occurred"); - } - catch (Exception ex) - { - return ex; - } + // Arrange + var eventListener = new CounterListener(new[] { + "requests-per-second", + "total-requests", + "current-requests", + "failed-requests" + }); + + var hostingEventSource = GetHostingEventSource(); + + using var timeoutTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(5)); + + var rpsValues = eventListener.GetCounterValues("requests-per-second", timeoutTokenSource.Token).GetAsyncEnumerator(); + var totalRequestValues = eventListener.GetCounterValues("total-requests", timeoutTokenSource.Token).GetAsyncEnumerator(); + var currentRequestValues = eventListener.GetCounterValues("current-requests", timeoutTokenSource.Token).GetAsyncEnumerator(); + var failedRequestValues = eventListener.GetCounterValues("failed-requests", timeoutTokenSource.Token).GetAsyncEnumerator(); + + eventListener.EnableEvents(hostingEventSource, EventLevel.Informational, EventKeywords.None, + new Dictionary + { + { "EventCounterIntervalSec", "1" } + }); + + hostingEventSource.RequestStart("GET", "/"); + + Assert.Equal(1, await totalRequestValues.FirstOrDefault(v => v == 1)); + Assert.Equal(1, await rpsValues.FirstOrDefault(v => v == 1)); + Assert.Equal(1, await currentRequestValues.FirstOrDefault(v => v == 1)); + Assert.Equal(0, await failedRequestValues.FirstOrDefault(v => v == 0)); + + hostingEventSource.RequestStop(); + + Assert.Equal(1, await totalRequestValues.FirstOrDefault(v => v == 1)); + Assert.Equal(0, await rpsValues.FirstOrDefault(v => v == 0)); + Assert.Equal(0, await currentRequestValues.FirstOrDefault(v => v == 0)); + Assert.Equal(0, await failedRequestValues.FirstOrDefault(v => v == 0)); + + hostingEventSource.RequestStart("POST", "/"); + + Assert.Equal(2, await totalRequestValues.FirstOrDefault(v => v == 2)); + Assert.Equal(1, await rpsValues.FirstOrDefault(v => v == 1)); + Assert.Equal(1, await currentRequestValues.FirstOrDefault(v => v == 1)); + Assert.Equal(0, await failedRequestValues.FirstOrDefault(v => v == 0)); + + hostingEventSource.RequestFailed(); + hostingEventSource.RequestStop(); + + Assert.Equal(2, await totalRequestValues.FirstOrDefault(v => v == 2)); + Assert.Equal(0, await rpsValues.FirstOrDefault(v => v == 0)); + Assert.Equal(0, await currentRequestValues.FirstOrDefault(v => v == 0)); + Assert.Equal(1, await failedRequestValues.FirstOrDefault(v => v == 1)); + } + + private static HostingEventSource GetHostingEventSource() + { + return new HostingEventSource(Guid.NewGuid().ToString()); } private class TestEventListener : EventListener @@ -216,5 +263,36 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData) } } } + + private class CounterListener : EventListener + { + private readonly Dictionary> _counters = new Dictionary>(); + + public CounterListener(string[] counterNames) + { + foreach (var item in counterNames) + { + _counters[item] = Channel.CreateUnbounded(); + } + } + + public IAsyncEnumerable GetCounterValues(string counterName, CancellationToken cancellationToken = default) + { + return _counters[counterName].Reader.ReadAllAsync(cancellationToken); + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + if (eventData.EventName == "EventCounters") + { + var payload = (IDictionary)eventData.Payload[0]; + var counter = (string)payload["Name"]; + payload.TryGetValue("Increment", out var increment); + payload.TryGetValue("Mean", out var mean); + var writer = _counters[counter].Writer; + writer.TryWrite((double)(increment ?? mean)); + } + } + } } } diff --git a/src/Hosting/Hosting/test/Microsoft.AspNetCore.Hosting.Tests.csproj b/src/Hosting/Hosting/test/Microsoft.AspNetCore.Hosting.Tests.csproj index cfdfd4ed0c4f..10635b28599c 100644 --- a/src/Hosting/Hosting/test/Microsoft.AspNetCore.Hosting.Tests.csproj +++ b/src/Hosting/Hosting/test/Microsoft.AspNetCore.Hosting.Tests.csproj @@ -19,6 +19,7 @@ +