Scheduled job gets delayed by the running time of the job in a long running (daemon like) program

[maddie]

I have written a little tool to backup my database every day at 0:00 and 13:00, thus:

gocron.Every(1).Day().At("00:00").Do(mainRoutine)
gocron.Every(1).Day().At("13:00").Do(mainRoutine)
<-gocron.Start()

The backup action itself takes around 10~12 seconds. I have set up a logger inside the program, and these are the log output:

INFO[2016-02-19 15:26:29.008 +0800] Backup program is starting.
INFO[2016-02-19 15:26:29.008 +0800] Scheduled backup job on 00:00
INFO[2016-02-19 15:26:29.008 +0800] Scheduled backup job on 13:00
INFO[2016-02-20 00:00:00.016 +0800] Below are databases owned by maddie, they will be backed up:
INFO[2016-02-20 00:00:00.016 +0800] db
INFO[2016-02-20 00:00:10.399 +0800] Database db is backed up as /home/db/database-backups/2016/02/db-20160220-00.bak.
INFO[2016-02-20 00:00:10.399 +0800] Backup finished.
INFO[2016-02-20 13:00:00.016 +0800] Below are databases owned by maddie, they will be backed up:
INFO[2016-02-20 13:00:00.017 +0800] db
INFO[2016-02-20 13:00:11.872 +0800] Database db is backed up as /home/db/database-backups/2016/02/db-20160220-13.bak.
INFO[2016-02-20 13:00:11.873 +0800] Backup finished.
INFO[2016-02-21 00:00:11.016 +0800] Below are databases owned by maddie, they will be backed up:
INFO[2016-02-21 00:00:11.016 +0800] db
INFO[2016-02-21 00:00:22.338 +0800] Database db is backed up as /home/db/database-backups/2016/02/db-20160221-00.bak.
INFO[2016-02-21 00:00:22.338 +0800] Backup finished.
INFO[2016-02-21 13:00:12.016 +0800] Below are databases owned by maddie, they will be backed up:
INFO[2016-02-21 13:00:12.016 +0800] db
INFO[2016-02-21 13:00:22.767 +0800] Database db is backed up as /home/db/database-backups/2016/02/db-20160221-13.bak.
INFO[2016-02-21 13:00:22.767 +0800] Backup finished.
INFO[2016-02-22 00:00:23.017 +0800] Below are databases owned by maddie, they will be backed up:
INFO[2016-02-22 00:00:23.017 +0800] db
INFO[2016-02-22 00:00:32.908 +0800] Database db is backed up as /home/db/database-backups/2016/02/db-20160222-00.bak.
INFO[2016-02-22 00:00:32.908 +0800] Backup finished.
INFO[2016-02-22 13:00:23.016 +0800] Below are databases owned by maddie, they will be backed up:
INFO[2016-02-22 13:00:23.016 +0800] db
INFO[2016-02-22 13:00:34.653 +0800] Database db is backed up as /home/db/database-backups/2016/02/db-20160222-13.bak.
INFO[2016-02-22 13:00:34.653 +0800] Backup finished.
INFO[2016-02-23 00:00:33.018 +0800] Below are databases owned by maddie, they will be backed up:
INFO[2016-02-23 00:00:33.018 +0800] db
INFO[2016-02-23 00:00:43.447 +0800] Database db is backed up as /home/db/database-backups/2016/02/db-20160223-00.bak.
INFO[2016-02-23 00:00:43.447 +0800] Backup finished.
INFO[2016-02-23 13:00:35.016 +0800] Below are databases owned by maddie, they will be backed up:
INFO[2016-02-23 13:00:35.016 +0800] db
INFO[2016-02-23 13:00:46.023 +0800] Database db is backed up as /home/db/database-backups/2016/02/db-20160223-13.bak.
INFO[2016-02-23 13:00:46.023 +0800] Backup finished.
INFO[2016-02-24 00:00:44.016 +0800] Below are databases owned by maddie, they will be backed up:
INFO[2016-02-24 00:00:44.016 +0800] db
INFO[2016-02-24 00:00:53.945 +0800] Database db is backed up as /home/db/database-backups/2016/02/db-20160224-00.bak.
INFO[2016-02-24 00:00:53.945 +0800] Backup finished.
INFO[2016-02-24 13:00:47.016 +0800] Below are databases owned by maddie, they will be backed up:
INFO[2016-02-24 13:00:47.016 +0800] db
INFO[2016-02-24 13:00:58.153 +0800] Database db is backed up as /home/db/database-backups/2016/02/db-20160224-13.bak.
INFO[2016-02-24 13:00:58.153 +0800] Backup finished.
INFO[2016-02-25 00:00:54.016 +0800] Below are databases owned by maddie, they will be backed up:
INFO[2016-02-25 00:00:54.016 +0800] db
INFO[2016-02-25 00:01:05.071 +0800] Database db is backed up as /home/db/database-backups/2016/02/db-20160225-00.bak.
INFO[2016-02-25 00:01:05.071 +0800] Backup finished.
INFO[2016-02-25 13:00:59.016 +0800] Below are databases owned by maddie, they will be backed up:
INFO[2016-02-25 13:00:59.016 +0800] db
INFO[2016-02-25 13:01:10.720 +0800] Database db is backed up as /home/db/database-backups/2016/02/db-20160225-13.bak.
INFO[2016-02-25 13:01:10.720 +0800] Backup finished.

As you can see, after each scheduled job being executed, the next job will be delayed by 10~12 seconds which is the execution time of the backup routine.

Is this by design? If yes, is there a way to change the behaviour?

[xEtarusx]

I have the same problems with my projects. All delay by some time. It's not exactly the time the tasks take to execute.
If I execute tasks every 10 seconds (which takes 1 second of processing time) they get delayed by 1 second most of the time. This is an incredible impact if I run tasks on another projects once a day. They take up to 2 hours to process and the delayed amount is always more than 30mins+ ! Please fix this. You cannot schedule a task at 03:00 AM and after a week it's running at 07:00 AM...

[jonlaing]

I was looking at this project after searching "Golang cron", and liked the idea, but wanted to build it differently without reflection, so I rolled my own. I think the issue is that all the jobs are being run on the same thread, thus if a job of yours takes more than a second, all of your jobs will be delayed by that much.

Looking at the code, it'll take some tinkering to make it work properly, as the job.run() function returns some values from the task, making spinning off a new goroutine a little more tricky. I guess, my question is why do we need to return the result of the task? It looks like the only time that's used is in NextRun().

I'm finding it a little hard to see where that would be useful. If we dropped needing to return the result of the task, we could rewrite the job.run() function like:

func (j *Job) run() {
    // ...
    // Instead of throwing an error here when the task is running,
    // why not throw an error when the task is added to the scheduler?
    // if len(params) != f.Type().NumIn() {
    //  err = errors.New("The number of param is not adapted.")
    //  return
    // }
    // ...
    go f.Call(in) // spin off a goroutine so as not to delay subsequent tasks
    j.lastRun = time.Now()
    j.scheduleNextRun()
}

My cursory testing shows this to work, but I've hardly been exhaustive with it. That's my suggestion anyway.

[igateno]

@jasonlvhit what's the status of this issue? Any plans to resolve? I'm seeing some similar behavior in my project, and honestly if this is not resolved I will need to move away from this lib.

[denouche]

Does #57 could resolve this issue ?

[skrynauw]

Yes #57 solves it, I had the same issue

[JohnRoesler]

Come checkout https://github.com/go-co-op/gocron where we have an active fork of this repo!