Scheduling a ScheduledJob hourly runs a few seconds early and reschedules thus running twice about queues HOT 23 OPEN

@tanner0101 A little backed up here, but not too badly and I think I can add it to my, uh... queue. 😄

from queues.

@tanner0101 Maybe I’m confused, but I don’t see how this runs a second time. This always calls cancel, which should always be done before the original future completes, and so this should never reschedule.

As to the question of why it might run early: NIO doesn’t schedule jobs on wall clock time, it schedules them against a monotonic uptime clock. The intention is that for event loops you usually want to say “run this in 10 seconds” and to have that mean in ten seconds, not in three seconds because the ntp daemon decided to jump the clock forward. The monotonic uptime clock is not affected by changes to wall time, and therefore asking to run something at a given wall time is not something NIO supports.

This means that yes, some systems may see inaccuracy when attempting to schedule things against the wall clock. That is just not really what NIO’s event loops are for. If you want things to be scheduled against a wall clock then something like DispatchSources may be more useful for the immediate use-case.

from queues.

Moving this to the queues repo for better tracking. I will look into this and see if I can figure out what's up.

from queues.

Scheduling correctly running natively on Mac OS 10.15.5 via Xcode.

I set the schedule to 21 minutes after the hour for this test run.

[ DEBUG ] Could not load .env.development file: open(file:oFlag:mode:): No such file or directory (errno: 2) (Vapor/Application.swift:132)
[ DEBUG ] Could not load .env file: open(file:oFlag:mode:): No such file or directory (errno: 2) (Vapor/Application.swift:132)
[ DEBUG ] 2020-08-02 06:19:25 +0000 Initializing rates (App/CurrencyRatesFetcher.swift:23)
[ DEBUG ] 2020-08-02 06:19:25 +0000 Try to load rates from file (App/CurrencyRatesFetcher.swift:27)
[ INFO ] 2020-08-02 06:19:25 +0000 Attempting to load cached rates from file file:///Users/danw/dev/YesFX/server/YesFX-server/data/rates... (App/CurrencyRatesStorage.swift:48)
[ INFO ] 2020-08-02 06:19:25 +0000 Loading cached rates from file file:///Users/danw/dev/YesFX/server/YesFX-server/data/rates... (App/CurrencyRatesStorage.swift:55)
[ INFO ] 2020-08-02 06:19:25 +0000 Cached rates: [{
"base" : "USD",
"fetchedAt" : 1596243718.0247989,
"rates" : {
"NZD" : 1.508102,
"QAR" : 3.641,
"MGA" : 3802,
"SOS" : 584.5,
"ZAR" : 17.06885,
...
"TWD" : 29.325,
"SDG" : 55.3,
"BTN" : 74.734688,
"UAH" : 27.715963
},
"timestamp" : 1596243614
}] (App/CurrencyRatesStorage.swift:57)
[ DEBUG ] Factory created. [RedisConnectionFactory: F39DD6DF-2BBC-4070-9553-4B6EFA308E2B] (RedisKit/RedisConnectionSource.swift:20)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-08-02 06:21:00 +0000 (Queues/ScheduledJob.swift:36)
[ NOTICE ] Server starting on http://127.0.0.1:8080 (Vapor/HTTP/Server/HTTPServer.swift:183)
[ DEBUG ] 2020-08-02 06:21:00 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:118)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-08-02 07:21:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-08-02 06:21:01 +0000 Fetched 171 currencies at 2 August 2020 at 6:21:01 PM NZST (App/CurrencyRatesFetcher.swift:49)
[ INFO ] 2020-08-02 06:21:01 +0000 Currency rates up to date at 2 August 2020 at 6:00:15 PM NZST) (App/CurrencyRatesFetcher.swift:51)
[ DEBUG ] 2020-08-02 06:21:01 +0000 Saved rates to file rates (App/CurrencyRatesFetcher.swift:58)
[ DEBUG ] 2020-08-02 07:21:00 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:118)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-08-02 08:21:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-08-02 07:21:01 +0000 Fetched 171 currencies at 2 August 2020 at 7:21:01 PM NZST (App/CurrencyRatesFetcher.swift:49)
[ INFO ] 2020-08-02 07:21:01 +0000 Currency rates up to date at 2 August 2020 at 7:00:11 PM NZST) (App/CurrencyRatesFetcher.swift:51)
[ DEBUG ] 2020-08-02 07:21:01 +0000 Saved rates to file rates (App/CurrencyRatesFetcher.swift:58)
[ DEBUG ] 2020-08-02 08:21:00 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:118)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-08-02 09:21:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-08-02 08:21:02 +0000 Fetched 171 currencies at 2 August 2020 at 8:21:02 PM NZST (App/CurrencyRatesFetcher.swift:49)
[ INFO ] 2020-08-02 08:21:02 +0000 Currency rates up to date at 2 August 2020 at 8:00:07 PM NZST) (App/CurrencyRatesFetcher.swift:51)
[ DEBUG ] 2020-08-02 08:21:02 +0000 Saved rates to file rates (App/CurrencyRatesFetcher.swift:58)

