diff --git a/src/Orleans.Runtime/Activation/ActivationDataActivatorProvider.cs b/src/Orleans.Runtime/Activation/ActivationDataActivatorProvider.cs index 7a58e8726d1..3dfda5e57f6 100644 --- a/src/Orleans.Runtime/Activation/ActivationDataActivatorProvider.cs +++ b/src/Orleans.Runtime/Activation/ActivationDataActivatorProvider.cs @@ -8,7 +8,7 @@ namespace Orleans.Runtime { - internal class ActivationDataActivatorProvider : IGrainContextActivatorProvider + internal partial class ActivationDataActivatorProvider : IGrainContextActivatorProvider { private readonly IServiceProvider _serviceProvider; private readonly IActivationWorkingSet _activationWorkingSet; @@ -81,7 +81,7 @@ public bool TryGet(GrainType grainType, out IGrainContextActivator activator) return true; } - private class ActivationDataActivator : IGrainContextActivator + private partial class ActivationDataActivator : IGrainContextActivator { private readonly ILogger _workItemGroupLogger; private readonly ILogger _activationTaskSchedulerLogger; @@ -133,7 +133,7 @@ public IGrainContext CreateContext(GrainAddress activationAddress) } catch (Exception exception) { - _grainLogger.LogError(exception, "Failed to construct grain '{GrainId}'.", activationAddress.GrainId); + LogErrorFailedToConstructGrain(_grainLogger, exception, activationAddress.GrainId); throw; } finally @@ -143,6 +143,12 @@ public IGrainContext CreateContext(GrainAddress activationAddress) return context; } + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Failed to construct grain '{GrainId}'." + )] + private static partial void LogErrorFailedToConstructGrain(ILogger logger, Exception exception, GrainId grainId); } } @@ -159,4 +165,4 @@ public StatelessWorkerActivator(GrainTypeSharedContext sharedContext, IGrainCont public IGrainContext CreateContext(GrainAddress address) => new StatelessWorkerGrainContext(address, _sharedContext, _innerActivator); } -} \ No newline at end of file +} diff --git a/src/Orleans.Runtime/Cancellation/GrainCallCancellationManager.cs b/src/Orleans.Runtime/Cancellation/GrainCallCancellationManager.cs index 30a8dc0d494..2b4917a6ced 100644 --- a/src/Orleans.Runtime/Cancellation/GrainCallCancellationManager.cs +++ b/src/Orleans.Runtime/Cancellation/GrainCallCancellationManager.cs @@ -41,7 +41,7 @@ internal struct GrainCallCancellationRequest(GrainId targetGrainId, GrainId sour /// /// Cancels grain calls issued to remote hosts and handles cancellation requests from other hosts. /// -internal class GrainCallCancellationManager : SystemTarget, IGrainCallCancellationManagerSystemTarget, IGrainCallCancellationManager, ILifecycleParticipant +internal partial class GrainCallCancellationManager : SystemTarget, IGrainCallCancellationManagerSystemTarget, IGrainCallCancellationManager, ILifecycleParticipant { private const int MaxBatchSize = 1_000; private readonly ConcurrentDictionary WorkItemChannel, CancellationTokenSource Cts)> _workers = new(); @@ -123,10 +123,7 @@ private async Task ProcessMembershipUpdates() try { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Monitoring cluster membership updates"); - } + LogDebugMonitoringClusterMembershipUpdates(_logger); var previousSnapshot = _clusterMembershipService.CurrentSnapshot; await foreach (var snapshot in _clusterMembershipService.MembershipUpdates.WithCancellation(_shuttingDownCts.Token)) @@ -153,16 +150,13 @@ private async Task ProcessMembershipUpdates() } catch (Exception exception) { - _logger.LogError(exception, "Error processing cluster membership updates"); + LogErrorProcessingClusterMembershipUpdates(_logger, exception); } } } finally { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("No longer monitoring cluster membership updates"); - } + LogDebugNoLongerMonitoringClusterMembershipUpdates(_logger); } } @@ -173,10 +167,7 @@ private async Task PumpCancellationQueue(SiloAddress targetSilo, Channel(Constants.CancellationManagerType, targetSilo); await Task.Yield(); - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Starting cancellation worker for target silo {SiloAddress}", targetSilo); - } + LogDebugStartingCancellationWorker(_logger, targetSilo); var batch = new List(); var reader = workItems.Reader; @@ -193,10 +184,7 @@ private async Task PumpCancellationQueue(SiloAddress targetSilo, Channel.Participate(ISiloLifecycle lifecycle) ct => this.RunOrQueueTask(() => StartAsync(ct)), ct => this.RunOrQueueTask(() => StopAsync(ct))); } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Monitoring cluster membership updates" + )] + private static partial void LogDebugMonitoringClusterMembershipUpdates(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Starting cancellation worker for target silo {SiloAddress}" + )] + private static partial void LogDebugStartingCancellationWorker(ILogger logger, SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Cancelled {Count} requests to target silo {SiloAddress}" + )] + private static partial void LogDebugCancelledRequests(ILogger logger, int count, SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error while cancelling {Count} requests to {SiloAddress}" + )] + private static partial void LogErrorCancellingRequests(ILogger logger, Exception exception, int count, SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Exiting cancellation worker for target silo {SiloAddress}" + )] + private static partial void LogDebugExitingCancellationWorker(ILogger logger, SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Target silo '{SiloAddress}' is no longer active, so this cancellation activation worker is terminating" + )] + private static partial void LogDebugTargetSiloNoLongerActive(ILogger logger, SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Error signaling shutdown." + )] + private static partial void LogWarningErrorSignalingShutdown(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "No longer monitoring cluster membership updates" + )] + private static partial void LogDebugNoLongerMonitoringClusterMembershipUpdates(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error processing cluster membership updates" + )] + private static partial void LogErrorProcessingClusterMembershipUpdates(ILogger logger, Exception exception); } diff --git a/src/Orleans.Runtime/Catalog/ActivationData.cs b/src/Orleans.Runtime/Catalog/ActivationData.cs index 15f5aa4a4eb..516a052a50d 100644 --- a/src/Orleans.Runtime/Catalog/ActivationData.cs +++ b/src/Orleans.Runtime/Catalog/ActivationData.cs @@ -1973,11 +1973,17 @@ void CancelRequest(IInvokable request) } catch (Exception exception) { - Shared.Logger.LogWarning(exception, "One or more cancellation callbacks failed."); + LogErrorCancellationCallbackFailed(Shared.Logger, exception); } } } + [LoggerMessage( + Level = LogLevel.Warning, + Message = "One or more cancellation callbacks failed." + )] + private static partial void LogErrorCancellationCallbackFailed(ILogger logger, Exception exception); + #endregion /// diff --git a/src/Orleans.Runtime/GrainDirectory/DistributedGrainDirectory.cs b/src/Orleans.Runtime/GrainDirectory/DistributedGrainDirectory.cs index 9bb7e2513e8..ed38df63f0b 100644 --- a/src/Orleans.Runtime/GrainDirectory/DistributedGrainDirectory.cs +++ b/src/Orleans.Runtime/GrainDirectory/DistributedGrainDirectory.cs @@ -227,7 +227,7 @@ public async ValueTask>> GetRegisteredActivations(M var stopwatch = CoarseStopwatch.StartNew(); using var cts = new CancellationTokenSource(); cts.Cancel(); - + foreach (var (grainId, activation) in _localActivations) { var directory = GetGrainDirectory(activation, _grainDirectoryResolver!); diff --git a/src/Orleans.Runtime/MembershipService/SiloMetadata/SiloMetadaCache.cs b/src/Orleans.Runtime/MembershipService/SiloMetadata/SiloMetadaCache.cs index b14bba38aca..4270a464478 100644 --- a/src/Orleans.Runtime/MembershipService/SiloMetadata/SiloMetadaCache.cs +++ b/src/Orleans.Runtime/MembershipService/SiloMetadata/SiloMetadaCache.cs @@ -11,7 +11,7 @@ #nullable enable namespace Orleans.Runtime.MembershipService.SiloMetadata; -internal class SiloMetadataCache( +internal partial class SiloMetadataCache( ISiloMetadataClient siloMetadataClient, MembershipTableManager membershipTableManager, IOptions clusterMembershipOptions, @@ -29,7 +29,7 @@ void ILifecycleParticipant.Participate(ISiloLifecycle lifecycle) Task OnStart(CancellationToken _) { // This gives time for the cluster to be voted Dead and for membership updates to propagate that out - negativeCachePeriod = clusterMembershipOptions.Value.ProbeTimeout * clusterMembershipOptions.Value.NumMissedProbesLimit + negativeCachePeriod = clusterMembershipOptions.Value.ProbeTimeout * clusterMembershipOptions.Value.NumMissedProbesLimit + (2 * clusterMembershipOptions.Value.TableRefreshTimeout); task = Task.Run(() => this.ProcessMembershipUpdates(_cts.Token)); return Task.CompletedTask; @@ -55,7 +55,7 @@ private async Task ProcessMembershipUpdates(CancellationToken ct) { try { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("Starting to process membership updates."); + LogDebugStartProcessingMembershipUpdates(logger); await foreach (var update in membershipTableManager.MembershipTableUpdates.WithCancellation(ct)) { // Add entries for members that aren't already in the cache @@ -80,7 +80,7 @@ private async Task ProcessMembershipUpdates(CancellationToken ct) catch(Exception exception) { _negativeCache.TryAdd(membershipEntry.Key, now + negativeCachePeriod); - logger.LogError(exception, "Error fetching metadata for silo {Silo}", membershipEntry.Key); + LogErrorFetchingSiloMetadata(logger, exception, membershipEntry.Key); } } } @@ -111,11 +111,11 @@ private async Task ProcessMembershipUpdates(CancellationToken ct) } catch (Exception exception) { - logger.LogError(exception, "Error processing membership updates"); + LogErrorProcessingMembershipUpdates(logger, exception); } finally { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("Stopping membership update processor"); + LogDebugStoppingMembershipProcessor(logger); } } @@ -124,5 +124,25 @@ private async Task ProcessMembershipUpdates(CancellationToken ct) public void SetMetadata(SiloAddress siloAddress, SiloMetadata metadata) => _metadata.TryAdd(siloAddress, metadata); public void Dispose() => _cts.Cancel(); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Starting to process membership updates.")] + private static partial void LogDebugStartProcessingMembershipUpdates(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error fetching metadata for silo {Silo}")] + private static partial void LogErrorFetchingSiloMetadata(ILogger logger, Exception exception, SiloAddress silo); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error processing membership updates")] + private static partial void LogErrorProcessingMembershipUpdates(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Stopping membership update processor")] + private static partial void LogDebugStoppingMembershipProcessor(ILogger logger); } diff --git a/src/Orleans.Runtime/Messaging/Gateway.cs b/src/Orleans.Runtime/Messaging/Gateway.cs index cca548b652a..c6518185ae5 100644 --- a/src/Orleans.Runtime/Messaging/Gateway.cs +++ b/src/Orleans.Runtime/Messaging/Gateway.cs @@ -357,9 +357,7 @@ public void Send(Message msg) { _pendingToSend.Enqueue(msg); _signal.Signal(); -#if DEBUG - if (_gateway.logger.IsEnabled(LogLevel.Trace)) _gateway.logger.LogTrace("Queued message {Message} for client {TargetGrain}", msg, msg.TargetGrain); -#endif + LogTraceQueuedMessage(_gateway.logger, msg, msg.TargetGrain); } private async Task RunMessageLoop() @@ -387,9 +385,7 @@ private async Task RunMessageLoop() { if (TrySend(connection, message)) { -#if DEBUG - if (_gateway.logger.IsEnabled(LogLevel.Trace)) _gateway.logger.LogTrace("Sent queued message {Message} to client {ClientId}", message, Id); -#endif + LogTraceSentQueuedMessage(_gateway.logger, message, Id); } else { @@ -515,6 +511,18 @@ internal void DropExpiredEntries() )] private static partial void LogWarningGatewayClientReceivedNewConnectionBeforePreviousConnectionRemoved(ILogger logger, ClientGrainId clientId, GatewayInboundConnection newConnection, GatewayInboundConnection previousConnection); + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Queued message {Message} for client {TargetGrain}" + )] + private static partial void LogTraceQueuedMessage(ILogger logger, object message, GrainId targetGrain); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Sent queued message {Message} to client {ClientId}" + )] + private static partial void LogTraceSentQueuedMessage(ILogger logger, object message, ClientGrainId clientId); + [LoggerMessage( Level = LogLevel.Warning, Message = "Exception in message loop for client {ClientId}" diff --git a/src/Orleans.Runtime/Placement/PlacementService.cs b/src/Orleans.Runtime/Placement/PlacementService.cs index 986d47f20af..49e5b3e85d7 100644 --- a/src/Orleans.Runtime/Placement/PlacementService.cs +++ b/src/Orleans.Runtime/Placement/PlacementService.cs @@ -98,9 +98,7 @@ public Task AddressMessage(Message message) private void SetMessageTargetPlacement(Message message, SiloAddress targetSilo) { message.TargetSilo = targetSilo; -#if DEBUG - if (_logger.IsEnabled(LogLevel.Trace)) _logger.LogTrace((int)ErrorCode.Dispatcher_AddressMsg_SelectTarget, "AddressMessage Placement SelectTarget {Message}", message); -#endif + LogTraceAddressMessageSelectTarget(message); } public SiloAddress[] GetCompatibleSilos(PlacementTarget target) @@ -318,7 +316,7 @@ private async Task ProcessLoop() } catch (Exception exception) { - _logger.LogWarning(exception, "Error in placement worker."); + LogWarnInPlacementWorker(_logger, exception); } await _workSignal.WaitAsync(); @@ -414,6 +412,12 @@ private class GrainPlacementWorkItem )] private partial void LogDebugLookingUpAddress(GrainId grainId, Message message); + [LoggerMessage( + Level = LogLevel.Trace, + Message = "AddressMessage Placement SelectTarget {Message}" + )] + private partial void LogTraceAddressMessageSelectTarget(Message message); + [LoggerMessage( EventId = (int)ErrorCode.Catalog_GetApproximateSiloStatuses, Level = LogLevel.Warning, @@ -426,5 +430,11 @@ private class GrainPlacementWorkItem Message = "Invalidating {Count} cached entries for message {Message}" )] private partial void LogDebugInvalidatingCachedEntries(int count, Message message); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Error in placement worker." + )] + private static partial void LogWarnInPlacementWorker(ILogger logger, Exception exception); } } diff --git a/src/Orleans.Runtime/Placement/Rebalancing/ActivationRebalancerMonitor.cs b/src/Orleans.Runtime/Placement/Rebalancing/ActivationRebalancerMonitor.cs index 9c4df27e618..5db2e6b75ff 100644 --- a/src/Orleans.Runtime/Placement/Rebalancing/ActivationRebalancerMonitor.cs +++ b/src/Orleans.Runtime/Placement/Rebalancing/ActivationRebalancerMonitor.cs @@ -130,7 +130,7 @@ public Task Report(RebalancingReport report) } catch (Exception ex) { - _logger.LogError(ex, "An unexpected error occurred while notifying rebalancer listener."); + LogErrorWhileNotifyingListener(ex); } } @@ -161,4 +161,10 @@ public void UnsubscribeFromReports(IActivationRebalancerReportListener listener) "I will attempt to migrate the rebalancer to another silo." )] private partial void LogMigratingRebalancer(SiloAddress silo); -} \ No newline at end of file + + [LoggerMessage( + Level = LogLevel.Error, + Message = "An unexpected error occurred while notifying rebalancer listener." + )] + private partial void LogErrorWhileNotifyingListener(Exception exception); +} diff --git a/src/Orleans.Runtime/Scheduler/ActivationTaskScheduler.cs b/src/Orleans.Runtime/Scheduler/ActivationTaskScheduler.cs index 7b8d389ad25..eaabb33614d 100644 --- a/src/Orleans.Runtime/Scheduler/ActivationTaskScheduler.cs +++ b/src/Orleans.Runtime/Scheduler/ActivationTaskScheduler.cs @@ -46,27 +46,17 @@ internal void RunTaskFromWorkItemGroup(Task task) if (!done) { #if DEBUG - LogTryExecuteTaskNotDone(task); + LogWarnTryExecuteTaskNotDone(task.Id, task.Status); #endif } } - [MethodImpl(MethodImplOptions.NoInlining)] - private void LogTryExecuteTaskNotDone(Task task) - { - logger.LogWarning( - (int)ErrorCode.SchedulerTaskExecuteIncomplete4, - "RunTask: Incomplete base.TryExecuteTask for Task Id={TaskId} with Status={TaskStatus}", - task.Id, - task.Status); - } - /// Queues a task to the scheduler. /// The task to be queued. protected override void QueueTask(Task task) { #if DEBUG - if (logger.IsEnabled(LogLevel.Trace)) logger.LogTrace("{TaskScheduler} QueueTask Task Id={TaskId}", myId, task.Id); + LogTraceQueueTask(myId, task.Id); #endif workerGroup.EnqueueTask(task); } @@ -84,22 +74,18 @@ protected override bool TryExecuteTaskInline(Task task, bool taskWasPreviouslyQu var canExecuteInline = !taskWasPreviouslyQueued && Equals(RuntimeContext.Current, workerGroup.GrainContext); #if DEBUG - if (logger.IsEnabled(LogLevel.Trace)) - { - logger.LogTrace( - "{TaskScheduler} TryExecuteTaskInline Task Id={TaskId} Status={Status} PreviouslyQueued={PreviouslyQueued} CanExecute={CanExecute} Queued={Queued}", - myId, - task.Id, - task.Status, - taskWasPreviouslyQueued, - canExecuteInline, - workerGroup.ExternalWorkItemCount); - } + LogTraceTryExecuteTaskInline( + myId, + task.Id, + task.Status, + taskWasPreviouslyQueued, + canExecuteInline, + workerGroup.ExternalWorkItemCount); #endif if (!canExecuteInline) { #if DEBUG - if (logger.IsEnabled(LogLevel.Trace)) logger.LogTrace("{TaskScheduler} Completed TryExecuteTaskInline Task Id={TaskId} Status={Status} Execute=No", myId, task.Id, task.Status); + LogTraceTryExecuteTaskInlineNotDone(myId, task.Id, task.Status); #endif return false; } @@ -108,29 +94,19 @@ protected override bool TryExecuteTaskInline(Task task, bool taskWasPreviouslyQu turnsExecutedStatistic.Increment(); #endif #if DEBUG - if (logger.IsEnabled(LogLevel.Trace)) - logger.LogTrace( - "{TaskScheduler} TryExecuteTaskInline Task Id={TaskId} Thread={Thread} Execute=Yes", - myId, - task.Id, - Thread.CurrentThread.ManagedThreadId); + LogTraceTryExecuteTaskInlineYes(myId, task.Id, Thread.CurrentThread.ManagedThreadId); #endif // Try to run the task. bool done = TryExecuteTask(task); if (!done) { #if DEBUG - LogTryExecuteTaskNotDone(task); + LogWarnTryExecuteTaskNotDone(task.Id, task.Status); #endif } #if DEBUG - if (logger.IsEnabled(LogLevel.Trace)) - logger.LogTrace( - "{TaskScheduler} Completed TryExecuteTaskInline Task Id={TaskId} Thread={Thread} Execute=Done Ok={Ok}", - myId, - task.Id, - Thread.CurrentThread.ManagedThreadId, - done); + + LogTraceTryExecuteTaskInlineCompleted(myId, task.Id, Thread.CurrentThread.ManagedThreadId, done); #endif return done; } @@ -142,5 +118,42 @@ protected override bool TryExecuteTaskInline(Task task, bool taskWasPreviouslyQu Message = "Created {TaskScheduler} with GrainContext={GrainContext}" )] private partial void LogCreatedTaskScheduler(ActivationTaskScheduler taskScheduler, IGrainContext grainContext); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)ErrorCode.SchedulerTaskExecuteIncomplete4, + Message = "RunTask: Incomplete base.TryExecuteTask for Task Id={TaskId} with Status={TaskStatus}" + )] + private partial void LogWarnTryExecuteTaskNotDone(int taskId, TaskStatus taskStatus); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{TaskScheduler} QueueTask Task Id={TaskId}" + )] + private partial void LogTraceQueueTask(long taskScheduler, int taskId); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{TaskScheduler} TryExecuteTaskInline Task Id={TaskId} Status={Status} PreviouslyQueued={PreviouslyQueued} CanExecute={CanExecute} Queued={Queued}" + )] + private partial void LogTraceTryExecuteTaskInline(long taskScheduler, int taskId, TaskStatus status, bool previouslyQueued, bool canExecute, int queued); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{TaskScheduler} Completed TryExecuteTaskInline Task Id={TaskId} Status={Status} Execute=No" + )] + private partial void LogTraceTryExecuteTaskInlineNotDone(long taskScheduler, int taskId, TaskStatus status); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{TaskScheduler} TryExecuteTaskInline Task Id={TaskId} Thread={Thread} Execute=Yes" + )] + private partial void LogTraceTryExecuteTaskInlineYes(long taskScheduler, int taskId, int thread); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{TaskScheduler} Completed TryExecuteTaskInline Task Id={TaskId} Thread={Thread} Execute=Done Ok={Ok}" + )] + private partial void LogTraceTryExecuteTaskInlineCompleted(long taskScheduler, int taskId, int thread, bool ok); } } diff --git a/src/Orleans.Runtime/Timers/GrainTimer.cs b/src/Orleans.Runtime/Timers/GrainTimer.cs index 2602b10ac5b..6bdbf530578 100644 --- a/src/Orleans.Runtime/Timers/GrainTimer.cs +++ b/src/Orleans.Runtime/Timers/GrainTimer.cs @@ -239,7 +239,7 @@ public void Dispose() } catch (Exception exception) { - Logger.LogWarning(exception, "Error cancelling timer callback."); + LogErrorCancellingCallback(Logger, exception); } _timer.Dispose(); @@ -319,6 +319,12 @@ public void Dispose() Message = "Caught and ignored exception thrown from timer callback for timer '{Timer}'." )] private static partial void LogWarningCallbackException(ILogger logger, Exception exception, GrainTimer timer); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error cancelling timer callback." + )] + private static partial void LogErrorCancellingCallback(ILogger logger, Exception exception); } internal sealed class GrainTimer : GrainTimer