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.

Sign up for GitHub

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

Wrap EventSource calls with IsEnabled #2052

Merged
merged 6 commits into from
Feb 21, 2023
Merged

Wrap EventSource calls with IsEnabled #2052

Show file tree
Hide file tree
Changes from 5 commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
3b4fbe7
Wrap EventSource calls with IsEnabled
JamesNK Feb 21, 2023
79d246b
Remove field
JamesNK Feb 21, 2023
c6ffe9d
Client
JamesNK Feb 21, 2023
cec3d67
Fix
JamesNK Feb 21, 2023
0a14bc0
Assert enabled
JamesNK Feb 21, 2023
00b7ed4
Seal event sources
JamesNK Feb 21, 2023
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
22 changes: 22 additions & 0 deletions src/Grpc.AspNetCore.Server/Internal/GrpcEventSource.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@

#endregion

using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.Runtime.CompilerServices;
using Grpc.Core;
Expand Down Expand Up @@ -68,6 +69,8 @@ internal GrpcEventSource(string eventSourceName)
[Event(eventId: 1, Level = EventLevel.Verbose)]
public void CallStart(string method)
{
AssertEventSourceEnabled();

Interlocked.Increment(ref _totalCalls);
Interlocked.Increment(ref _currentCalls);

Expand All @@ -78,6 +81,8 @@ public void CallStart(string method)
[Event(eventId: 2, Level = EventLevel.Verbose)]
public void CallStop()
{
AssertEventSourceEnabled();

Interlocked.Decrement(ref _currentCalls);

WriteEvent(2);
Expand All @@ -87,6 +92,8 @@ public void CallStop()
[Event(eventId: 3, Level = EventLevel.Error)]
public void CallFailed(StatusCode statusCode)
{
AssertEventSourceEnabled();

Interlocked.Increment(ref _callsFailed);

WriteEvent(3, (int)statusCode);
Expand All @@ -96,6 +103,8 @@ public void CallFailed(StatusCode statusCode)
[Event(eventId: 4, Level = EventLevel.Error)]
public void CallDeadlineExceeded()
{
AssertEventSourceEnabled();

Interlocked.Increment(ref _callsDeadlineExceeded);

WriteEvent(4);
Expand All @@ -105,6 +114,8 @@ public void CallDeadlineExceeded()
[Event(eventId: 5, Level = EventLevel.Verbose)]
public void MessageSent()
{
AssertEventSourceEnabled();

Interlocked.Increment(ref _messageSent);

WriteEvent(5);
Expand All @@ -114,6 +125,8 @@ public void MessageSent()
[Event(eventId: 6, Level = EventLevel.Verbose)]
public void MessageReceived()
{
AssertEventSourceEnabled();

Interlocked.Increment(ref _messageReceived);

WriteEvent(6);
Expand All @@ -123,11 +136,20 @@ public void MessageReceived()
[Event(eventId: 7, Level = EventLevel.Verbose)]
public void CallUnimplemented(string method)
{
AssertEventSourceEnabled();

Interlocked.Increment(ref _callsUnimplemented);

WriteEvent(7, method);
}

[Conditional("DEBUG")]
[NonEvent]
private void AssertEventSourceEnabled()
{
Debug.Assert(IsEnabled(), "Event source should be enabled.");
}

protected override void OnEventCommand(EventCommandEventArgs command)
{
if (command.Command == EventCommand.Enable)
Expand Down
20 changes: 16 additions & 4 deletions src/Grpc.AspNetCore.Server/Internal/HttpContextServerCallContext.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -297,9 +297,15 @@ private void LogCallEnd()
}
if (_status.StatusCode != StatusCode.OK)
{
GrpcEventSource.Log.CallFailed(_status.StatusCode);
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.CallFailed(_status.StatusCode);
}
}
if (GrpcEventSource.Log.IsEnabled())
Copy link
Contributor

Choose a reason for hiding this comment

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

since you're always going to test enabled here, is it worth pulling this into a local around L297, to avoid multiple checks?

Copy link
Member Author

@JamesNK JamesNK Feb 21, 2023 •
edited
Loading

Choose a reason for hiding this comment

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

IsEnabled implementation directly returns a field: https://github.com/dotnet/runtime/blob/463954dbc728470fb21a097188fc3dae91f6cbe4/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs#L256-L263

IsEnabled is so cheap (probably inlined) that I don't think it's worth it.

{
GrpcEventSource.Log.CallStop();
}
GrpcEventSource.Log.CallStop();
}

protected override WriteOptions? WriteOptionsCore { get; set; }
Expand Down Expand Up @@ -379,7 +385,10 @@ public void Initialize(ISystemClock? clock = null)
_activity.AddTag(GrpcServerConstants.ActivityMethodTag, MethodCore);
}

GrpcEventSource.Log.CallStart(MethodCore);
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.CallStart(MethodCore);
}

var timeout = GetTimeout();

Expand Down Expand Up @@ -459,7 +468,10 @@ private TimeSpan GetTimeout()
internal async Task DeadlineExceededAsync()
{
GrpcServerLog.DeadlineExceeded(Logger, GetTimeout());
GrpcEventSource.Log.CallDeadlineExceeded();
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.CallDeadlineExceeded();
}

var status = new Status(StatusCode.DeadlineExceeded, "Deadline Exceeded");

Expand Down
22 changes: 16 additions & 6 deletions src/Grpc.AspNetCore.Server/Internal/PipeExtensions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -65,7 +65,10 @@ public static async Task WriteSingleMessageAsync<TResponse>(this PipeWriter pipe
serializer(response, serializationContext);

GrpcServerLog.MessageSent(serverCallContext.Logger);
GrpcEventSource.Log.MessageSent();
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.MessageSent();
}
}
catch (Exception ex)
{
Expand Down Expand Up @@ -112,7 +115,10 @@ public static async Task WriteStreamedMessageAsync<TResponse>(this PipeWriter pi
}

GrpcServerLog.MessageSent(serverCallContext.Logger);
GrpcEventSource.Log.MessageSent();
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.MessageSent();
}
}
catch (Exception ex)
{
Expand Down Expand Up @@ -226,8 +232,10 @@ public static async ValueTask<T> ReadSingleMessageAsync<T>(this PipeReader input
serverCallContext.DeserializationContext.SetPayload(null);

GrpcServerLog.ReceivedMessage(logger);

GrpcEventSource.Log.MessageReceived();
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.MessageReceived();
}

// Store the request
// Need to verify the request completes with no additional data
Expand Down Expand Up @@ -318,8 +326,10 @@ public static async ValueTask<T> ReadSingleMessageAsync<T>(this PipeReader input
serverCallContext.DeserializationContext.SetPayload(null);

GrpcServerLog.ReceivedMessage(logger);

GrpcEventSource.Log.MessageReceived();
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.MessageReceived();
}

return request;
}
Expand Down
12 changes: 8 additions & 4 deletions src/Grpc.AspNetCore.Server/Internal/ServerCallHandlerFactory.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -118,8 +118,10 @@ public RequestDelegate CreateUnimplementedMethod()

