NextRun does sometimes not get updated or updated incorrectly

[ExtraTNT]

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]

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]

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]

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

[tallesl]

Hey @ExtraTNT, first off thank you for the report and sorry for taking so long to reply!

From your output, that's indeed a bug. Unfortunately I wasn't able to reproduce. I know it's been a looong time, but do you happen to have the rest of your code as well? (the schedule code)

On the PR, do you mind expanding on "because of the nature of CPUs"? It's still unclear to me what is making this issue happens and why your patch would fix it...

Stressing out potential culprits, I thought of maybe having different cached timestamps in the different threads, so the Now() call before the await could be later than the Now() call after the await, but I couldn't confirm this theory (either through documentation or test code).

[ExtraTNT]

It's been a while... 3 years ago i was a fresh junior... yeah, from what i remember the issue was, that the time for running the code of fluent scheduler itself created some small delay and fucked things up... -> fix on a real time system would have been to just schedule it a bit more frequent... i think the issue we had was in subtitling with allowed error margins of less than 100ms over long periods of time... the fix updates the startTime to the value it was supposed to have, if it starts later -> this removes the delay that creeps up over time...

In the end it's just the:

if (startTime < NextRun)
                startTime = NextRun.Value;

was tested in a prod environment now for 3 years on around 40 services (also dev and stage env for the same time), 1 simulator for tv subtitles... time was always within range for realistic scheduled tasks (scheduling a task to run every 5ms causes problems, but so does a random rm -rf /)