From 87bd24a616401c1aa17d8602f78cf7ff7c255eac Mon Sep 17 00:00:00 2001 From: Gregorius Soedharmo Date: Fri, 1 Mar 2024 00:35:36 +0700 Subject: [PATCH] Suppress extremely chatty TimerScheduler debug messages (#7102) * Suppress extremely chatty TimerScheduler debug messages * Move configuration to Settings class. * Update API approval list --- ...oreAPISpec.ApproveCore.DotNet.verified.txt | 1 + .../CoreAPISpec.ApproveCore.Net.verified.txt | 1 + .../Scheduler/TimerSchedulerDebugSpec.cs | 103 ++++++++++++++++++ .../Akka/Actor/Scheduler/TimerScheduler.cs | 31 ++++-- src/core/Akka/Actor/Settings.cs | 6 + src/core/Akka/Configuration/akka.conf | 3 + 6 files changed, 135 insertions(+), 10 deletions(-) create mode 100644 src/core/Akka.Tests/Actor/Scheduler/TimerSchedulerDebugSpec.cs diff --git a/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.DotNet.verified.txt b/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.DotNet.verified.txt index 6a0f57ea371..08d6294b218 100644 --- a/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.DotNet.verified.txt +++ b/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.DotNet.verified.txt @@ -1712,6 +1712,7 @@ namespace Akka.Actor public bool DebugEventStream { get; } public bool DebugLifecycle { get; } public bool DebugRouterMisconfiguration { get; } + public bool DebugTimerScheduler { get; } public bool DebugUnhandledMessage { get; } public int DefaultVirtualNodesFactor { get; } public bool EmitActorTelemetry { get; } diff --git a/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.Net.verified.txt b/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.Net.verified.txt index 88832976eb4..f50634d8b95 100644 --- a/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.Net.verified.txt +++ b/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.Net.verified.txt @@ -1710,6 +1710,7 @@ namespace Akka.Actor public bool DebugEventStream { get; } public bool DebugLifecycle { get; } public bool DebugRouterMisconfiguration { get; } + public bool DebugTimerScheduler { get; } public bool DebugUnhandledMessage { get; } public int DefaultVirtualNodesFactor { get; } public bool EmitActorTelemetry { get; } diff --git a/src/core/Akka.Tests/Actor/Scheduler/TimerSchedulerDebugSpec.cs b/src/core/Akka.Tests/Actor/Scheduler/TimerSchedulerDebugSpec.cs new file mode 100644 index 00000000000..8a4061451e2 --- /dev/null +++ b/src/core/Akka.Tests/Actor/Scheduler/TimerSchedulerDebugSpec.cs @@ -0,0 +1,103 @@ +// ----------------------------------------------------------------------- +// +// Copyright (C) 2013-2024 .NET Foundation +// +// ----------------------------------------------------------------------- + +using System; +using System.Diagnostics; +using System.Threading; +using System.Threading.Tasks; +using Akka.Actor; +using Akka.Configuration; +using Akka.TestKit; +using FluentAssertions.Extensions; +using Xunit; +using Xunit.Abstractions; +using Debug = Akka.Event.Debug; + +namespace Akka.Tests.Actor.Scheduler; + +internal sealed class TimerTestActor: UntypedActor, IWithTimers +{ + protected override void OnReceive(object message) + { + switch (message) + { + case "startTimer": + Timers.StartSingleTimer("test", "test", 1.Seconds()); + break; + case "test": + break; + default: + Unhandled(message); + break; + } + } + + public ITimerScheduler Timers { get; set; } +} + +public class TimerSchedulerDebug: TestKit.Xunit2.TestKit +{ + public TimerSchedulerDebug(ITestOutputHelper output) : base("akka.actor.debug.log-timers = true", null, output) + { + } + + [Fact] + public void ShouldHonorDebugFlag() + { + Sys.EventStream.Subscribe(TestActor, typeof(Debug)); + var timerActor = Sys.ActorOf(); + timerActor.Tell("startTimer"); + + FishForMessage(msg => msg is Debug dbg && dbg.Message.ToString()!.StartsWith("Start timer [")); + } +} + +public class TimerSchedulerSuppressDebug: TestKit.Xunit2.TestKit +{ + public TimerSchedulerSuppressDebug(ITestOutputHelper output) : base("akka.actor.debug.log-timers = false", null, output) + { + } + + [Fact] + public async Task ShouldHonorSuppressDebugFlag() + { + Sys.EventStream.Subscribe(TestActor, typeof(Debug)); + var timerActor = Sys.ActorOf(); + timerActor.Tell("startTimer"); + + await ExpectNoMsgAsync( + predicate: msg => msg is Debug dbg && dbg.Message.ToString()!.StartsWith("Start timer ["), + timeout: 1.Seconds()); + } + + private async Task ExpectNoMsgAsync( + Predicate predicate, + TimeSpan? timeout = null, + CancellationToken cancellationToken = default) + { + var deadline = DateTime.Now + (timeout ?? 3.Seconds()); + var offset = 0.Seconds(); + + while (DateTime.Now < deadline) + { + var stopwatch = Stopwatch.StartNew(); + var (success, envelope) = await TryReceiveOneAsync(timeout - offset, cancellationToken); + stopwatch.Stop(); + offset += stopwatch.Elapsed; + + if(!success) + continue; + + var message = envelope.Message; + if (!predicate(message)) + continue; + + Assertions.Fail("Expected no message to match predicate, received {0} instead.", message); + break; + } + } + +} diff --git a/src/core/Akka/Actor/Scheduler/TimerScheduler.cs b/src/core/Akka/Actor/Scheduler/TimerScheduler.cs index 0d1279e775e..a619c0645c0 100644 --- a/src/core/Akka/Actor/Scheduler/TimerScheduler.cs +++ b/src/core/Akka/Actor/Scheduler/TimerScheduler.cs @@ -78,10 +78,14 @@ public TimerMsgNotInfluenceReceiveTimeout(object key, int generation, TimerSched private readonly IActorContext _ctx; private readonly Dictionary _timers = new(); private readonly AtomicCounter _timerGen = new(0); + private readonly bool _logDebug; + private readonly ILoggingAdapter _log; public TimerScheduler(IActorContext ctx) { _ctx = ctx; + _log = _ctx.System.Log; + _logDebug = ctx.System.Settings.DebugTimerScheduler; } /// @@ -167,7 +171,8 @@ public void Cancel(object key) /// public void CancelAll() { - _ctx.System.Log.Debug("Cancel all timers"); + if(_logDebug) + _log.Debug("Cancel all timers"); foreach (var timer in _timers) timer.Value.Task.Cancel(); _timers.Clear(); @@ -175,7 +180,8 @@ public void CancelAll() private void CancelTimer(Timer timer) { - _ctx.System.Log.Debug("Cancel timer [{0}] with generation [{1}]", timer.Key, timer.Generation); + if(_logDebug) + _log.Debug("Cancel timer [{0}] with generation [{1}]", timer.Key, timer.Generation); timer.Task.Cancel(); _timers.Remove(timer.Key); } @@ -201,7 +207,9 @@ private void StartTimer(object key, object msg, TimeSpan timeout, TimeSpan initi task = _ctx.System.Scheduler.ScheduleTellOnceCancelable(timeout, _ctx.Self, timerMsg, ActorRefs.NoSender); var nextTimer = new Timer(key, msg, repeat, nextGen, task); - _ctx.System.Log.Debug("Start timer [{0}] with generation [{1}]", key, nextGen); + + if(_logDebug) + _log.Debug("Start timer [{0}] with generation [{1}]", key, nextGen); _timers[key] = nextTimer; } @@ -210,13 +218,15 @@ public object InterceptTimerMsg(ILoggingAdapter log, ITimerMsg timerMsg) if (!_timers.TryGetValue(timerMsg.Key, out var timer)) { // it was from canceled timer that was already enqueued in mailbox - log.Debug("Received timer [{0}] that has been removed, discarding", timerMsg.Key); + if(_logDebug) + log.Debug("Received timer [{0}] that has been removed, discarding", timerMsg.Key); return null; // message should be ignored } if (!ReferenceEquals(timerMsg.Owner, this)) { // after restart, it was from an old instance that was enqueued in mailbox before canceled - log.Debug("Received timer [{0}] from old restarted instance, discarding", timerMsg.Key); + if(_logDebug) + log.Debug("Received timer [{0}] from old restarted instance, discarding", timerMsg.Key); return null; // message should be ignored } @@ -229,11 +239,12 @@ public object InterceptTimerMsg(ILoggingAdapter log, ITimerMsg timerMsg) } // it was from an old timer that was enqueued in mailbox before canceled - log.Debug( - "Received timer [{0}] from old generation [{1}], expected generation [{2}], discarding", - timerMsg.Key, - timerMsg.Generation, - timer.Generation); + if(_logDebug) + log.Debug( + "Received timer [{0}] from old generation [{1}], expected generation [{2}], discarding", + timerMsg.Key, + timerMsg.Generation, + timer.Generation); return null; // message should be ignored } } diff --git a/src/core/Akka/Actor/Settings.cs b/src/core/Akka/Actor/Settings.cs index d6a4c2818a4..62a4d75a689 100644 --- a/src/core/Akka/Actor/Settings.cs +++ b/src/core/Akka/Actor/Settings.cs @@ -205,6 +205,7 @@ public Settings(ActorSystem system, Config config, ActorSystemSetup setup) DebugEventStream = Config.GetBoolean("akka.actor.debug.event-stream", false); DebugUnhandledMessage = Config.GetBoolean("akka.actor.debug.unhandled", false); DebugRouterMisconfiguration = Config.GetBoolean("akka.actor.debug.router-misconfiguration", false); + DebugTimerScheduler = Config.GetBoolean("akka.actor.debug.log-timers"); Home = Config.GetString("akka.home", ""); DefaultVirtualNodesFactor = Config.GetInt("akka.actor.deployment.default.virtual-nodes-factor", 0); @@ -425,6 +426,11 @@ public Settings(ActorSystem system, Config config, ActorSystemSetup setup) /// /// true if [debug lifecycle]; otherwise, false. public bool DebugLifecycle { get; private set; } + + /// + /// Should TimerScheduler emit debug logs + /// + public bool DebugTimerScheduler { get; private set; } /// /// TBD diff --git a/src/core/Akka/Configuration/akka.conf b/src/core/Akka/Configuration/akka.conf index e4594491f39..933eefbd724 100644 --- a/src/core/Akka/Configuration/akka.conf +++ b/src/core/Akka/Configuration/akka.conf @@ -514,6 +514,9 @@ akka { # enable WARN logging of misconfigured routers router-misconfiguration = off + + # enable TimerScheduler debug logging + log-timers = false } # Entries for pluggable serializers and their bindings.