from queues.

I have noticed something that may be relevant here. I run the vapor server as a localhost on my computer. However, the server is GMT and the computer is GMT + 1. Depending on how you call schedule(), you need to input different times in order to get them to run at the same time.

// 1st case runs at the time on my computer.
app.queues.schedule(CleanupJob())
.daily()
.at(6, 08, .pm)

// runs at the time of the server. someDateTime is 5:08pm GMT
app.queues.schedule(CleanupJob()).at(Date(timeInterval: 0, since: someDateTime!))

from queues.

It is possible that the clocks between your server and computer are off by a few seconds.

from queues.

Moving this to the queues repo for better tracking. I will look into this and see if I can figure out what's up.

Thanks Jimmy.

from queues.

It is possible that the clocks between your server and computer are off by a few seconds.

@felswa Thanks for the suggestion. Any suggestion on how I could test this?

from queues.

@felswa I ran:

#!/bin/sh
docker exec 989eac6f8cfc date
date

and got:

Sun Aug  2 20:43:30 UTC 2020
Mon  3 Aug 2020 08:43:30 NZST

So I guess the clocks are in sync.

from queues.

from queues.

Thanks Dan. I am very new to this.
…

@felswa Me too.

from queues.

from queues.

Hi @danwallacenz, thanks for reporting. Based on the logs it looks like the target date is being calculated correctly:

[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 02:02:00 +0000 (Queues/ScheduledJob.swift:36)

However, the job is actually running slightly early:

[ INFO ] 2020-07-31 02:01:59 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)

That makes me think the issue resides here where we schedule the job on the event loop: https://github.com/vapor/queues/blob/master/Sources/Queues/ScheduledJob.swift#L39

Perhaps Date.timeIntervalSinceNow or EventLoop.scheduleRepeatedTask are less accurate on Linux? If this is working on macOS, that could be a sign that the bug is not in our code.

cc @weissi @Lukasa. Can you see anything here that looks out of the ordinary?

from queues.

Side note, a potential workaround here could be storing the last date the job was scheduled to run at and backoff rescheduling until we get a next date that is greater.

from queues.

@tanner0101 Thanks for looking at this. I do have workarounds in place.

from queues.

Can you see anything here that looks out of the ordinary?

@jdmcd (et al) Apologies for dropping an aside in here, but if not actually scheduling a repeating task there

let task = context.eventLoop.scheduleRepeatedTask(
    initialDelay: .microseconds(Int64(date.timeIntervalSinceNow * 1_000_000)),
    delay: .seconds(0)
) { task in
    // always cancel
    task.cancel()

is there a reason for not just using scheduleTask(deadline:_:) or scheduleTask(in:_:)?

Perhaps I'm missing something, but I'm not readily seeing anywhere that class RepeatedTask is being used where struct Scheduled would not suffice (and that .cancel() in the closure could be eliminated?).

from queues.

@grundoon good catch, that looks like an oversight. scheduleTask seems like the better API for this case.

from queues.

@grundoon would you wanna open an issue for that or PR it? Otherwise I can

from queues.

Hmm, I realise I should add to this something explicit that is implicit above: the monotonic uptime clock is still affected by ntp changes! It just doesn't jump: it skews, instead. The end result is that if you run something "once per hour" against the monotonic clock you should see it run approximately once per wall clock hour, but sometimes it'll run a bit early and sometimes it'll run a bit late. Over time it'll correct itself to the right interval, however.

from queues.

@Lukasa OK that makes sense and seems very likely to be the culprit. I imagine Date.timeIntervalSinceNow is using the "wall clock" so that's where we're getting a divergence. I will look into DispatchSources, thank you!

Maybe I’m confused, but I don’t see how this runs a second time. This always calls cancel, which should always be done before the original future completes, and so this should never reschedule.

Ignore that we are using scheduleRepeatedTask here. That should really be scheduleTask as @grundoon pointed out. Once the task completes, we calculate the next date and schedule again. If the task starts too early, that next date resolves to the previously scheduled date resulting in it running again at basically the same time.

from queues.

@tanner0101 After messing with it a bit, I'm going to withdraw that suggestion. While the API switch superficially seems to make sense, the returned Scheduled would be a generic and likely carry more overhead than any minimal benefit derived. Since the observed behavior is entirely unrelated, not seeing any real point in trying to extricate RepeatedTask from the package... it's pretty embedded, and sensibly so.

from queues.

@grundoon either way it seems like we need to switch to Dispatch or something else given what Cory said. Thanks for looking into it though 👍

from queues.

I have not seen these scheduling errors after deploying my container to an AWS Elastic Beanstalk multi-container Docker environment running on 64bit Amazon Linux/2.20.4.

from queues.