From 9fe803a576f4ecee4c39fb87bc9cf203e6f21348 Mon Sep 17 00:00:00 2001 From: Reuben Bond Date: Thu, 11 Jun 2026 16:11:40 -0700 Subject: [PATCH 1/3] test: stabilize timer tests with fake time Use FakeTimeProvider for the timer test cluster and drive timer ticks through diagnostic events instead of wall-clock delays. Inject TimeProvider into timer grains so callback delays are advanced deterministically by the tests. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../Grains/TestGrainInterfaces/ITimerGrain.cs | 1 + test/Grains/TestInternalGrains/TimerGrain.cs | 168 ++++++- .../TimerOrleansTest.cs | 458 ++++++++++-------- .../Diagnostics/TimerDiagnosticObserver.cs | 219 ++++++--- 4 files changed, 566 insertions(+), 280 deletions(-) diff --git a/test/Grains/TestGrainInterfaces/ITimerGrain.cs b/test/Grains/TestGrainInterfaces/ITimerGrain.cs index 2cf7cc93fe6..965a0770d65 100644 --- a/test/Grains/TestGrainInterfaces/ITimerGrain.cs +++ b/test/Grains/TestGrainInterfaces/ITimerGrain.cs @@ -25,6 +25,7 @@ public interface ITimerCallGrain : IGrainWithIntegerKey Task StartTimer(string name, TimeSpan dueTime, string operationType); Task RestartTimer(string name, TimeSpan dueTime); Task RestartTimer(string name, TimeSpan dueTime, TimeSpan period); + Task TestTimerChangeArguments(); Task StopTimer(string name); Task RunSelfDisposingTimer(); } diff --git a/test/Grains/TestInternalGrains/TimerGrain.cs b/test/Grains/TestInternalGrains/TimerGrain.cs index b91e7fe4bcd..640f56a9fd0 100644 --- a/test/Grains/TestInternalGrains/TimerGrain.cs +++ b/test/Grains/TestInternalGrains/TimerGrain.cs @@ -1,3 +1,5 @@ +using System.Diagnostics; +using System.Runtime.CompilerServices; using Microsoft.Extensions.Logging; using Orleans.Runtime; using Orleans.Runtime.Scheduler; @@ -13,6 +15,59 @@ internal static class TimerGrainTestConstants public static readonly TimeSpan CallbackDelay = TimeSpan.FromMilliseconds(50); } + public static class TimerGrainCallbackEvents + { + public const string ListenerName = "Orleans.Tests.TimerGrainCallbacks"; + + private static readonly DiagnosticListener Listener = new(ListenerName); + + public static IObservable AllEvents { get; } = new Observable(); + + public abstract class CallbackEvent(GrainId grainId) + { + public readonly GrainId GrainId = grainId; + } + + public sealed class DelayStarted(GrainId grainId) : CallbackEvent(grainId) + { + } + + internal static void EmitDelayStarted(GrainId grainId) + { + if (!Listener.IsEnabled(nameof(DelayStarted))) + { + return; + } + + Emit(grainId); + + [MethodImpl(MethodImplOptions.NoInlining)] + static void Emit(GrainId grainId) + { + Listener.Write(nameof(DelayStarted), new DelayStarted(grainId)); + } + } + + private sealed class Observable : IObservable + { + public IDisposable Subscribe(IObserver observer) => Listener.Subscribe(new Observer(observer)); + + private sealed class Observer(IObserver observer) : IObserver> + { + public void OnCompleted() => observer.OnCompleted(); + public void OnError(Exception error) => observer.OnError(error); + + public void OnNext(KeyValuePair value) + { + if (value.Value is CallbackEvent evt) + { + observer.OnNext(evt); + } + } + } + } + } + public class TimerGrain : Grain, ITimerGrain { private bool deactivating; @@ -144,10 +199,12 @@ public class TimerCallGrain : Grain, ITimerCallGrain private TaskScheduler activationTaskScheduler; private readonly ILogger logger; + private readonly TimeProvider timeProvider; - public TimerCallGrain(ILoggerFactory loggerFactory) + public TimerCallGrain(ILoggerFactory loggerFactory, TimeProvider timeProvider) { this.logger = loggerFactory.CreateLogger($"{this.GetType().Name}-{this.IdentityString}"); + this.timeProvider = timeProvider; } public Task GetTickCount() { return Task.FromResult(tickCount); } @@ -199,6 +256,42 @@ public Task RestartTimer(string name, TimeSpan delay, TimeSpan period) return Task.CompletedTask; } + public Task TestTimerChangeArguments() + { + ValidateTimerChangeArguments(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan); + ValidateTimerChangeArguments(TimeSpan.Zero, Timeout.InfiniteTimeSpan); + ValidateTimerChangeArguments(TimeSpan.FromMicroseconds(10), Timeout.InfiniteTimeSpan); + ValidateTimerChangeArguments(TimeSpan.Zero, TimeSpan.Zero); + ValidateTimerChangeArguments(TimeSpan.FromMicroseconds(10), TimeSpan.FromMicroseconds(10)); + ValidateTimerChangeArguments(TimeSpan.FromMilliseconds(-0.4), Timeout.InfiniteTimeSpan); + ValidateTimerChangeArguments(TimeSpan.FromSeconds(1), TimeSpan.FromMilliseconds(-0.5)); + ValidateTimerChangeArguments(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan); + + Assert.Throws(() => ValidateTimerChangeArguments(TimeSpan.FromSeconds(-5), Timeout.InfiniteTimeSpan)); + Assert.Throws(() => ValidateTimerChangeArguments(TimeSpan.MaxValue, Timeout.InfiniteTimeSpan)); + Assert.Throws(() => ValidateTimerChangeArguments(TimeSpan.FromSeconds(1), TimeSpan.FromSeconds(-5))); + Assert.Throws(() => ValidateTimerChangeArguments(TimeSpan.FromSeconds(1), TimeSpan.MaxValue)); + + return Task.CompletedTask; + } + + private void ValidateTimerChangeArguments(TimeSpan dueTime, TimeSpan period) + { + var timer = this.RegisterGrainTimer(_ => Task.CompletedTask, new GrainTimerCreationOptions(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan) + { + Interleave = true + }); + + try + { + timer.Change(dueTime, period); + } + finally + { + timer.Dispose(); + } + } + public Task StopTimer(string name) { logger.LogInformation("StopTimer Name={Name}", name); @@ -225,7 +318,8 @@ public async Task RunSelfDisposingTimer() Assert.NotNull(timer[0]); timer[0].Dispose(); Assert.True(ct.IsCancellationRequested); - await Task.Delay(100); + TimerGrainCallbackEvents.EmitDelayStarted(context.GrainId); + await Task.Delay(TimeSpan.FromMilliseconds(100), timeProvider); tcs.TrySetResult(); } catch (Exception ex) @@ -303,7 +397,8 @@ private async Task ProcessTimerTick(object data) CheckRuntimeContext(step); LogStatus("Before Delay"); - await Task.Delay(TimerGrainTestConstants.CallbackDelay); + TimerGrainCallbackEvents.EmitDelayStarted(context.GrainId); + await Task.Delay(TimerGrainTestConstants.CallbackDelay, timeProvider); step = "After Delay"; LogStatus(step); CheckRuntimeContext(step); @@ -367,10 +462,12 @@ public class NonReentrantTimerCallGrain : Grain, INonReentrantTimerCallGrain private Guid _tickId; private readonly ILogger _logger; + private readonly TimeProvider _timeProvider; - public NonReentrantTimerCallGrain(ILoggerFactory loggerFactory) + public NonReentrantTimerCallGrain(ILoggerFactory loggerFactory, TimeProvider timeProvider) { _logger = loggerFactory.CreateLogger($"{GetType().Name}-{IdentityString}"); + _timeProvider = timeProvider; } public Task GetTickCount() => Task.FromResult(_tickCount); @@ -450,7 +547,8 @@ private async Task ProcessTimerTick(object data, CancellationToken cancellationT CheckReentrancy(step, expectedTickId); LogStatus("Before Delay", timerName); - await Task.Delay(TimerGrainTestConstants.CallbackDelay); + TimerGrainCallbackEvents.EmitDelayStarted(_context.GrainId); + await Task.Delay(TimerGrainTestConstants.CallbackDelay, _timeProvider); step = "After Delay"; LogStatus(step, timerName); CheckRuntimeContext(step); @@ -797,13 +895,15 @@ public class PocoTimerCallGrain : IGrainBase, IPocoTimerCallGrain private readonly ILogger logger; private readonly IGrainFactory _grainFactory; + private readonly TimeProvider _timeProvider; public IGrainContext GrainContext { get; } - public PocoTimerCallGrain(ILoggerFactory loggerFactory, IGrainContext grainContext, IGrainFactory grainFactory) + public PocoTimerCallGrain(ILoggerFactory loggerFactory, IGrainContext grainContext, IGrainFactory grainFactory, TimeProvider timeProvider) { GrainContext = grainContext; _grainFactory = grainFactory; + _timeProvider = timeProvider; this.logger = loggerFactory.CreateLogger($"{this.GetType().Name}-{this.GrainContext.GrainId}"); } @@ -821,7 +921,7 @@ public Task StartTimer(string name, TimeSpan delay) { logger.LogInformation("StartTimer Name={Name} Delay={Delay}", name, delay); if (timer is not null) throw new InvalidOperationException("Expected timer to be null"); - this.timer = this.RegisterGrainTimer(TimerTick, name, new(delay, Timeout.InfiniteTimeSpan)); // One shot timer + this.timer = this.RegisterGrainTimer(TimerTick, name, new(delay, Timeout.InfiniteTimeSpan) { Interleave = true }); // One shot timer this.timerName = name; return Task.CompletedTask; @@ -832,7 +932,7 @@ public Task StartTimer(string name, TimeSpan delay, string operationType) logger.LogInformation("StartTimer Name={Name} Delay={Delay}", name, delay); if (timer is not null) throw new InvalidOperationException("Expected timer to be null"); var state = Tuple.Create(operationType, name); - this.timer = this.RegisterGrainTimer(TimerTickAdvanced, state, delay, Timeout.InfiniteTimeSpan); // One shot timer + this.timer = this.RegisterGrainTimer(TimerTickAdvanced, state, new(delay, Timeout.InfiniteTimeSpan) { Interleave = true }); // One shot timer this.timerName = name; return Task.CompletedTask; @@ -856,6 +956,42 @@ public Task RestartTimer(string name, TimeSpan delay, TimeSpan period) return Task.CompletedTask; } + public Task TestTimerChangeArguments() + { + ValidateTimerChangeArguments(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan); + ValidateTimerChangeArguments(TimeSpan.Zero, Timeout.InfiniteTimeSpan); + ValidateTimerChangeArguments(TimeSpan.FromMicroseconds(10), Timeout.InfiniteTimeSpan); + ValidateTimerChangeArguments(TimeSpan.Zero, TimeSpan.Zero); + ValidateTimerChangeArguments(TimeSpan.FromMicroseconds(10), TimeSpan.FromMicroseconds(10)); + ValidateTimerChangeArguments(TimeSpan.FromMilliseconds(-0.4), Timeout.InfiniteTimeSpan); + ValidateTimerChangeArguments(TimeSpan.FromSeconds(1), TimeSpan.FromMilliseconds(-0.5)); + ValidateTimerChangeArguments(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan); + + Assert.Throws(() => ValidateTimerChangeArguments(TimeSpan.FromSeconds(-5), Timeout.InfiniteTimeSpan)); + Assert.Throws(() => ValidateTimerChangeArguments(TimeSpan.MaxValue, Timeout.InfiniteTimeSpan)); + Assert.Throws(() => ValidateTimerChangeArguments(TimeSpan.FromSeconds(1), TimeSpan.FromSeconds(-5))); + Assert.Throws(() => ValidateTimerChangeArguments(TimeSpan.FromSeconds(1), TimeSpan.MaxValue)); + + return Task.CompletedTask; + } + + private void ValidateTimerChangeArguments(TimeSpan dueTime, TimeSpan period) + { + var timer = this.RegisterGrainTimer(_ => Task.CompletedTask, new GrainTimerCreationOptions(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan) + { + Interleave = true + }); + + try + { + timer.Change(dueTime, period); + } + finally + { + timer.Dispose(); + } + } + public Task StopTimer(string name) { logger.LogInformation("StopTimer Name={Name}", name); @@ -882,7 +1018,8 @@ public async Task RunSelfDisposingTimer() Assert.NotNull(timer[0]); timer[0].Dispose(); Assert.True(ct.IsCancellationRequested); - await Task.Delay(100); + TimerGrainCallbackEvents.EmitDelayStarted(context.GrainId); + await Task.Delay(TimeSpan.FromMilliseconds(100), _timeProvider); tcs.TrySetResult(); } catch (Exception ex) @@ -960,7 +1097,8 @@ private async Task ProcessTimerTick(object data) CheckRuntimeContext(step); LogStatus("Before Delay"); - await Task.Delay(TimerGrainTestConstants.CallbackDelay); + TimerGrainCallbackEvents.EmitDelayStarted(context.GrainId); + await Task.Delay(TimerGrainTestConstants.CallbackDelay, _timeProvider); step = "After Delay"; LogStatus(step); CheckRuntimeContext(step); @@ -1176,13 +1314,15 @@ public class PocoNonReentrantTimerCallGrain : IGrainBase, IPocoNonReentrantTimer private readonly ILogger _logger; private readonly IGrainFactory _grainFactory; + private readonly TimeProvider _timeProvider; public IGrainContext GrainContext { get; } - public PocoNonReentrantTimerCallGrain(ILoggerFactory loggerFactory, IGrainContext grainContext, IGrainFactory grainFactory) + public PocoNonReentrantTimerCallGrain(ILoggerFactory loggerFactory, IGrainContext grainContext, IGrainFactory grainFactory, TimeProvider timeProvider) { GrainContext = grainContext; _grainFactory = grainFactory; + _timeProvider = timeProvider; _logger = loggerFactory.CreateLogger($"{GetType().Name}-{GrainContext.GrainId}"); } @@ -1212,7 +1352,8 @@ public async Task RunSelfDisposingTimer() Assert.NotNull(timer[0]); timer[0].Dispose(); tcs.TrySetResult(); - await Task.Delay(100); + TimerGrainCallbackEvents.EmitDelayStarted(_context.GrainId); + await Task.Delay(TimeSpan.FromMilliseconds(100), _timeProvider); } catch (Exception ex) { @@ -1289,7 +1430,8 @@ private async Task ProcessTimerTick(object data, CancellationToken cancellationT CheckReentrancy(step, expectedTickId); LogStatus("Before Delay", timerName); - await Task.Delay(TimerGrainTestConstants.CallbackDelay); + TimerGrainCallbackEvents.EmitDelayStarted(_context.GrainId); + await Task.Delay(TimerGrainTestConstants.CallbackDelay, _timeProvider); step = "After Delay"; LogStatus(step, timerName); CheckRuntimeContext(step); diff --git a/test/Orleans.DefaultCluster.Tests/TimerOrleansTest.cs b/test/Orleans.DefaultCluster.Tests/TimerOrleansTest.cs index fd3fb7e4d77..aadcf619d73 100644 --- a/test/Orleans.DefaultCluster.Tests/TimerOrleansTest.cs +++ b/test/Orleans.DefaultCluster.Tests/TimerOrleansTest.cs @@ -1,12 +1,28 @@ -using System.Diagnostics; -using Orleans.TestingHost.Utils; +using System.Collections.Concurrent; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.DependencyInjection.Extensions; +using Microsoft.Extensions.Time.Testing; +using Orleans.Configuration; +using Orleans.Hosting; +using Orleans.TestingHost; using TestExtensions; +using UnitTestGrains; using UnitTests.GrainInterfaces; using Xunit; using Xunit.Abstractions; namespace DefaultCluster.Tests.TimerTests { + public static class TimerOrleansTestCollection + { + public const string Name = nameof(TimerOrleansTest); + } + + [CollectionDefinition(TimerOrleansTestCollection.Name)] + public sealed class TimerOrleansTestCollectionDefinition : ICollectionFixture + { + } + /// /// Tests for Orleans Timer functionality. /// Timers provide grain-local, non-durable periodic callbacks. Unlike reminders, @@ -15,55 +31,215 @@ namespace DefaultCluster.Tests.TimerTests /// timeouts, and other scenarios where persistence isn't required. /// Timers are more efficient than reminders for high-frequency operations. /// - public class TimerOrleansTest : HostedTestClusterEnsureDefaultStarted + [Collection(TimerOrleansTestCollection.Name)] + public class TimerOrleansTest : OrleansTestingBase { + private const int ExpectedDefaultTimerTicks = 10; private static readonly TimeSpan OneShotTimerDelay = TimeSpan.FromMilliseconds(100); + private static readonly TimeSpan TimerCallbackDelay = TimeSpan.FromMilliseconds(50); + private static readonly TimeSpan TimerOverloadDueTime = TimeSpan.FromMilliseconds(25); private static readonly TimeSpan TimerDiagnosticTimeout = TimeSpan.FromSeconds(10); + private readonly Fixture fixture; private readonly ITestOutputHelper output; - public TimerOrleansTest(ITestOutputHelper output, DefaultClusterFixture fixture) - : base(fixture) + public TimerOrleansTest(ITestOutputHelper output, Fixture fixture) { + this.fixture = fixture; this.output = output; } - private static async Task WaitForCounterAtLeast(Func> getCounter, int minimumValue, TimeSpan timeout, TimeSpan delay) + private IGrainFactory GrainFactory => fixture.GrainFactory; + + private async Task AdvanceDefaultTimerTicksAsync(ITimerGrain grain, TimeSpan period) + { + using var timerObserver = TimerDiagnosticObserver.Create(); + for (var expectedTickCount = 1; expectedTickCount <= ExpectedDefaultTimerTicks; expectedTickCount++) + { + await AdvanceTimerToTickCountAsync(grain, timerObserver, period, expectedTickCount); + await grain.GetCounter(); + } + + return await grain.GetCounter(); + } + + private async Task AdvanceDefaultTimerTicksAsync(IReadOnlyList grains, TimeSpan period) + where TGrain : ITimerGrain + { + using var timerObserver = TimerDiagnosticObserver.Create(); + for (var expectedTickCount = 1; expectedTickCount <= ExpectedDefaultTimerTicks; expectedTickCount++) + { + var waitForTicks = Task.WhenAll(grains.Select(g => timerObserver.WaitForTickCountAsync(g, expectedTickCount, TimerDiagnosticTimeout))); + fixture.AdvanceTime(period); + await waitForTicks; + await Task.WhenAll(grains.Select(g => g.GetCounter())); + } + } + + private async Task AdvanceTimerToTickCountAsync(IAddressable grain, TimerDiagnosticObserver timerObserver, TimeSpan dueTime, int expectedTickCount) + { + var waitForTick = timerObserver.WaitForTickCountAsync(grain, expectedTickCount, TimerDiagnosticTimeout); + fixture.AdvanceTime(dueTime); + await waitForTick; + } + + private async Task AdvanceTimerToTickCountAsync( + IAddressable grain, + TimerDiagnosticObserver timerObserver, + TimeSpan dueTime, + TimeSpan callbackDelay, + int expectedTickCount) + { + using var callbackObserver = TimerCallbackDiagnosticObserver.Create(); + var grainId = grain.GetGrainId(); + var delayStartedCount = callbackObserver.GetDelayStartedCount(grainId); + + fixture.AdvanceTime(dueTime); + for (var tickCount = timerObserver.GetTickCount(grain.GetGrainId()) + 1; tickCount <= expectedTickCount; tickCount++) + { + await timerObserver.WaitForTickStartCountAsync(grain, tickCount, TimerDiagnosticTimeout); + await callbackObserver.WaitForDelayStartedCountAsync(grainId, ++delayStartedCount, TimerDiagnosticTimeout); + + var waitForTickStop = timerObserver.WaitForTickCountAsync(grain, tickCount, TimerDiagnosticTimeout); + fixture.AdvanceTime(callbackDelay); + await waitForTickStop; + } + } + + private async Task DriveExternalTickUntilTimerTicks(INonReentrantTimerCallGrain grain, TimerDiagnosticObserver timerObserver, TimeSpan dueTime, int expectedTimerTicks) + { + using var callbackObserver = TimerCallbackDiagnosticObserver.Create(); + var grainId = grain.GetGrainId(); + var externalTick = grain.ExternalTick("external"); + await callbackObserver.WaitForDelayStartedCountAsync(grainId, callbackObserver.GetDelayStartedCount(grainId) + 1, TimerDiagnosticTimeout); + fixture.AdvanceTime(TimerCallbackDelay); + await externalTick; + await AdvanceTimerToTickCountAsync(grain, timerObserver, dueTime, TimerCallbackDelay, expectedTimerTicks); + return 1; + } + + private async Task RunSelfDisposingTimerAsync(ITimerCallGrain grain) { - var last = 0; - await TestingUtils.WaitUntilAsync( - async lastTry => + using var timerObserver = TimerDiagnosticObserver.Create(); + var runTimer = grain.RunSelfDisposingTimer(); + var created = await timerObserver.WaitForTimerCreatedAsync(grain, TimerDiagnosticTimeout); + await AdvanceTimerToTickCountAsync(grain, timerObserver, created.DueTime, TimeSpan.FromMilliseconds(100), expectedTickCount: 1); + await runTimer; + } + + private sealed class TimerCallbackDiagnosticObserver : IDisposable, IObserver + { + private readonly ConcurrentBag delayStartedEvents = new(); + private readonly object changeLock = new(); + private TaskCompletionSource changed = CreateCompletionSource(); + private IDisposable subscription; + + public static TimerCallbackDiagnosticObserver Create() + { + var observer = new TimerCallbackDiagnosticObserver(); + observer.subscription = TimerGrainCallbackEvents.AllEvents.Subscribe(observer); + return observer; + } + + public int GetDelayStartedCount(GrainId grainId) + { + return delayStartedEvents.Count(e => e.GrainId == grainId); + } + + public async Task WaitForDelayStartedCountAsync(GrainId grainId, int expectedCount, TimeSpan timeout) + { + using var cts = new CancellationTokenSource(timeout); + + while (true) { - last = await getCounter(); - if (last >= minimumValue) + Task changedTask; + lock (changeLock) { - return true; + var currentCount = GetDelayStartedCount(grainId); + if (currentCount >= expectedCount) + { + return; + } + + changedTask = changed.Task; } - if (lastTry) + try + { + await changedTask.WaitAsync(cts.Token); + } + catch (OperationCanceledException) { - Assert.Fail($"Counter did not reach {minimumValue} within {timeout}. Last value: {last}"); + break; } + } + + var finalCount = GetDelayStartedCount(grainId); + if (finalCount >= expectedCount) + { + return; + } + + throw new TimeoutException($"Timed out waiting for {expectedCount} timer callbacks to reach their fake delay on grain {grainId}. Current count: {finalCount} after {timeout}"); + } + + void IObserver.OnNext(TimerGrainCallbackEvents.CallbackEvent value) + { + if (value is TimerGrainCallbackEvents.DelayStarted delayStarted) + { + delayStartedEvents.Add(delayStarted); + SignalChanged(); + } + } + + void IObserver.OnError(Exception error) + { + } + + void IObserver.OnCompleted() + { + } + + public void Dispose() + { + subscription?.Dispose(); + } - return false; - }, - timeout, - delay); + private static TaskCompletionSource CreateCompletionSource() => new(TaskCreationOptions.RunContinuationsAsynchronously); + + private void SignalChanged() + { + TaskCompletionSource previous; + lock (changeLock) + { + previous = changed; + changed = CreateCompletionSource(); + } - return last; + previous.TrySetResult(); + } } - private static async Task DriveExternalTicksUntilTimerTicks(INonReentrantTimerCallGrain grain, TimerDiagnosticObserver timerObserver, int expectedTimerTicks) + public sealed class Fixture : BaseInProcessTestClusterFixture { - var waitForTimers = timerObserver.WaitForTickCountAsync(grain, expectedTimerTicks, TimerDiagnosticTimeout); - var externalTicks = 0; - while (!waitForTimers.IsCompleted) + private readonly FakeTimeProvider timeProvider = new(new DateTimeOffset(2026, 1, 1, 0, 0, 0, TimeSpan.Zero)); + + protected override void ConfigureTestCluster(InProcessTestClusterBuilder builder) { - await grain.ExternalTick("external"); - externalTicks++; + builder.ConfigureSilo((_, siloBuilder) => + { + siloBuilder + .Configure(o => o.ClientGatewayShutdownNotificationTimeout = default) + .UseInMemoryReminderService() + .UseInMemoryDurableJobs() + .AddMemoryGrainStorageAsDefault() + .AddMemoryGrainStorage("MemoryStore"); + + siloBuilder.Services.AddSingleton(timeProvider); + siloBuilder.Services.Replace(ServiceDescriptor.Singleton(sp => sp.GetRequiredService())); + }); } - await waitForTimers; - return externalTicks; + public void AdvanceTime(TimeSpan duration) => timeProvider.Advance(duration); } /// @@ -79,16 +255,15 @@ public async Task TimerOrleansTest_Basic() { var grain = GrainFactory.GetGrain(GetRandomGrainId()); var period = await grain.GetTimerPeriod(); - var timeout = period.Multiply(50); - var last = await WaitForCounterAtLeast(grain.GetCounter, 10, timeout, period); + var last = await AdvanceDefaultTimerTicksAsync(grain, period); output.WriteLine("value = " + last); - Assert.True(last >= 10 & last <= 12, last.ToString()); + Assert.Equal(ExpectedDefaultTimerTicks, last); await grain.StopDefaultTimer(); - await Task.Delay(period.Multiply(2)); + fixture.AdvanceTime(period.Multiply(2)); var curr = await grain.GetCounter(); - Assert.True(curr == last || curr == last + 1, "curr == last || curr == last + 1"); + Assert.Equal(last, curr); } } @@ -110,32 +285,13 @@ public async Task TimerOrleansTest_Parallel() period = await grain.GetTimerPeriod(); // activate grains } - var tasks = new List(grains.Count); - for (int i = 0; i < grains.Count; i++) - { - ITimerGrain grain = grains[i]; - tasks.Add( - Task.Run( - async () => - { - int last = await grain.GetCounter(); - var stopwatch = Stopwatch.StartNew(); - var timeout = period.Multiply(50); - while (stopwatch.Elapsed < timeout && last < 10) - { - await Task.Delay(period.Divide(2)); - last = await grain.GetCounter(); - } - - output.WriteLine("value = " + last); - Assert.True(last >= 10 && last <= 12, "last >= 10 && last <= 12"); - })); - } - - await Task.WhenAll(tasks); + await AdvanceDefaultTimerTicksAsync(grains, period); for (int i = 0; i < grains.Count; i++) { ITimerGrain grain = grains[i]; + var last = await grain.GetCounter(); + output.WriteLine("value = " + last); + Assert.Equal(ExpectedDefaultTimerTicks, last); await grain.StopDefaultTimer(); } } @@ -153,42 +309,22 @@ public async Task TimerOrleansTest_Migration() TimeSpan period = await grain.GetTimerPeriod(); // Ensure that the grain works as it should. - var last = await grain.GetCounter(); - var stopwatch = Stopwatch.StartNew(); - var timeout = period.Multiply(50); - while (stopwatch.Elapsed < timeout && last < 10) - { - await Task.Delay(period.Divide(2)); - last = await grain.GetCounter(); - } - - last = await grain.GetCounter(); + var last = await AdvanceDefaultTimerTicksAsync(grain, period); + Assert.Equal(ExpectedDefaultTimerTicks, last); output.WriteLine("value = " + last); // Restart the grain. await grain.Deactivate(); - stopwatch.Restart(); last = await grain.GetCounter(); Assert.True(last == 0, "Restarted grains should have zero ticks. Actual: " + last); period = await grain.GetTimerPeriod(); // Poke the grain and ensure it still works as it should. - while (stopwatch.Elapsed < timeout && last < 10) - { - await Task.Delay(period.Divide(2)); - last = await grain.GetCounter(); - } - - last = await grain.GetCounter(); - stopwatch.Stop(); - - int maximalNumTicks = (int)Math.Round(stopwatch.Elapsed.Divide(period), MidpointRounding.ToPositiveInfinity); - Assert.True( - last <= maximalNumTicks, - $"Assert: last <= maximalNumTicks. Actual: last = {last}, maximalNumTicks = {maximalNumTicks}"); + last = await AdvanceDefaultTimerTicksAsync(grain, period); + Assert.Equal(ExpectedDefaultTimerTicks, last); output.WriteLine( - "Total Elapsed time = " + (stopwatch.Elapsed.TotalSeconds) + " sec. Expected Ticks = " + maximalNumTicks + + "Virtual elapsed time = " + (period.Multiply(ExpectedDefaultTimerTicks).TotalSeconds) + " sec. Expected ticks = " + ExpectedDefaultTimerTicks + ". Actual ticks = " + last); } @@ -214,7 +350,7 @@ public async Task AsyncTimerTest_GrainCall() await grain.StartTimer(testName, delay); - await timerObserver.WaitForTimerTickAsync(grain, TimerDiagnosticTimeout); + await AdvanceTimerToTickCountAsync(grain, timerObserver, delay, TimerCallbackDelay, expectedTickCount: 1); int tickCount = await grain.GetTickCount(); Assert.Equal(1, tickCount); @@ -255,19 +391,11 @@ public async Task GrainTimer_TestAllOverloads() { var grain = GrainFactory.GetGrain(GetRandomGrainId()); - using var cts = new CancellationTokenSource(TimeSpan.FromSeconds(30)); + using var timerObserver = TimerDiagnosticObserver.Create(); var numTimers = await grain.TestAllTimerOverloads(); - while (true) - { - var completedTimers = await grain.PollCompletedTimers().WaitAsync(cts.Token); - if (completedTimers == numTimers) - { - break; - } - - await Task.Delay(TimeSpan.FromMilliseconds(50), cts.Token); - } - + var waitForTimers = timerObserver.WaitForTickCountAsync(grain, numTimers, TimerDiagnosticTimeout); + fixture.AdvanceTime(TimerOverloadDueTime); + await waitForTimers; await grain.TestCompletedTimerResults(); } @@ -282,10 +410,10 @@ public async Task GrainTimer_DisposeFromCallback() { // Schedule a timer which disposes itself from its own callback. var grain = GrainFactory.GetGrain(GetRandomGrainId()); - await grain.RunSelfDisposingTimer(); + await RunSelfDisposingTimerAsync(grain); var pocoGrain = GrainFactory.GetGrain(GetRandomGrainId()); - await pocoGrain.RunSelfDisposingTimer(); + await RunSelfDisposingTimerAsync(pocoGrain); } /// @@ -310,7 +438,7 @@ public async Task NonReentrantGrainTimer_Test() await grain.StartTimer($"{testName}_2", delay); // Invoke some non-interleaving methods while waiting for the timer callbacks. - var externalTicks = await DriveExternalTicksUntilTimerTicks(grain, timerObserver, expectedTimerTicks: 3); + var externalTicks = await DriveExternalTickUntilTimerTicks(grain, timerObserver, delay, expectedTimerTicks: 3); var tickCount = await grain.GetTickCount(); @@ -342,35 +470,19 @@ public async Task GrainTimer_Change() await grain.StartTimer(testName, delay); - await timerObserver.WaitForTickCountAsync(grain, 1, TimerDiagnosticTimeout); + await AdvanceTimerToTickCountAsync(grain, timerObserver, delay, TimerCallbackDelay, expectedTickCount: 1); int tickCount = await grain.GetTickCount(); Assert.Equal(1, tickCount); await grain.RestartTimer(testName, delay); - await timerObserver.WaitForTickCountAsync(grain, 2, TimerDiagnosticTimeout); + await AdvanceTimerToTickCountAsync(grain, timerObserver, delay, TimerCallbackDelay, expectedTickCount: 2); tickCount = await grain.GetTickCount(); Assert.Equal(2, tickCount); - // Infinite timeouts should be valid. - await grain.RestartTimer(testName, Timeout.InfiniteTimeSpan); - await grain.RestartTimer(testName, Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan); - - // Zero and sub-ms timeouts should be valid (rounded up to 1ms) - await grain.RestartTimer(testName, TimeSpan.Zero); - await grain.RestartTimer(testName, TimeSpan.FromMicroseconds(10)); - await grain.RestartTimer(testName, TimeSpan.Zero, TimeSpan.Zero); - await grain.RestartTimer(testName, TimeSpan.FromMicroseconds(10), TimeSpan.FromMicroseconds(10)); - await grain.RestartTimer(testName, TimeSpan.FromMilliseconds(-0.4)); - await grain.RestartTimer(testName, TimeSpan.FromSeconds(1), TimeSpan.FromMilliseconds(-0.5)); - - // Invalid values - await Assert.ThrowsAsync(async () => await grain.RestartTimer(testName, TimeSpan.FromSeconds(-5))); - await Assert.ThrowsAsync(async () => await grain.RestartTimer(testName, TimeSpan.MaxValue)); - await Assert.ThrowsAsync(async () => await grain.RestartTimer(testName, TimeSpan.FromSeconds(1), TimeSpan.FromSeconds(-5))); - await Assert.ThrowsAsync(async () => await grain.RestartTimer(testName, TimeSpan.FromSeconds(1), TimeSpan.MaxValue)); + await grain.TestTimerChangeArguments(); Exception err = await grain.GetException(); Assert.Null(err); // Should be no exceptions during timer callback @@ -378,13 +490,13 @@ public async Task GrainTimer_Change() // Valid operations called from within a timer: updating the period and disposing the timer. var grain2 = GrainFactory.GetGrain(GetRandomGrainId()); await grain2.StartTimer(testName, delay, "update_period"); - await timerObserver.WaitForTickCountAsync(grain2, 1, TimerDiagnosticTimeout); + await AdvanceTimerToTickCountAsync(grain2, timerObserver, delay, TimerCallbackDelay, expectedTickCount: 1); Assert.Null(await grain2.GetException()); // Should be no exceptions during timer callback Assert.Equal(1, await grain2.GetTickCount()); var grain3 = GrainFactory.GetGrain(GetRandomGrainId()); await grain3.StartTimer(testName, delay, "dispose_timer"); - await timerObserver.WaitForTickCountAsync(grain3, 1, TimerDiagnosticTimeout); + await AdvanceTimerToTickCountAsync(grain3, timerObserver, delay, TimerCallbackDelay, expectedTickCount: 1); var grain3TickCount = await grain3.GetTickCount(); Assert.Null(await grain3.GetException()); // Should be no exceptions during timer callback @@ -406,16 +518,15 @@ public async Task TimerOrleansTest_Basic_Poco() { var grain = GrainFactory.GetGrain(GetRandomGrainId()); var period = await grain.GetTimerPeriod(); - var timeout = period.Multiply(50); - var last = await WaitForCounterAtLeast(grain.GetCounter, 10, timeout, period); + var last = await AdvanceDefaultTimerTicksAsync(grain, period); output.WriteLine("value = " + last); - Assert.True(last >= 10 & last <= 12, last.ToString()); + Assert.Equal(ExpectedDefaultTimerTicks, last); await grain.StopDefaultTimer(); - await Task.Delay(period.Multiply(2)); + fixture.AdvanceTime(period.Multiply(2)); var curr = await grain.GetCounter(); - Assert.True(curr == last || curr == last + 1, "curr == last || curr == last + 1"); + Assert.Equal(last, curr); } } @@ -437,32 +548,13 @@ public async Task TimerOrleansTest_Parallel_Poco() period = await grain.GetTimerPeriod(); // activate grains } - var tasks = new List(grains.Count); - for (int i = 0; i < grains.Count; i++) - { - IPocoTimerGrain grain = grains[i]; - tasks.Add( - Task.Run( - async () => - { - int last = await grain.GetCounter(); - var stopwatch = Stopwatch.StartNew(); - var timeout = period.Multiply(50); - while (stopwatch.Elapsed < timeout && last < 10) - { - await Task.Delay(period.Divide(2)); - last = await grain.GetCounter(); - } - - output.WriteLine("value = " + last); - Assert.True(last >= 10 && last <= 12, "last >= 10 && last <= 12"); - })); - } - - await Task.WhenAll(tasks); + await AdvanceDefaultTimerTicksAsync(grains, period); for (int i = 0; i < grains.Count; i++) { IPocoTimerGrain grain = grains[i]; + var last = await grain.GetCounter(); + output.WriteLine("value = " + last); + Assert.Equal(ExpectedDefaultTimerTicks, last); await grain.StopDefaultTimer(); } } @@ -480,42 +572,22 @@ public async Task TimerOrleansTest_Migration_Poco() TimeSpan period = await grain.GetTimerPeriod(); // Ensure that the grain works as it should. - var last = await grain.GetCounter(); - var stopwatch = Stopwatch.StartNew(); - var timeout = period.Multiply(50); - while (stopwatch.Elapsed < timeout && last < 10) - { - await Task.Delay(period.Divide(2)); - last = await grain.GetCounter(); - } - - last = await grain.GetCounter(); + var last = await AdvanceDefaultTimerTicksAsync(grain, period); + Assert.Equal(ExpectedDefaultTimerTicks, last); output.WriteLine("value = " + last); // Restart the grain. await grain.Deactivate(); - stopwatch.Restart(); last = await grain.GetCounter(); Assert.True(last == 0, "Restarted grains should have zero ticks. Actual: " + last); period = await grain.GetTimerPeriod(); // Poke the grain and ensure it still works as it should. - while (stopwatch.Elapsed < timeout && last < 10) - { - await Task.Delay(period.Divide(2)); - last = await grain.GetCounter(); - } - - last = await grain.GetCounter(); - stopwatch.Stop(); - - int maximalNumTicks = (int)Math.Round(stopwatch.Elapsed.Divide(period), MidpointRounding.ToPositiveInfinity); - Assert.True( - last <= maximalNumTicks, - $"Assert: last <= maximalNumTicks. Actual: last = {last}, maximalNumTicks = {maximalNumTicks}"); + last = await AdvanceDefaultTimerTicksAsync(grain, period); + Assert.Equal(ExpectedDefaultTimerTicks, last); output.WriteLine( - "Total Elapsed time = " + (stopwatch.Elapsed.TotalSeconds) + " sec. Expected Ticks = " + maximalNumTicks + + "Virtual elapsed time = " + (period.Multiply(ExpectedDefaultTimerTicks).TotalSeconds) + " sec. Expected ticks = " + ExpectedDefaultTimerTicks + ". Actual ticks = " + last); } @@ -541,7 +613,7 @@ public async Task AsyncTimerTest_GrainCall_Poco() await grain.StartTimer(testName, delay); - await timerObserver.WaitForTimerTickAsync(grain, TimerDiagnosticTimeout); + await AdvanceTimerToTickCountAsync(grain, timerObserver, delay, TimerCallbackDelay, expectedTickCount: 1); int tickCount = await grain.GetTickCount(); Assert.Equal(1, tickCount); @@ -582,19 +654,11 @@ public async Task GrainTimer_TestAllOverloads_Poco() { var grain = GrainFactory.GetGrain(GetRandomGrainId()); - using var cts = new CancellationTokenSource(TimeSpan.FromSeconds(30)); + using var timerObserver = TimerDiagnosticObserver.Create(); var numTimers = await grain.TestAllTimerOverloads(); - while (true) - { - var completedTimers = await grain.PollCompletedTimers().WaitAsync(cts.Token); - if (completedTimers == numTimers) - { - break; - } - - await Task.Delay(TimeSpan.FromMilliseconds(50), cts.Token); - } - + var waitForTimers = timerObserver.WaitForTickCountAsync(grain, numTimers, TimerDiagnosticTimeout); + fixture.AdvanceTime(TimerOverloadDueTime); + await waitForTimers; await grain.TestCompletedTimerResults(); } @@ -619,7 +683,7 @@ public async Task NonReentrantGrainTimer_Test_Poco() await grain.StartTimer($"{testName}_2", delay); // Invoke some non-interleaving methods while waiting for the timer callbacks. - var externalTicks = await DriveExternalTicksUntilTimerTicks(grain, timerObserver, expectedTimerTicks: 3); + var externalTicks = await DriveExternalTickUntilTimerTicks(grain, timerObserver, delay, expectedTimerTicks: 3); var tickCount = await grain.GetTickCount(); @@ -650,35 +714,19 @@ public async Task GrainTimer_Change_Poco() await grain.StartTimer(testName, delay); - await timerObserver.WaitForTickCountAsync(grain, 1, TimerDiagnosticTimeout); + await AdvanceTimerToTickCountAsync(grain, timerObserver, delay, TimerCallbackDelay, expectedTickCount: 1); int tickCount = await grain.GetTickCount(); Assert.Equal(1, tickCount); await grain.RestartTimer(testName, delay); - await timerObserver.WaitForTickCountAsync(grain, 2, TimerDiagnosticTimeout); + await AdvanceTimerToTickCountAsync(grain, timerObserver, delay, TimerCallbackDelay, expectedTickCount: 2); tickCount = await grain.GetTickCount(); Assert.Equal(2, tickCount); - // Infinite timeouts should be valid. - await grain.RestartTimer(testName, Timeout.InfiniteTimeSpan); - await grain.RestartTimer(testName, Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan); - - // Zero and sub-ms timeouts should be valid (rounded up to 1ms) - await grain.RestartTimer(testName, TimeSpan.Zero); - await grain.RestartTimer(testName, TimeSpan.FromMicroseconds(10)); - await grain.RestartTimer(testName, TimeSpan.Zero, TimeSpan.Zero); - await grain.RestartTimer(testName, TimeSpan.FromMicroseconds(10), TimeSpan.FromMicroseconds(10)); - await grain.RestartTimer(testName, TimeSpan.FromMilliseconds(-0.4)); - await grain.RestartTimer(testName, TimeSpan.FromSeconds(1), TimeSpan.FromMilliseconds(-0.5)); - - // Invalid values - await Assert.ThrowsAsync(async () => await grain.RestartTimer(testName, TimeSpan.FromSeconds(-5))); - await Assert.ThrowsAsync(async () => await grain.RestartTimer(testName, TimeSpan.MaxValue)); - await Assert.ThrowsAsync(async () => await grain.RestartTimer(testName, TimeSpan.FromSeconds(1), TimeSpan.FromSeconds(-5))); - await Assert.ThrowsAsync(async () => await grain.RestartTimer(testName, TimeSpan.FromSeconds(1), TimeSpan.MaxValue)); + await grain.TestTimerChangeArguments(); Exception err = await grain.GetException(); Assert.Null(err); // Should be no exceptions during timer callback @@ -686,13 +734,13 @@ public async Task GrainTimer_Change_Poco() // Valid operations called from within a timer: updating the period and disposing the timer. var grain2 = GrainFactory.GetGrain(GetRandomGrainId()); await grain2.StartTimer(testName, delay, "update_period"); - await timerObserver.WaitForTickCountAsync(grain2, 1, TimerDiagnosticTimeout); + await AdvanceTimerToTickCountAsync(grain2, timerObserver, delay, TimerCallbackDelay, expectedTickCount: 1); Assert.Null(await grain2.GetException()); // Should be no exceptions during timer callback Assert.Equal(1, await grain2.GetTickCount()); var grain3 = GrainFactory.GetGrain(GetRandomGrainId()); await grain3.StartTimer(testName, delay, "dispose_timer"); - await timerObserver.WaitForTickCountAsync(grain3, 1, TimerDiagnosticTimeout); + await AdvanceTimerToTickCountAsync(grain3, timerObserver, delay, TimerCallbackDelay, expectedTickCount: 1); Assert.Null(await grain3.GetException()); // Should be no exceptions during timer callback Assert.Equal(1, await grain3.GetTickCount()); diff --git a/test/TestInfrastructure/TestExtensions/Diagnostics/TimerDiagnosticObserver.cs b/test/TestInfrastructure/TestExtensions/Diagnostics/TimerDiagnosticObserver.cs index 75a5bf8d71d..37d66ecb087 100644 --- a/test/TestInfrastructure/TestExtensions/Diagnostics/TimerDiagnosticObserver.cs +++ b/test/TestInfrastructure/TestExtensions/Diagnostics/TimerDiagnosticObserver.cs @@ -18,6 +18,8 @@ public sealed class TimerDiagnosticObserver : IDisposable, IObserver _tickStartEvents = new(); private readonly ConcurrentBag _tickStopEvents = new(); private readonly ConcurrentBag _disposedEvents = new(); + private readonly object _changeLock = new(); + private TaskCompletionSource _changed = CreateCompletionSource(); private IDisposable? _subscription; /// @@ -65,28 +67,28 @@ private TimerDiagnosticObserver() var effectiveTimeout = timeout ?? TimeSpan.FromSeconds(30); using var cts = new CancellationTokenSource(effectiveTimeout); - var existingMatch = _createdEvents.FirstOrDefault(e => e.GrainContext.GrainId == grainId); - if (existingMatch is not null) + while (true) { - return existingMatch; - } + Task changed; + lock (_changeLock) + { + var existingMatch = _createdEvents.FirstOrDefault(e => e.GrainContext.GrainId == grainId); + if (existingMatch is not null) + { + return existingMatch; + } + + changed = _changed.Task; + } - while (!cts.Token.IsCancellationRequested) - { try { - await Task.Delay(10, cts.Token); + await changed.WaitAsync(cts.Token); } catch (OperationCanceledException) { break; } - - var match = _createdEvents.FirstOrDefault(e => e.GrainContext.GrainId == grainId); - if (match is not null) - { - return match; - } } throw new TimeoutException($"Timed out waiting for timer creation on grain {grainId} after {effectiveTimeout}"); @@ -103,28 +105,28 @@ private TimerDiagnosticObserver() var effectiveTimeout = timeout ?? TimeSpan.FromSeconds(30); using var cts = new CancellationTokenSource(effectiveTimeout); - var existingMatch = _tickStopEvents.FirstOrDefault(e => e.GrainContext.GrainId == grainId); - if (existingMatch is not null) + while (true) { - return existingMatch; - } + Task changed; + lock (_changeLock) + { + var existingMatch = _tickStopEvents.FirstOrDefault(e => e.GrainContext.GrainId == grainId); + if (existingMatch is not null) + { + return existingMatch; + } + + changed = _changed.Task; + } - while (!cts.Token.IsCancellationRequested) - { try { - await Task.Delay(10, cts.Token); + await changed.WaitAsync(cts.Token); } catch (OperationCanceledException) { break; } - - var match = _tickStopEvents.FirstOrDefault(e => e.GrainContext.GrainId == grainId); - if (match is not null) - { - return match; - } } throw new TimeoutException($"Timed out waiting for timer tick on grain {grainId} after {effectiveTimeout}"); @@ -141,28 +143,28 @@ private TimerDiagnosticObserver() var effectiveTimeout = timeout ?? TimeSpan.FromSeconds(30); using var cts = new CancellationTokenSource(effectiveTimeout); - var existingMatch = _tickStopEvents.FirstOrDefault(e => GetGrainTypeName(e.GrainContext).Contains(grainTypeName, StringComparison.OrdinalIgnoreCase)); - if (existingMatch is not null) + while (true) { - return existingMatch; - } + Task changed; + lock (_changeLock) + { + var existingMatch = _tickStopEvents.FirstOrDefault(e => GetGrainTypeName(e.GrainContext).Contains(grainTypeName, StringComparison.OrdinalIgnoreCase)); + if (existingMatch is not null) + { + return existingMatch; + } + + changed = _changed.Task; + } - while (!cts.Token.IsCancellationRequested) - { try { - await Task.Delay(10, cts.Token); + await changed.WaitAsync(cts.Token); } catch (OperationCanceledException) { break; } - - var match = _tickStopEvents.FirstOrDefault(e => GetGrainTypeName(e.GrainContext).Contains(grainTypeName, StringComparison.OrdinalIgnoreCase)); - if (match is not null) - { - return match; - } } throw new TimeoutException($"Timed out waiting for timer tick on grain type '{grainTypeName}' after {effectiveTimeout}"); @@ -179,28 +181,28 @@ private TimerDiagnosticObserver() var effectiveTimeout = timeout ?? TimeSpan.FromSeconds(30); using var cts = new CancellationTokenSource(effectiveTimeout); - var existingMatch = _disposedEvents.FirstOrDefault(e => e.GrainContext.GrainId == grainId); - if (existingMatch is not null) + while (true) { - return existingMatch; - } + Task changed; + lock (_changeLock) + { + var existingMatch = _disposedEvents.FirstOrDefault(e => e.GrainContext.GrainId == grainId); + if (existingMatch is not null) + { + return existingMatch; + } + + changed = _changed.Task; + } - while (!cts.Token.IsCancellationRequested) - { try { - await Task.Delay(10, cts.Token); + await changed.WaitAsync(cts.Token); } catch (OperationCanceledException) { break; } - - var match = _disposedEvents.FirstOrDefault(e => e.GrainContext.GrainId == grainId); - if (match is not null) - { - return match; - } } throw new TimeoutException($"Timed out waiting for timer disposal on grain {grainId} after {effectiveTimeout}"); @@ -219,17 +221,23 @@ public async Task WaitForTickCountAsync(GrainId grainId, int expectedCount, Time var effectiveTimeout = timeout ?? TimeSpan.FromSeconds(60); using var cts = new CancellationTokenSource(effectiveTimeout); - while (!cts.Token.IsCancellationRequested) + while (true) { - var currentCount = GetTickCount(grainId); - if (currentCount >= expectedCount) + Task changed; + lock (_changeLock) { - return; + var currentCount = GetTickCount(grainId); + if (currentCount >= expectedCount) + { + return; + } + + changed = _changed.Task; } try { - await Task.Delay(10, cts.Token); + await changed.WaitAsync(cts.Token); } catch (OperationCanceledException) { @@ -246,6 +254,52 @@ public async Task WaitForTickCountAsync(GrainId grainId, int expectedCount, Time throw new TimeoutException($"Timed out waiting for {expectedCount} timer ticks on grain {grainId}. Current count: {finalCount} after {effectiveTimeout}"); } + /// + /// Waits for a specific number of timer ticks to start on a grain. + /// + /// The grain ID to wait for. + /// The minimum number of tick starts to wait for. + /// Maximum time to wait. Defaults to 60 seconds. + /// A task that completes when the expected count is reached. + /// Thrown if the expected count is not reached within the timeout. + public async Task WaitForTickStartCountAsync(GrainId grainId, int expectedCount, TimeSpan? timeout = null) + { + var effectiveTimeout = timeout ?? TimeSpan.FromSeconds(60); + using var cts = new CancellationTokenSource(effectiveTimeout); + + while (true) + { + Task changed; + lock (_changeLock) + { + var currentCount = GetTickStartCount(grainId); + if (currentCount >= expectedCount) + { + return; + } + + changed = _changed.Task; + } + + try + { + await changed.WaitAsync(cts.Token); + } + catch (OperationCanceledException) + { + break; + } + } + + var finalCount = GetTickStartCount(grainId); + if (finalCount >= expectedCount) + { + return; + } + + throw new TimeoutException($"Timed out waiting for {expectedCount} timer tick starts on grain {grainId}. Current count: {finalCount} after {effectiveTimeout}"); + } + /// /// Waits for a specific number of timer ticks to complete on any grain of the specified type. /// @@ -259,17 +313,23 @@ public async Task WaitForTickCountByGrainTypeAsync(string grainTypeName, int exp var effectiveTimeout = timeout ?? TimeSpan.FromSeconds(60); using var cts = new CancellationTokenSource(effectiveTimeout); - while (!cts.Token.IsCancellationRequested) + while (true) { - var currentCount = GetTickCountByGrainType(grainTypeName); - if (currentCount >= expectedCount) + Task changed; + lock (_changeLock) { - return; + var currentCount = GetTickCountByGrainType(grainTypeName); + if (currentCount >= expectedCount) + { + return; + } + + changed = _changed.Task; } try { - await Task.Delay(10, cts.Token); + await changed.WaitAsync(cts.Token); } catch (OperationCanceledException) { @@ -296,6 +356,16 @@ public int GetTickCount(GrainId grainId) return _tickStopEvents.Count(e => e.GrainContext.GrainId == grainId); } + /// + /// Gets the count of timer tick starts for a specific grain. + /// + /// The grain ID to filter by. + /// The count of timer tick start events. + public int GetTickStartCount(GrainId grainId) + { + return _tickStartEvents.Count(e => e.GrainContext.GrainId == grainId); + } + /// /// Gets the count of timer ticks for a specific grain type. /// @@ -325,6 +395,7 @@ public void Clear() _tickStartEvents.Clear(); _tickStopEvents.Clear(); _disposedEvents.Clear(); + SignalChanged(); } void IObserver.OnNext(GrainTimerEvents.TimerEvent value) @@ -344,6 +415,8 @@ public void Clear() _disposedEvents.Add(disposed); break; } + + SignalChanged(); } void IObserver.OnError(Exception error) @@ -360,6 +433,20 @@ public void Dispose() } private static string GetGrainTypeName(IGrainContext grainContext) => grainContext.GrainId.Type.ToString()!; + + private static TaskCompletionSource CreateCompletionSource() => new(TaskCreationOptions.RunContinuationsAsynchronously); + + private void SignalChanged() + { + TaskCompletionSource changed; + lock (_changeLock) + { + changed = _changed; + _changed = CreateCompletionSource(); + } + + changed.TrySetResult(); + } } /// @@ -391,6 +478,14 @@ public static Task WaitForTickCountAsync(this TimerDiagnosticObserver observer, return observer.WaitForTickCountAsync(grain.GetGrainId(), expectedCount, timeout); } + /// + /// Waits for a specific number of timer ticks to start on a grain. + /// + public static Task WaitForTickStartCountAsync(this TimerDiagnosticObserver observer, IAddressable grain, int expectedCount, TimeSpan? timeout = null) + { + return observer.WaitForTickStartCountAsync(grain.GetGrainId(), expectedCount, timeout); + } + /// /// Waits for timer disposal on a grain. /// From 2aa9e78d9c3abbcc8f20dcdf9d8f944d7d95274e Mon Sep 17 00:00:00 2001 From: Reuben Bond Date: Fri, 12 Jun 2026 08:36:28 -0700 Subject: [PATCH 2/3] test: address timer review comments Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- test/Grains/TestInternalGrains/TimerGrain.cs | 22 ++++---------------- 1 file changed, 4 insertions(+), 18 deletions(-) diff --git a/test/Grains/TestInternalGrains/TimerGrain.cs b/test/Grains/TestInternalGrains/TimerGrain.cs index 640f56a9fd0..3098d3ddd9c 100644 --- a/test/Grains/TestInternalGrains/TimerGrain.cs +++ b/test/Grains/TestInternalGrains/TimerGrain.cs @@ -277,19 +277,12 @@ public Task TestTimerChangeArguments() private void ValidateTimerChangeArguments(TimeSpan dueTime, TimeSpan period) { - var timer = this.RegisterGrainTimer(_ => Task.CompletedTask, new GrainTimerCreationOptions(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan) + using var validationTimer = this.RegisterGrainTimer(_ => Task.CompletedTask, new GrainTimerCreationOptions(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan) { Interleave = true }); - try - { - timer.Change(dueTime, period); - } - finally - { - timer.Dispose(); - } + validationTimer.Change(dueTime, period); } public Task StopTimer(string name) @@ -977,19 +970,12 @@ public Task TestTimerChangeArguments() private void ValidateTimerChangeArguments(TimeSpan dueTime, TimeSpan period) { - var timer = this.RegisterGrainTimer(_ => Task.CompletedTask, new GrainTimerCreationOptions(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan) + using var validationTimer = this.RegisterGrainTimer(_ => Task.CompletedTask, new GrainTimerCreationOptions(Timeout.InfiniteTimeSpan, Timeout.InfiniteTimeSpan) { Interleave = true }); - try - { - timer.Change(dueTime, period); - } - finally - { - timer.Dispose(); - } + validationTimer.Change(dueTime, period); } public Task StopTimer(string name) From 338bbfee09843587ac0e3b5128d62357f7e7d9c1 Mon Sep 17 00:00:00 2001 From: Reuben Bond Date: Fri, 12 Jun 2026 09:26:31 -0700 Subject: [PATCH 3/3] test: make timer fake-time waits deterministic Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- test/Grains/TestInternalGrains/TimerGrain.cs | 43 +++++++++++-------- .../TimerOrleansTest.cs | 24 +++++------ 2 files changed, 37 insertions(+), 30 deletions(-) diff --git a/test/Grains/TestInternalGrains/TimerGrain.cs b/test/Grains/TestInternalGrains/TimerGrain.cs index 3098d3ddd9c..483ee757148 100644 --- a/test/Grains/TestInternalGrains/TimerGrain.cs +++ b/test/Grains/TestInternalGrains/TimerGrain.cs @@ -28,13 +28,13 @@ public abstract class CallbackEvent(GrainId grainId) public readonly GrainId GrainId = grainId; } - public sealed class DelayStarted(GrainId grainId) : CallbackEvent(grainId) + public sealed class DelayScheduled(GrainId grainId) : CallbackEvent(grainId) { } - internal static void EmitDelayStarted(GrainId grainId) + internal static void EmitDelayScheduled(GrainId grainId) { - if (!Listener.IsEnabled(nameof(DelayStarted))) + if (!Listener.IsEnabled(nameof(DelayScheduled))) { return; } @@ -44,7 +44,7 @@ internal static void EmitDelayStarted(GrainId grainId) [MethodImpl(MethodImplOptions.NoInlining)] static void Emit(GrainId grainId) { - Listener.Write(nameof(DelayStarted), new DelayStarted(grainId)); + Listener.Write(nameof(DelayScheduled), new DelayScheduled(grainId)); } } @@ -311,8 +311,9 @@ public async Task RunSelfDisposingTimer() Assert.NotNull(timer[0]); timer[0].Dispose(); Assert.True(ct.IsCancellationRequested); - TimerGrainCallbackEvents.EmitDelayStarted(context.GrainId); - await Task.Delay(TimeSpan.FromMilliseconds(100), timeProvider); + var delay = Task.Delay(TimeSpan.FromMilliseconds(100), timeProvider); + TimerGrainCallbackEvents.EmitDelayScheduled(context.GrainId); + await delay; tcs.TrySetResult(); } catch (Exception ex) @@ -390,8 +391,9 @@ private async Task ProcessTimerTick(object data) CheckRuntimeContext(step); LogStatus("Before Delay"); - TimerGrainCallbackEvents.EmitDelayStarted(context.GrainId); - await Task.Delay(TimerGrainTestConstants.CallbackDelay, timeProvider); + var delay = Task.Delay(TimerGrainTestConstants.CallbackDelay, timeProvider); + TimerGrainCallbackEvents.EmitDelayScheduled(context.GrainId); + await delay; step = "After Delay"; LogStatus(step); CheckRuntimeContext(step); @@ -540,8 +542,9 @@ private async Task ProcessTimerTick(object data, CancellationToken cancellationT CheckReentrancy(step, expectedTickId); LogStatus("Before Delay", timerName); - TimerGrainCallbackEvents.EmitDelayStarted(_context.GrainId); - await Task.Delay(TimerGrainTestConstants.CallbackDelay, _timeProvider); + var delay = Task.Delay(TimerGrainTestConstants.CallbackDelay, _timeProvider); + TimerGrainCallbackEvents.EmitDelayScheduled(_context.GrainId); + await delay; step = "After Delay"; LogStatus(step, timerName); CheckRuntimeContext(step); @@ -1004,8 +1007,9 @@ public async Task RunSelfDisposingTimer() Assert.NotNull(timer[0]); timer[0].Dispose(); Assert.True(ct.IsCancellationRequested); - TimerGrainCallbackEvents.EmitDelayStarted(context.GrainId); - await Task.Delay(TimeSpan.FromMilliseconds(100), _timeProvider); + var delay = Task.Delay(TimeSpan.FromMilliseconds(100), _timeProvider); + TimerGrainCallbackEvents.EmitDelayScheduled(context.GrainId); + await delay; tcs.TrySetResult(); } catch (Exception ex) @@ -1083,8 +1087,9 @@ private async Task ProcessTimerTick(object data) CheckRuntimeContext(step); LogStatus("Before Delay"); - TimerGrainCallbackEvents.EmitDelayStarted(context.GrainId); - await Task.Delay(TimerGrainTestConstants.CallbackDelay, _timeProvider); + var delay = Task.Delay(TimerGrainTestConstants.CallbackDelay, _timeProvider); + TimerGrainCallbackEvents.EmitDelayScheduled(context.GrainId); + await delay; step = "After Delay"; LogStatus(step); CheckRuntimeContext(step); @@ -1338,8 +1343,9 @@ public async Task RunSelfDisposingTimer() Assert.NotNull(timer[0]); timer[0].Dispose(); tcs.TrySetResult(); - TimerGrainCallbackEvents.EmitDelayStarted(_context.GrainId); - await Task.Delay(TimeSpan.FromMilliseconds(100), _timeProvider); + var delay = Task.Delay(TimeSpan.FromMilliseconds(100), _timeProvider); + TimerGrainCallbackEvents.EmitDelayScheduled(_context.GrainId); + await delay; } catch (Exception ex) { @@ -1416,8 +1422,9 @@ private async Task ProcessTimerTick(object data, CancellationToken cancellationT CheckReentrancy(step, expectedTickId); LogStatus("Before Delay", timerName); - TimerGrainCallbackEvents.EmitDelayStarted(_context.GrainId); - await Task.Delay(TimerGrainTestConstants.CallbackDelay, _timeProvider); + var delay = Task.Delay(TimerGrainTestConstants.CallbackDelay, _timeProvider); + TimerGrainCallbackEvents.EmitDelayScheduled(_context.GrainId); + await delay; step = "After Delay"; LogStatus(step, timerName); CheckRuntimeContext(step); diff --git a/test/Orleans.DefaultCluster.Tests/TimerOrleansTest.cs b/test/Orleans.DefaultCluster.Tests/TimerOrleansTest.cs index aadcf619d73..011ee79d88f 100644 --- a/test/Orleans.DefaultCluster.Tests/TimerOrleansTest.cs +++ b/test/Orleans.DefaultCluster.Tests/TimerOrleansTest.cs @@ -91,13 +91,13 @@ private async Task AdvanceTimerToTickCountAsync( { using var callbackObserver = TimerCallbackDiagnosticObserver.Create(); var grainId = grain.GetGrainId(); - var delayStartedCount = callbackObserver.GetDelayStartedCount(grainId); + var delayScheduledCount = callbackObserver.GetDelayScheduledCount(grainId); fixture.AdvanceTime(dueTime); for (var tickCount = timerObserver.GetTickCount(grain.GetGrainId()) + 1; tickCount <= expectedTickCount; tickCount++) { await timerObserver.WaitForTickStartCountAsync(grain, tickCount, TimerDiagnosticTimeout); - await callbackObserver.WaitForDelayStartedCountAsync(grainId, ++delayStartedCount, TimerDiagnosticTimeout); + await callbackObserver.WaitForDelayScheduledCountAsync(grainId, ++delayScheduledCount, TimerDiagnosticTimeout); var waitForTickStop = timerObserver.WaitForTickCountAsync(grain, tickCount, TimerDiagnosticTimeout); fixture.AdvanceTime(callbackDelay); @@ -110,7 +110,7 @@ private async Task DriveExternalTickUntilTimerTicks(INonReentrantTimerCallG using var callbackObserver = TimerCallbackDiagnosticObserver.Create(); var grainId = grain.GetGrainId(); var externalTick = grain.ExternalTick("external"); - await callbackObserver.WaitForDelayStartedCountAsync(grainId, callbackObserver.GetDelayStartedCount(grainId) + 1, TimerDiagnosticTimeout); + await callbackObserver.WaitForDelayScheduledCountAsync(grainId, callbackObserver.GetDelayScheduledCount(grainId) + 1, TimerDiagnosticTimeout); fixture.AdvanceTime(TimerCallbackDelay); await externalTick; await AdvanceTimerToTickCountAsync(grain, timerObserver, dueTime, TimerCallbackDelay, expectedTimerTicks); @@ -128,7 +128,7 @@ private async Task RunSelfDisposingTimerAsync(ITimerCallGrain grain) private sealed class TimerCallbackDiagnosticObserver : IDisposable, IObserver { - private readonly ConcurrentBag delayStartedEvents = new(); + private readonly ConcurrentBag delayScheduledEvents = new(); private readonly object changeLock = new(); private TaskCompletionSource changed = CreateCompletionSource(); private IDisposable subscription; @@ -140,12 +140,12 @@ public static TimerCallbackDiagnosticObserver Create() return observer; } - public int GetDelayStartedCount(GrainId grainId) + public int GetDelayScheduledCount(GrainId grainId) { - return delayStartedEvents.Count(e => e.GrainId == grainId); + return delayScheduledEvents.Count(e => e.GrainId == grainId); } - public async Task WaitForDelayStartedCountAsync(GrainId grainId, int expectedCount, TimeSpan timeout) + public async Task WaitForDelayScheduledCountAsync(GrainId grainId, int expectedCount, TimeSpan timeout) { using var cts = new CancellationTokenSource(timeout); @@ -154,7 +154,7 @@ public async Task WaitForDelayStartedCountAsync(GrainId grainId, int expectedCou Task changedTask; lock (changeLock) { - var currentCount = GetDelayStartedCount(grainId); + var currentCount = GetDelayScheduledCount(grainId); if (currentCount >= expectedCount) { return; @@ -173,20 +173,20 @@ public async Task WaitForDelayStartedCountAsync(GrainId grainId, int expectedCou } } - var finalCount = GetDelayStartedCount(grainId); + var finalCount = GetDelayScheduledCount(grainId); if (finalCount >= expectedCount) { return; } - throw new TimeoutException($"Timed out waiting for {expectedCount} timer callbacks to reach their fake delay on grain {grainId}. Current count: {finalCount} after {timeout}"); + throw new TimeoutException($"Timed out waiting for {expectedCount} timer callbacks to schedule their fake delay on grain {grainId}. Current count: {finalCount} after {timeout}"); } void IObserver.OnNext(TimerGrainCallbackEvents.CallbackEvent value) { - if (value is TimerGrainCallbackEvents.DelayStarted delayStarted) + if (value is TimerGrainCallbackEvents.DelayScheduled delayScheduled) { - delayStartedEvents.Add(delayStarted); + delayScheduledEvents.Add(delayScheduled); SignalChanged(); } }