vapor/queues

ScheduledJob run twice quickly because actual sleep duration is shorter than expected.

omochi opened this issue · 0 comments

omochi commented

Describe the bug

I used ScheduledJob which is scheduled at every minutes.
In some environment, job runs twice quickly at every minutes.

I patched this library to investigate by printing more information to know what happens.
This is a patch.
https://github.com/omochi/queues/pull/1/files

It prints scheduled time previously started job and current time.

This is log.

$ .build/release/Run serve --hostname 0.0.0.0 --port 80
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:16:00 +0000, now=2021-03-03 12:15:26 +0000, prev=nil
[ NOTICE ] Server starting on http://0.0.0.0:80
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:16:00 +0000, now=2021-03-03 12:15:59 +0000, prev=Optional(2021-03-03 12:16:00 +0000)
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:17:00 +0000, now=2021-03-03 12:16:00 +0000, prev=Optional(2021-03-03 12:16:00 +0000)
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:17:00 +0000, now=2021-03-03 12:16:59 +0000, prev=Optional(2021-03-03 12:17:00 +0000)
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:18:00 +0000, now=2021-03-03 12:17:00 +0000, prev=Optional(2021-03-03 12:17:00 +0000)
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:18:00 +0000, now=2021-03-03 12:17:59 +0000, prev=Optional(2021-03-03 12:18:00 +0000)
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:19:00 +0000, now=2021-03-03 12:18:00 +0000, prev=Optional(2021-03-03 12:18:00 +0000)
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:19:00 +0000, now=2021-03-03 12:18:59 +0000, prev=Optional(2021-03-03 12:19:00 +0000)
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:20:00 +0000, now=2021-03-03 12:19:00 +0000, prev=Optional(2021-03-03 12:19:00 +0000)
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:20:00 +0000, now=2021-03-03 12:19:59 +0000, prev=Optional(2021-03-03 12:20:00 +0000)
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:21:00 +0000, now=2021-03-03 12:20:00 +0000, prev=Optional(2021-03-03 12:20:00 +0000)
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:21:00 +0000, now=2021-03-03 12:20:59 +0000, prev=Optional(2021-03-03 12:21:00 +0000)
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:22:00 +0000, now=2021-03-03 12:21:00 +0000, prev=Optional(2021-03-03 12:21:00 +0000)
[ INFO ] Scheduling JobKickerJob to run at 2021-03-03 12:22:00 +0000, now=2021-03-03 12:21:59 +0000, prev=Optional(2021-03-03 12:22:00 +0000)

First, job is scheduled at 12:16:00 at (now=)12:15:26.

Next, job is started at (now=)12:15:59.
This is problem.
This job is actually scheduled at 12:16:00 but started earlier it.
So next schedule is also 12:16:00.
Immediately, 12:16:00 comes actually.
This is twice execution process.

After that, same phenomenon happens repeatedly.

To Reproduce

Configure job.

    app.queues.schedule(JobKickerJob()).minutely().at(0)
    try app.queues.startScheduledJobs()

Start app.

Expected behavior

Job should run only once at every scheduled interval.

Environment

I tried this at many environment.
I got only once environment as below.

  • Linux on Docker on Mac. Docker image is swift:5.3.
  • Release build. ($ swift build -c release)
  • My mac is iMac Pro 2017, 2.3 GHz 18 core Intel Xeon W
  • Docker engine uses 18 core.
  • vapor 4.41.2
  • queus-redis-driver 1.0.0
  • queues 1.5.1

Additional context

This bug causes concurrent execution and race condition in our project.
We didn't expect this at all, so debugging was very hard and consume many working time.
I finally reached to this library and very surprised.

It may be duplicate with #85