Wrap EventSource calls with IsEnabled (#2052)

grpc · Feb 21, 2023 · a456d47 · a456d47
1 parent 8471823
commit a456d47
Show file tree

Hide file tree

Showing 10 changed files with 132 additions and 34 deletions.
diff --git a/src/Grpc.AspNetCore.Server/Internal/GrpcEventSource.cs b/src/Grpc.AspNetCore.Server/Internal/GrpcEventSource.cs
@@ -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();
 
@@ -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);
 
@@ -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);
@@ -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);
@@ -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);
@@ -105,6 +114,8 @@ public void CallDeadlineExceeded()
     [Event(eventId: 5, Level = EventLevel.Verbose)]
     public void MessageSent()
     {
+        AssertEventSourceEnabled();
+
         Interlocked.Increment(ref _messageSent);
 
         WriteEvent(5);
@@ -114,6 +125,8 @@ public void MessageSent()
     [Event(eventId: 6, Level = EventLevel.Verbose)]
     public void MessageReceived()
     {
+        AssertEventSourceEnabled();
+
         Interlocked.Increment(ref _messageReceived);
 
         WriteEvent(6);
@@ -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)

diff --git a/src/Grpc.AspNetCore.Server/Internal/HttpContextServerCallContext.cs b/src/Grpc.AspNetCore.Server/Internal/HttpContextServerCallContext.cs
@@ -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; }
@@ -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();
 
@@ -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");
 

diff --git a/src/Grpc.AspNetCore.Server/Internal/PipeExtensions.cs b/src/Grpc.AspNetCore.Server/Internal/PipeExtensions.cs
@@ -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)
         {
@@ -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)
         {
@@ -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
@@ -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;
                         }

diff --git a/src/Grpc.AspNetCore.Server/Internal/ServerCallHandlerFactory.cs b/src/Grpc.AspNetCore.Server/Internal/ServerCallHandlerFactory.cs
@@ -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;
         };
@@ -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;
         };

diff --git a/src/Grpc.Net.Client/Internal/GrpcCall.cs b/src/Grpc.Net.Client/Internal/GrpcCall.cs
@@ -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);
 
@@ -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
@@ -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)
         {
@@ -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;

diff --git a/src/Grpc.Net.Client/Internal/GrpcEventSource.cs b/src/Grpc.Net.Client/Internal/GrpcEventSource.cs
@@ -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();
 
@@ -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);
 
@@ -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);
@@ -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);
@@ -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);
@@ -105,6 +114,8 @@ public void CallDeadlineExceeded()
     [Event(eventId: 5, Level = EventLevel.Verbose)]
     public void MessageSent()
     {
+        AssertEventSourceEnabled();
+
         Interlocked.Increment(ref _messageSent);
 
         WriteEvent(5);
@@ -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)

diff --git a/src/Grpc.Net.Client/Internal/Http/PushUnaryContent.cs b/src/Grpc.Net.Client/Internal/Http/PushUnaryContent.cs
@@ -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;
         }
 
@@ -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)