var unimplementedMethod = httpContext.Request.RouteValues["unimplementedMethod"]?.ToString() ?? "<unknown>";
Log.MethodUnimplemented(logger, unimplementedMethod);
GrpcEventSource.Log.CallUnimplemented(httpContext.Request.Path.Value!);

if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.CallUnimplemented(httpContext.Request.Path.Value!);
}
GrpcProtocolHelpers.SetStatus(GrpcProtocolHelpers.GetTrailersDestination(httpContext.Response), new Status(StatusCode.Unimplemented, "Method is unimplemented."));
return Task.CompletedTask;
};
Expand All @@ -146,8 +148,10 @@ public RequestDelegate CreateUnimplementedService()

var unimplementedService = httpContext.Request.RouteValues["unimplementedService"]?.ToString() ?? "<unknown>";
Log.ServiceUnimplemented(logger, unimplementedService);
GrpcEventSource.Log.CallUnimplemented(httpContext.Request.Path.Value!);

if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.CallUnimplemented(httpContext.Request.Path.Value!);
}
GrpcProtocolHelpers.SetStatus(GrpcProtocolHelpers.GetTrailersDestination(httpContext.Response), new Status(StatusCode.Unimplemented, "Service is unimplemented."));
return Task.CompletedTask;
};
Expand Down
34 changes: 24 additions & 10 deletions src/Grpc.Net.Client/Internal/GrpcCall.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -585,8 +585,10 @@ private async Task RunCall(HttpRequestMessage request, TimeSpan? timeout)
}
else
{
GrpcEventSource.Log.MessageReceived();

if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.MessageReceived();
}
FinishResponseAndCleanUp(status.Value);
finished = FinishCall(request, diagnosticSourceEnabled, activity, status.Value);

Expand Down Expand Up @@ -809,7 +811,10 @@ public Exception CreateFailureStatusException(Status status)
private (bool diagnosticSourceEnabled, Activity? activity) InitializeCall(HttpRequestMessage request, TimeSpan? timeout)
{
GrpcCallLog.StartingCall(Logger, Method.Type, request.RequestUri!);
GrpcEventSource.Log.CallStart(Method.FullName);
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.CallStart(Method.FullName);
}

// Deadline will cancel the call CTS.
// Only exceed deadline/start timer after reader/writer have been created, otherwise deadline will cancel
Expand Down Expand Up @@ -882,19 +887,26 @@ private bool FinishCall(HttpRequestMessage request, bool diagnosticSourceEnabled
if (IsDeadlineExceededUnsynchronized())
{
GrpcCallLog.DeadlineExceeded(Logger);
GrpcEventSource.Log.CallDeadlineExceeded();

if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.CallDeadlineExceeded();
}
_deadline = DateTime.MaxValue;
}
}
}

GrpcCallLog.GrpcStatusError(Logger, status.StatusCode, status.Detail);
GrpcEventSource.Log.CallFailed(status.StatusCode);
if (GrpcEventSource.Log.IsEnabled())
Copy link
Contributor

