Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Added basic event counters for hosting #10884

Merged
merged 1 commit into from
Jun 5, 2019
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -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() { }
Expand All @@ -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)]
Expand Down
15 changes: 12 additions & 3 deletions src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

First time I'm seeing this code, so I know this is already "how it's been" but EventLog != EventSource so this name struck me as odd. I backtracked to where it's initialized and confirmed it was right but the naming seems off.

It's internal so a rename would be safe if you want to be a little more consistent... 🤷‍♂

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's public unfortunately. That's why I never renamed it. Can do it later, I think we should make all this stuff internal anyways.

{
// Non-inline
HostingEventSource.Log.UnhandledException();
if (exception != null)
{
// Non-inline
HostingEventSource.Log.UnhandledException();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there a reason we don't put exception details in the message?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  1. This isn't new code
  2. You can't pass the exception itself (that isn't supported in EventSource writes), you could pass the text though.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  1. This isn't new code

Yes, I am aware.

}

// Count 500 as failed requests
if (httpContext.Response.StatusCode >= 500)
{
HostingEventSource.Log.RequestFailed();
}
}

// Logging Scope is finshed with
Expand Down
64 changes: 61 additions & 3 deletions src/Hosting/Hosting/src/Internal/HostingEventSource.cs
Original file line number Diff line number Diff line change
@@ -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
Expand All @@ -35,13 +55,16 @@ public void HostStop()
[Event(3, Level = EventLevel.Informational)]
public void RequestStart(string method, string path)
{
Interlocked.Increment(ref _totalRequests);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is cool stuff. Is it worth investigating using ThreadLocal<int> and summing the .Values in the counter delegate? That would save a bit of time in the hot path by not locking the processor cores. Though I'm probably optimizing a bit prematurely ;)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yea I had a version with that though I'll do it after we measure this which I haven't since it involves turning on logging/eventsource which has other overhead. We also still need to interlocked.increment/decrement current requests which also made me go meh.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Measure first is best

Interlocked.Increment(ref _currentRequests);
WriteEvent(3, method, path);
}

[MethodImpl(MethodImplOptions.NoInlining)]
[Event(4, Level = EventLevel.Informational)]
public void RequestStop()
{
Interlocked.Decrement(ref _currentRequests);
WriteEvent(4);
}

Expand All @@ -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)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about Disable?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

From below this line:

// They aren't disabled afterwards...

Do you have more context on why?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's racy to disable counters and dispose and re-create them, that would need to be synchronized. The other way to turn it off is to stop pumping the data (that can be done via a different set of arguments), which turns the timer off so allocating the counter itself is fine.

{
// 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"
};
}
}
}
}
23 changes: 23 additions & 0 deletions src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs
Original file line number Diff line number Diff line change
@@ -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<T> FirstOrDefault<T>(this IAsyncEnumerator<T> values, Func<T, bool> filter)
{
while (await values.MoveNextAsync())
{
if (filter(values.Current))
{
return values.Current;
}
}

return default;
}
}
}
124 changes: 101 additions & 23 deletions src/Hosting/Hosting/test/Internal/HostingEventSourceTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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]
Expand All @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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<string, string>
{
{ "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
Expand All @@ -216,5 +263,36 @@ protected override void OnEventWritten(EventWrittenEventArgs eventData)
}
}
}

private class CounterListener : EventListener
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This could be useful for testing all counters. We'll have to remember this when adding other counters and promote this to src/Shared (or you could just do it now...)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep. I have a thread with corefx about how to test these things. As I add more counters I'll move it to shared.

{
private readonly Dictionary<string, Channel<double>> _counters = new Dictionary<string, Channel<double>>();

public CounterListener(string[] counterNames)
{
foreach (var item in counterNames)
{
_counters[item] = Channel.CreateUnbounded<double>();
}
}

public IAsyncEnumerable<double> 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<string, object>)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));
}
}
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@
<Reference Include="Microsoft.Extensions.Hosting" />
<Reference Include="Microsoft.Extensions.Logging.Testing" />
<Reference Include="Microsoft.Extensions.Options" />
<Reference Include="System.Threading.Channels" />
</ItemGroup>

</Project>