Skip to content

Commit

Permalink
Wrap EventSource calls with IsEnabled (#2052)
Browse files Browse the repository at this point in the history
  • Loading branch information
@JamesNK
JamesNK authored Feb 21, 2023
1 parent 8471823 commit a456d47
Show file tree
Hide file tree
Showing 10 changed files with 132 additions and 34 deletions.
24 changes: 23 additions & 1 deletion src/Grpc.AspNetCore.Server/Internal/GrpcEventSource.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,13 +16,14 @@

#endregion

using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.Runtime.CompilerServices;
using Grpc.Core;

namespace Grpc.AspNetCore.Server.Internal;

internal class GrpcEventSource : EventSource
internal sealed class GrpcEventSource : EventSource
{
public static readonly GrpcEventSource Log = new GrpcEventSource();

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
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())
{
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
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
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
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())
{
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
22 changes: 21 additions & 1 deletion src/Grpc.Net.Client/Internal/GrpcEventSource.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,13 +16,14 @@

#endregion

using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.Runtime.CompilerServices;
using Grpc.Core;

namespace Grpc.Net.Client.Internal;

internal class GrpcEventSource : EventSource
internal sealed class GrpcEventSource : EventSource
{
public static readonly GrpcEventSource Log = new GrpcEventSource();

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
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
Loading

0 comments on commit a456d47

Please sign in to comment.