From a0c7a13bff297b5af5bb32036bfa576cd25c2482 Mon Sep 17 00:00:00 2001 From: James Hickey Date: Fri, 26 Jan 2024 17:05:37 -0400 Subject: [PATCH] Fix Missed Ticks In Scheduler (#359) * scheduler catch-up with missed ticks * fix demo prj to reproduce issue --- Demo/.dockerignore | 25 ++++ Demo/Demo.csproj | 3 +- Demo/Dockerfile | 22 ++++ Demo/Startup.cs | 45 ++++--- Demo/appsettings.json | 2 +- .../Scheduling/HostedService/SchedulerHost.cs | 29 ++++- .../Schedule/EnsureContinuousSecondTicks.cs | 46 +++++++ .../Schedule/Helpers/DateHelpers.cs | 4 +- Src/Coravel/Scheduling/Schedule/Scheduler.cs | 6 - .../EnsureContinuousSecondTicksTests.cs | 116 ++++++++++++++++++ .../SchedulerEventDispatcherTests.cs | 2 +- 11 files changed, 272 insertions(+), 28 deletions(-) create mode 100644 Demo/.dockerignore create mode 100644 Demo/Dockerfile create mode 100644 Src/Coravel/Scheduling/Schedule/EnsureContinuousSecondTicks.cs create mode 100644 Src/UnitTests/CoravelUnitTests/Scheduling/EnsureContinuousSecondTicksTests.cs diff --git a/Demo/.dockerignore b/Demo/.dockerignore new file mode 100644 index 00000000..cd967fc3 --- /dev/null +++ b/Demo/.dockerignore @@ -0,0 +1,25 @@ +**/.dockerignore +**/.env +**/.git +**/.gitignore +**/.project +**/.settings +**/.toolstarget +**/.vs +**/.vscode +**/.idea +**/*.*proj.user +**/*.dbmdl +**/*.jfm +**/azds.yaml +**/bin +**/charts +**/docker-compose* +**/Dockerfile* +**/node_modules +**/npm-debug.log +**/obj +**/secrets.dev.yaml +**/values.dev.yaml +LICENSE +README.md \ No newline at end of file diff --git a/Demo/Demo.csproj b/Demo/Demo.csproj index 652fcf9c..646d419e 100644 --- a/Demo/Demo.csproj +++ b/Demo/Demo.csproj @@ -1,7 +1,8 @@ - netcoreapp2.1 + net6.0 + Linux diff --git a/Demo/Dockerfile b/Demo/Dockerfile new file mode 100644 index 00000000..49484670 --- /dev/null +++ b/Demo/Dockerfile @@ -0,0 +1,22 @@ +FROM mcr.microsoft.com/dotnet/aspnet:6.0 AS base +WORKDIR /app +EXPOSE 80 +EXPOSE 443 + +FROM mcr.microsoft.com/dotnet/sdk:6.0 AS build +ARG BUILD_CONFIGURATION=Release +WORKDIR /src +COPY ["Demo.csproj", "./"] +RUN dotnet restore "Demo.csproj" +COPY . . +WORKDIR "/src/" +RUN dotnet build "Demo.csproj" -c $BUILD_CONFIGURATION -o /app/build + +FROM build AS publish +ARG BUILD_CONFIGURATION=Release +RUN dotnet publish "Demo.csproj" -c $BUILD_CONFIGURATION -o /app/publish /p:UseAppHost=false + +FROM base AS final +WORKDIR /app +COPY --from=publish /app/publish . +ENTRYPOINT ["dotnet", "Demo.dll"] diff --git a/Demo/Startup.cs b/Demo/Startup.cs index 7789af00..6d9f14a9 100644 --- a/Demo/Startup.cs +++ b/Demo/Startup.cs @@ -1,4 +1,5 @@ using System; +using System.Threading; using Coravel; using Coravel.Events.Interfaces; using Coravel.Queuing.Interfaces; @@ -42,7 +43,7 @@ public void ConfigureServices(IServiceCollection services) services.AddQueue(); // Coravel Caching - services.AddSQLServerCache(this.Configuration.GetConnectionString("DefaultConnection")); + //services.AddSQLServerCache(this.Configuration.GetConnectionString("DefaultConnection")); // services.AddPostgreSQLCache(this.Configuration.GetConnectionString("PostGreSQL")); // Coravel Mail @@ -74,12 +75,12 @@ public void Configure(IApplicationBuilder app, IHostingEnvironment env) app.UseStaticFiles(); app.UseCookiePolicy(); - app.UseMvc(routes => - { - routes.MapRoute( - name: "default", - template: "{controller=Home}/{action=Index}/{id?}"); - }); + // app.UseMvc(routes => + // { + // routes.MapRoute( + // name: "default", + // template: "{controller=Home}/{action=Index}/{id?}"); + // }); IEventRegistration registration = app.ApplicationServices.ConfigureEvents(); @@ -94,15 +95,27 @@ public void Configure(IApplicationBuilder app, IHostingEnvironment env) .Schedule().Hourly(); scheduler.OnWorker("TestingSeconds"); - scheduler.Schedule( - () => Console.WriteLine($"Runs every second. Ran at: {DateTime.UtcNow}") - ).EverySecond(); - scheduler.Schedule(() => Console.WriteLine($"Runs every thirty seconds. Ran at: {DateTime.UtcNow}")).EveryThirtySeconds().Zoned(TimeZoneInfo.Local); - scheduler.Schedule(() => Console.WriteLine($"Runs every ten seconds. Ran at: {DateTime.UtcNow}")).EveryTenSeconds(); - scheduler.Schedule(() => Console.WriteLine($"Runs every fifteen seconds. Ran at: {DateTime.UtcNow}")).EveryFifteenSeconds(); - scheduler.Schedule(() => Console.WriteLine($"Runs every thirty seconds. Ran at: {DateTime.UtcNow}")).EveryThirtySeconds(); - scheduler.Schedule(() => Console.WriteLine($"Runs every minute Ran at: {DateTime.UtcNow}")).EveryMinute(); - scheduler.Schedule(() => Console.WriteLine($"Runs every 2nd minute Ran at: {DateTime.UtcNow}")).Cron("*/2 * * * *"); + // scheduler.Schedule( + // () => Console.WriteLine($"Runs every second. Ran at: {DateTime.UtcNow}") + // ).EverySecond(); + // scheduler.Schedule(() => Console.WriteLine($"Runs every thirty seconds. Ran at: {DateTime.UtcNow}")).EveryThirtySeconds().Zoned(TimeZoneInfo.Local); + // scheduler.Schedule(() => Console.WriteLine($"Runs every ten seconds. Ran at: {DateTime.UtcNow}")).EveryTenSeconds(); + // scheduler.Schedule(() => Console.WriteLine($"Runs every fifteen seconds. Ran at: {DateTime.UtcNow}")).EveryFifteenSeconds(); + // scheduler.Schedule(() => Console.WriteLine($"Runs every thirty seconds. Ran at: {DateTime.UtcNow}")).EveryThirtySeconds(); + // scheduler.Schedule(() => Console.WriteLine($"Runs every minute Ran at: {DateTime.UtcNow}")).EveryMinute(); + // scheduler.Schedule(() => Console.WriteLine($"Runs every 2nd minute Ran at: {DateTime.UtcNow}")).Cron("*/2 * * * *"); + + + scheduler.Schedule(() => Thread.Sleep(5000)).EverySecond(); + scheduler.Schedule(() => Thread.Sleep(5000)).EverySecond(); + scheduler.Schedule(() => Thread.Sleep(5000)).EverySecond(); + scheduler.Schedule(() => Thread.Sleep(5000)).EverySecond(); + scheduler.Schedule(() => Thread.Sleep(5000)).EverySecond(); + scheduler.Schedule(() => Thread.Sleep(5000)).EverySecond(); + scheduler.Schedule(() => Thread.Sleep(5000)).EverySecond(); + scheduler.Schedule(() => Thread.Sleep(5000)).EverySecond(); + scheduler.Schedule(() => Thread.Sleep(5000)).EverySecond(); + scheduler.Schedule(() => Thread.Sleep(5000)).EverySecond(); }); app.ApplicationServices diff --git a/Demo/appsettings.json b/Demo/appsettings.json index def9159a..6a845cfd 100644 --- a/Demo/appsettings.json +++ b/Demo/appsettings.json @@ -1,7 +1,7 @@ { "Logging": { "LogLevel": { - "Default": "Warning" + "Default": "Information" } }, "AllowedHosts": "*" diff --git a/Src/Coravel/Scheduling/HostedService/SchedulerHost.cs b/Src/Coravel/Scheduling/HostedService/SchedulerHost.cs index 3e4826d8..42861fc8 100644 --- a/Src/Coravel/Scheduling/HostedService/SchedulerHost.cs +++ b/Src/Coravel/Scheduling/HostedService/SchedulerHost.cs @@ -1,4 +1,6 @@ using System; +using System.Collections.Generic; +using System.Linq; using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.Hosting; @@ -15,6 +17,8 @@ internal class SchedulerHost : IHostedService, IDisposable private bool _schedulerEnabled = true; private ILogger _logger; private IHostApplicationLifetime _lifetime; + private object _tickLockObj = new object(); + private EnsureContinuousSecondTicks _ensureContinuousSecondTicks; private readonly string ScheduledTasksRunningMessage = "Coravel's Scheduling service is attempting to close but there are tasks still running." + " App closing (in background) will be prevented until all tasks are completed."; @@ -23,6 +27,7 @@ public SchedulerHost(IScheduler scheduler, ILogger logger, IHostA this._scheduler = scheduler as Scheduler; this._logger = logger; this._lifetime = lifetime; + this._ensureContinuousSecondTicks = new EnsureContinuousSecondTicks(DateTime.UtcNow); } public Task StartAsync(CancellationToken cancellationToken) @@ -44,7 +49,29 @@ private async void RunSchedulerPerSecondAsync(object state) { if (this._schedulerEnabled) { - await this._scheduler.RunSchedulerAsync(); + // This will get any missed ticks that might arise from the Timer triggering a little too late. + // If under CPU load or if the Timer is for some reason a little slow, then it's possible to + // miss a tick - which we want to make sure the scheduler doesn't miss and catches up. + var now = DateTime.UtcNow; + DateTime[] ticks = null; + lock (_tickLockObj) + { + // This class isn't thread-safe. + ticks = this._ensureContinuousSecondTicks.GetTicksBetweenPreviousAndNext(now).ToArray(); + this._ensureContinuousSecondTicks.SetNextTick(now); + } + + if (ticks.Length > 0) + { + this._logger.LogInformation($"Coravel's scheduler is behind {ticks.Length} ticks and is catching-up to the current tick. Triggered at {now.ToString("o")}."); + foreach (var tick in ticks) + { + await this._scheduler.RunAtAsync(tick); + } + } + + // If we've processed any missed ticks, we also need to explicitly run the current tick. + await this._scheduler.RunAtAsync(now); } } diff --git a/Src/Coravel/Scheduling/Schedule/EnsureContinuousSecondTicks.cs b/Src/Coravel/Scheduling/Schedule/EnsureContinuousSecondTicks.cs new file mode 100644 index 00000000..e3bc6cd6 --- /dev/null +++ b/Src/Coravel/Scheduling/Schedule/EnsureContinuousSecondTicks.cs @@ -0,0 +1,46 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using Coravel.Scheduling.Schedule.Helpers; + +namespace Coravel.Scheduling.Schedule; + +public class EnsureContinuousSecondTicks +{ + private DateTime previousTick; + + public EnsureContinuousSecondTicks(DateTime firstTick) + { + previousTick = firstTick; + } + + /// + /// Give this method when the next tick occurs and it will return any intermediary ticks that should + /// have existed been the stored previous tick and the next one. + /// + /// + /// + public IEnumerable GetTicksBetweenPreviousAndNext(DateTime nextTick) + { + // Starting at previousTick, we move ahead one second a time and record the next time until we get to the "nextTick". + // Then we check if there are any missed ticks between the two. + List missingTicks = null; // We don't want to commit any memory until we know for sure there's at least 1 missed tick. + DateTime nextTickToTest = previousTick.PreciseUpToSecond().AddSeconds(1); + while (nextTickToTest < nextTick.PreciseUpToSecond()) + { + if (missingTicks is null) + { + missingTicks = new List(); + } + missingTicks.Add(nextTickToTest); + nextTickToTest = nextTickToTest.PreciseUpToSecond().AddSeconds(1); + } + + return missingTicks ?? Enumerable.Empty(); + } + + public void SetNextTick(DateTime nextTick) + { + previousTick = nextTick; + } +} diff --git a/Src/Coravel/Scheduling/Schedule/Helpers/DateHelpers.cs b/Src/Coravel/Scheduling/Schedule/Helpers/DateHelpers.cs index 2a0485a1..8c64ac4a 100644 --- a/Src/Coravel/Scheduling/Schedule/Helpers/DateHelpers.cs +++ b/Src/Coravel/Scheduling/Schedule/Helpers/DateHelpers.cs @@ -4,8 +4,8 @@ namespace Coravel.Scheduling.Schedule.Helpers { public static class DateHelpers { - public static DateTime PreciseUpToMinute(this DateTime me) { - return new DateTime(me.Year, me.Month, me.Day, me.Hour, me.Minute, 0); + public static DateTime PreciseUpToSecond(this DateTime me) { + return new DateTime(me.Year, me.Month, me.Day, me.Hour, me.Minute, me.Second, DateTimeKind.Utc); } } } \ No newline at end of file diff --git a/Src/Coravel/Scheduling/Schedule/Scheduler.cs b/Src/Coravel/Scheduling/Schedule/Scheduler.cs index b8bd81ed..c6e2e7c7 100644 --- a/Src/Coravel/Scheduling/Schedule/Scheduler.cs +++ b/Src/Coravel/Scheduling/Schedule/Scheduler.cs @@ -99,12 +99,6 @@ public IScheduler OnWorker(string workerName) return this; } - public async Task RunSchedulerAsync() - { - DateTime utcNow = DateTime.UtcNow; - await this.RunAtAsync(utcNow); - } - public async Task RunAtAsync(DateTime utcDate) { Interlocked.Increment(ref this._schedulerIterationsActiveCount); diff --git a/Src/UnitTests/CoravelUnitTests/Scheduling/EnsureContinuousSecondTicksTests.cs b/Src/UnitTests/CoravelUnitTests/Scheduling/EnsureContinuousSecondTicksTests.cs new file mode 100644 index 00000000..84ef0d32 --- /dev/null +++ b/Src/UnitTests/CoravelUnitTests/Scheduling/EnsureContinuousSecondTicksTests.cs @@ -0,0 +1,116 @@ +using System; +using System.Linq; +using Coravel.Scheduling.Schedule; +using Xunit; + +namespace CoravelUnitTests.Scheduling; + +public class EnsureContinuousSecondTicksTests +{ + public const int SecondsInMinute = 60; + public const int SecondsInHour = 60 * 60; + public const int SecondsInDay = 60 * 60 * 24; + + [Theory] + // 1 second difference: no missing ticks + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T12:00:01.0000000Z")] + [InlineData("2024-01-12T12:00:00.2000000Z", "2024-01-12T12:00:01.2000000Z")] + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T12:00:01.9990000Z")] + [InlineData("2009-05-22T22:22:22.0000000Z", "2009-05-22T22:22:23.9999999Z")] + + // Having less than a second between: no missing ticks + [InlineData("2009-05-22T22:22:22.0000000Z", "2009-05-22T22:22:22.9999999Z")] + [InlineData("2009-05-22T23:59:59.0000000Z", "2009-05-22T23:59:59.9999999Z")] + + // Negative ticks + [InlineData("2009-05-22T23:59:59.9999999Z", "2009-05-22T23:59:59.0000000Z")] + [InlineData("2009-05-22T23:59:59.9999999Z", "2009-05-22T23:59:58.9999999Z")] + [InlineData("2009-05-22T23:59:59.9999999Z", "2009-05-22T23:58:59.9999999Z")] + [InlineData("2009-05-22T23:59:59.9999999Z", "2009-05-22T22:59:59.9999999Z")] + [InlineData("2009-05-22T23:59:59.9999999Z", "2009-05-21T23:59:59.9999999Z")] + [InlineData("2009-05-22T23:59:59.9999999Z", "2009-04-22T23:59:59.9999999Z")] + [InlineData("2009-05-22T23:59:59.9999999Z", "2008-05-22T23:59:59.9999999Z")] + public void ShouldNotHaveMissingTicks(string previousTick, string nextTick) + { + var previous = DateTime.Parse(previousTick); + var next = DateTime.Parse(nextTick); + + var sut = new EnsureContinuousSecondTicks(previous); + var missingTicks = sut.GetTicksBetweenPreviousAndNext(next); + + Assert.Empty(missingTicks); + } + + [Theory] + // Same day but different seconds + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T12:00:02.0000000Z", 1)] + [InlineData("2024-01-12T12:00:00.9999999Z", "2024-01-12T12:00:02.0000000Z", 1)] + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T12:00:03.0000000Z", 2)] + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T12:00:04.0000000Z", 3)] + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T12:00:04.9999999Z", 3)] + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T12:00:59.9999999Z", 58)] + + // Different seconds and minutes + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T12:01:02.0000000Z", 61)] + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T12:01:02.5500000Z", 61)] + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T12:01:02.9999998Z", 61)] + + // Different seconds, minutes and/or hours + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T13:00:00.0000000Z", SecondsInHour - 1)] + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T13:00:00.9999999Z", SecondsInHour - 1)] + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-12T14:10:22.9999999Z", (SecondsInHour * 2) + (SecondsInMinute * 10) + 22 - 1)] + + // Different day but same month + [InlineData("2024-01-12T13:00:00.0000000Z", "2024-01-13T13:00:00.0000000Z", SecondsInDay - 1)] + [InlineData("2024-01-12T12:00:00.0000000Z", "2024-01-17T14:10:22.9999999Z", (SecondsInDay * 5) + (SecondsInHour * 2) + (SecondsInMinute * 10) + 22 - 1)] + + // Different month + [InlineData("2024-01-01T13:00:00.0000000Z", "2024-02-01T13:00:00.0000000Z", SecondsInDay * 31 - 1)] + [InlineData("2024-01-01T13:00:00.0000000Z", "2024-03-01T13:00:00.0000000Z", (SecondsInDay * 31) + (SecondsInDay * 29) - 1)] + [InlineData("2024-01-01T13:00:00.0000000Z", "2024-03-01T13:00:00.9999999Z", (SecondsInDay * 31) + (SecondsInDay * 29) - 1)] + + // Different year (testing large ranges and moving from dec to jan) + [InlineData("2023-12-31T13:00:00.0000000Z", "2024-01-01T13:00:00.0000000Z", SecondsInDay - 1)] + [InlineData("2023-12-31T13:00:00.0000000Z", "2024-01-01T13:00:00.9456743Z", SecondsInDay - 1)] + + // Entire year (not realistic but tests the logic). + [InlineData("2022-12-31T13:00:00.0000000Z", "2023-12-31T13:00:00.0000000Z", SecondsInDay * 365 - 1)] + [InlineData("2022-12-31T13:00:00.9999999Z", "2023-12-31T13:00:00.0000000Z", SecondsInDay * 365 - 1)] + [InlineData("2022-12-31T13:00:00.0000000Z", "2023-12-31T13:00:00.9999999Z", SecondsInDay * 365 - 1)] + + public void ShouldHaveMissingTicks(string previousTick, string nextTick, int expectedMissingTicks) + { + var previous = DateTime.Parse(previousTick).ToUniversalTime(); + var next = DateTime.Parse(nextTick).ToUniversalTime(); + + var sut = new EnsureContinuousSecondTicks(previous); + var missingTicks = sut.GetTicksBetweenPreviousAndNext(next); + + Assert.Equal(expectedMissingTicks, missingTicks.Count()); + } + + [Fact] + public void MissingTicksAreExpectedTimes() + { + var previous = DateTime.Parse("2024-01-12T12:00:00.9994443Z").ToUniversalTime(); + var next = DateTime.Parse("2024-01-12T12:00:05.2345633Z").ToUniversalTime(); + + var sut = new EnsureContinuousSecondTicks(previous); + var missingTicks = sut.GetTicksBetweenPreviousAndNext(next).ToArray(); + + Assert.Equal(4, missingTicks.Count()); + Assert.Equal(DateTime.Parse("2024-01-12T12:00:01.0000000Z").ToUniversalTime(), missingTicks[0]); + Assert.Equal(DateTime.Parse("2024-01-12T12:00:02.0000000Z").ToUniversalTime(), missingTicks[1]); + Assert.Equal(DateTime.Parse("2024-01-12T12:00:03.0000000Z").ToUniversalTime(), missingTicks[2]); + Assert.Equal(DateTime.Parse("2024-01-12T12:00:04.0000000Z").ToUniversalTime(), missingTicks[3]); + + // Set the next tick and test that the next check works. + sut.SetNextTick(DateTime.Parse("2024-01-12T12:00:06.2345633Z").ToUniversalTime()); + missingTicks = sut.GetTicksBetweenPreviousAndNext(DateTime.Parse("2024-01-12T12:00:10.9999888Z").ToUniversalTime()).ToArray(); + + Assert.Equal(3, missingTicks.Count()); + Assert.Equal(DateTime.Parse("2024-01-12T12:00:07.0000000Z").ToUniversalTime(), missingTicks[0]); + Assert.Equal(DateTime.Parse("2024-01-12T12:00:08.0000000Z").ToUniversalTime(), missingTicks[1]); + Assert.Equal(DateTime.Parse("2024-01-12T12:00:09.0000000Z").ToUniversalTime(), missingTicks[2]); + } +} diff --git a/Src/UnitTests/CoravelUnitTests/Scheduling/SchedulerEventDispatcherTests.cs b/Src/UnitTests/CoravelUnitTests/Scheduling/SchedulerEventDispatcherTests.cs index cf5a525a..dcff2f8b 100644 --- a/Src/UnitTests/CoravelUnitTests/Scheduling/SchedulerEventDispatcherTests.cs +++ b/Src/UnitTests/CoravelUnitTests/Scheduling/SchedulerEventDispatcherTests.cs @@ -14,7 +14,7 @@ namespace CoravelUnitTests.Scheduling { public class SchedulerEventDispatcherTests { - [Fact] + [Fact] public async Task DoesNotThrowOnNullDispatcher() { var scheduler = new Scheduler(new InMemoryMutex(), new ServiceScopeFactoryStub(), null);