FluentScheduler icon indicating copy to clipboard operation
FluentScheduler copied to clipboard

NextRun does sometimes not get updated or updated incorrectly

Open ExtraTNT opened this issue 2 years ago • 3 comments

So, it looks like that the NextRun value does sometimes not get updated or does get updated incorrectly. Which leads to tasks being executed twice when they should instead only run once. I wrote a small test application to show the problem:

...
private async Task<bool> Tester()
    {
        _logger.LogInformation("Thread id: " + Thread.CurrentThread.ManagedThreadId);
        _logger.LogInformation("Next Run: " + _scheduler.NextRun);
        _logger.LogInformation("Current Time " + DateTime.Now);
        // do something for 1 sec... (sleep 2x 1/2 sec -.-)
        Thread.Sleep(500);
        Thread.Sleep(500);
        _logger.LogInformation("After execution Time (+ 1s): " + DateTime.Now);
        return true;
    }

I ran this every 10 seconds and got the following output:

testScheduler.Worker: Information: Thread id: 9
testScheduler.Worker: Information: Next Run: 04.04.2022 14:43:40
testScheduler.Worker: Information: Current Time 04.04.2022 14:43:30
testScheduler.Worker: Information: After execution Time (+ 1s): 04.04.2022 14:43:31
Exited Thread 302116
testScheduler.Worker: Information: Thread id: 9
testScheduler.Worker: Information: Next Run: 04.04.2022 14:43:50
testScheduler.Worker: Information: Current Time 04.04.2022 14:43:40
testScheduler.Worker: Information: After execution Time (+ 1s): 04.04.2022 14:43:41
Exited Thread 302587
Started Thread 303062
testScheduler.Worker: Information: Thread id: 3
testScheduler.Worker: Information: Next Run: 04.04.2022 14:44:00
testScheduler.Worker: Information: Current Time 04.04.2022 14:43:50
testScheduler.Worker: Information: After execution Time (+ 1s): 04.04.2022 14:43:51
Exited Thread 303063
testScheduler.Worker: Information: Thread id: 7
testScheduler.Worker: Information: Next Run: 04.04.2022 14:44:00
testScheduler.Worker: Information: Current Time 04.04.2022 14:44:00
testScheduler.Worker: Information: After execution Time (+ 1s): 04.04.2022 14:44:01
testScheduler.Worker: Information: Thread id: 3
testScheduler.Worker: Information: Next Run: 04.04.2022 14:44:10
testScheduler.Worker: Information: Current Time 04.04.2022 14:44:01
testScheduler.Worker: Information: After execution Time (+ 1s): 04.04.2022 14:44:02
Exited Thread 303539
testScheduler.Worker: Information: Thread id: 7
testScheduler.Worker: Information: Next Run: 04.04.2022 14:44:10
testScheduler.Worker: Information: Current Time 04.04.2022 14:44:10
testScheduler.Worker: Information: After execution Time (+ 1s): 04.04.2022 14:44:11
testScheduler.Worker: Information: Thread id: 3
testScheduler.Worker: Information: Next Run: 04.04.2022 14:44:20
testScheduler.Worker: Information: Current Time 04.04.2022 14:44:11
testScheduler.Worker: Information: After execution Time (+ 1s): 04.04.2022 14:44:12

The bug occurs randomly, but in a test before a "buggy thread" was more likely to bug again and it got worse over time. But since this is not really testable i can not confirm, that it will always be this way. I currently do not have a fix for this bug, but i will try to fix it and create a pull request. The version i use is version-6 with dotnet 6.0 on debian gnu/linux 11

ExtraTNT avatar Apr 04 '22 13:04 ExtraTNT

It looks like sometimes RunNext gets calculated before the task should run, leading to a wrong RunNext time, without an error in the calculation...

ExtraTNT avatar Apr 04 '22 14:04 ExtraTNT

found the problem, it's in InternalSchedule in Run, using Calculator.Now(); in the calculation for the delay isn't accurate, because a cpu takes time to do something...

i have a fix for it, but it probably will not work if the task runs every second (gets executed ~1 sec later -> probably, because we don't have infinitely fast cpus). i will test this and if it's a problem fix it

ExtraTNT avatar Apr 05 '22 07:04 ExtraTNT

Found a easy way to fix the 1 sec issue, a bit hacky, but should work

ExtraTNT avatar Apr 05 '22 07:04 ExtraTNT