Choose a reason for hiding this comment

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

ditto hoist covering 3 in a row here

{
GrpcEventSource.Log.CallFailed(status.StatusCode);
}
}
GrpcCallLog.FinishedCall(Logger);
GrpcEventSource.Log.CallStop();

if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.CallStop();
}
// Activity needs to be stopped in the same execution context it was started
if (activity != null)
{
Expand Down Expand Up @@ -1096,8 +1108,10 @@ private void DeadlineExceeded()
Debug.Assert(Monitor.IsEntered(this));

GrpcCallLog.DeadlineExceeded(Logger);
GrpcEventSource.Log.CallDeadlineExceeded();

if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.CallDeadlineExceeded();
}
// Set _deadline to DateTime.MaxValue to signal that deadline has been exceeded.
// This prevents duplicate logging and cancellation.
_deadline = DateTime.MaxValue;
Expand Down
20 changes: 20 additions & 0 deletions src/Grpc.Net.Client/Internal/GrpcEventSource.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@

#endregion

using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.Runtime.CompilerServices;
using Grpc.Core;
Expand Down Expand Up @@ -68,6 +69,8 @@ internal void ResetCounters()
[Event(eventId: 1, Level = EventLevel.Verbose)]
public void CallStart(string method)
{
AssertEventSourceEnabled();

Interlocked.Increment(ref _totalCalls);
Interlocked.Increment(ref _currentCalls);

Expand All @@ -78,6 +81,8 @@ public void CallStart(string method)
[Event(eventId: 2, Level = EventLevel.Verbose)]
public void CallStop()
{
AssertEventSourceEnabled();

Interlocked.Decrement(ref _currentCalls);

WriteEvent(2);
Expand All @@ -87,6 +92,8 @@ public void CallStop()
[Event(eventId: 3, Level = EventLevel.Error)]
public void CallFailed(StatusCode statusCode)
{
AssertEventSourceEnabled();

Interlocked.Increment(ref _callsFailed);

WriteEvent(3, (int)statusCode);
Expand All @@ -96,6 +103,8 @@ public void CallFailed(StatusCode statusCode)
[Event(eventId: 4, Level = EventLevel.Error)]
public void CallDeadlineExceeded()
{
AssertEventSourceEnabled();

Interlocked.Increment(ref _callsDeadlineExceeded);

WriteEvent(4);
Expand All @@ -105,6 +114,8 @@ public void CallDeadlineExceeded()
[Event(eventId: 5, Level = EventLevel.Verbose)]
public void MessageSent()
{
AssertEventSourceEnabled();

Interlocked.Increment(ref _messageSent);

WriteEvent(5);
Expand All @@ -114,11 +125,20 @@ public void MessageSent()
[Event(eventId: 6, Level = EventLevel.Verbose)]
public void MessageReceived()
{
AssertEventSourceEnabled();

Interlocked.Increment(ref _messageReceived);

WriteEvent(6);
}

[Conditional("DEBUG")]
[NonEvent]
private void AssertEventSourceEnabled()
{
Debug.Assert(IsEnabled(), "Event source should be enabled.");
}

protected override void OnEventCommand(EventCommandEventArgs command)
{
if (command.Command == EventCommand.Enable)
Expand Down
10 changes: 8 additions & 2 deletions src/Grpc.Net.Client/Internal/Http/PushUnaryContent.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -47,7 +47,10 @@ protected override Task SerializeToStreamAsync(Stream stream, TransportContext?
#pragma warning restore CA2012 // Use ValueTasks correctly
if (writeMessageTask.IsCompletedSuccessfully())
{
GrpcEventSource.Log.MessageSent();
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.MessageSent();
}
return Task.CompletedTask;
}

Expand All @@ -57,7 +60,10 @@ protected override Task SerializeToStreamAsync(Stream stream, TransportContext?
private static async Task WriteMessageCore(ValueTask writeMessageTask)
{
await writeMessageTask.ConfigureAwait(false);
GrpcEventSource.Log.MessageSent();
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.MessageSent();
}
}

protected override bool TryComputeLength(out long length)
Expand Down
10 changes: 8 additions & 2 deletions src/Grpc.Net.Client/Internal/Http/WinHttpUnaryContent.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -54,7 +54,10 @@ protected override Task SerializeToStreamAsync(Stream stream, TransportContext?
#pragma warning restore CA2012 // Use ValueTasks correctly
if (writeMessageTask.IsCompletedSuccessfully())
{
GrpcEventSource.Log.MessageSent();
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.MessageSent();
}
return Task.CompletedTask;
}

Expand All @@ -64,7 +67,10 @@ protected override Task SerializeToStreamAsync(Stream stream, TransportContext?
private static async Task WriteMessageCore(ValueTask writeMessageTask)
{
await writeMessageTask.ConfigureAwait(false);
GrpcEventSource.Log.MessageSent();
if (GrpcEventSource.Log.IsEnabled())
{
GrpcEventSource.Log.MessageSent();
}
}

protected override bool TryComputeLength(out long length)
Expand Down
Loading