Search code examples
rubysinatrasidekiq

Staggering Sidekiq Scheduled Jobs

I tried using Sidekiq's perform_in call in (nextSend += 1).seconds while iterating through 30 times.

But I found that each job was enqueued around the same time and executed almost immediately after each other.

Why did this happen, and is there a better way to stagger calls without sleeping the application?

Thanks.

Some logs: 

2015-06-30T21:30:12.216092+00:00 app[web.1]: SystemTime: 21:30
2015-06-30T21:30:12.216137+00:00 app[web.1]: 
2015-06-30T21:30:12.216139+00:00 app[web.1]: Send story?: 
2015-06-30T21:30:12.720780+00:00 app[web.1]: doing hard work!!
2015-06-30T21:30:12.720783+00:00 app[web.1]: 
2015-06-30T21:30:12.722278+00:00 app[web.1]: 6 TID-oxrbofeo8 SomeWorker JID-1cb9f52c40ce3d76fb1df5c6 INFO: done: 0.508 sec
2015-06-30T21:30:30.581846+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+12039095780"],"retry":false,"queue":"critical","jid":"ecda1711afd63dffced0cc30","created_at":1435699812.262315}
2015-06-30T21:30:30.625757+00:00 app[web.1]: 6 TID-oxrbofeo8 NewTextWorker JID-ecda1711afd63dffced0cc30 INFO: start
2015-06-30T21:30:30.640225+00:00 app[web.1]: 6 TID-oxrbo923c NewTextWorker JID-8bf1e1b26054e5b335232f27 INFO: start
2015-06-30T21:30:30.640229+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NextMessageWorker","args":["StoryTime: Here's your new story... beware of hungry crocodiles!",["http://i.imgur.com/gNPKPSs.jpg","http://i.imgur.com/SRDF3II.jpg","http://i.imgur.com/iSVBGu4.jpg"],"+12034354841"],"retry":false,"queue":"critical","jid":"cb93b0d5469ae43b9c355fd4","created_at":1435699812.352102}
2015-06-30T21:30:30.640253+00:00 app[web.1]: 6 TID-oxrbvnftw NewTextWorker JID-145a78e8a781bdee9d364eaf INFO: start
2015-06-30T21:30:30.583719+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+15615422026"],"retry":false,"queue":"critical","jid":"8bf1e1b26054e5b335232f27","created_at":1435699812.296749}
2015-06-30T21:30:30.626992+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+12033615947"],"retry":false,"queue":"critical","jid":"145a78e8a781bdee9d364eaf","created_at":1435699812.3334303}
2015-06-30T21:30:30.668423+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+16468878679"],"retry":false,"queue":"critical","jid":"4a7b6d697095ecd670a00078","created_at":1435699812.372093}
2015-06-30T21:30:30.769061+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+15612125831"],"retry":false,"queue":"critical","jid":"29e7553ccab09cada3a0c919","created_at":1435699812.3837028}
2015-06-30T21:30:30.656838+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! We noticed you didn't choose your last story. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+15619008225"],"retry":false,"queue":"critical","jid":"85cb3b18503837dac61ace6b","created_at":1435699812.3557012}
2015-06-30T21:30:30.771557+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+12392735883"],"retry":false,"queue":"critical","jid":"2f072b313a0fbe1b3413a466","created_at":1435699812.4306083}
2015-06-30T21:30:30.800228+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+13522226913"],"retry":false,"queue":"critical","jid":"4dcd80cac50e8f19a2b6d867","created_at":1435699812.5680537}
2015-06-30T21:30:30.816201+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+19417243442"],"retry":false,"queue":"critical","jid":"674e5f1aa017bd6b50140cb4","created_at":1435699812.5889344}
2015-06-30T21:30:30.749579+00:00 app[web.1]: 6 TID-oxrbvm37c NextMessageWorker JID-cb93b0d5469ae43b9c355fd4 INFO: start
2015-06-30T21:30:30.769567+00:00 app[web.1]: 6 TID-oxrbvkjm8 NewTextWorker JID-85cb3b18503837dac61ace6b INFO: start
2015-06-30T21:30:30.786596+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+17722330863"],"retry":false,"queue":"critical","jid":"fd1d1c029e836c12577fd7ca","created_at":1435699812.5403354}
2015-06-30T21:30:30.804066+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NextMessageWorker","args":["StoryTime: Here's your new story... beware of hungry crocodiles!",["http://i.imgur.com/gNPKPSs.jpg","http://i.imgur.com/SRDF3II.jpg","http://i.imgur.com/iSVBGu4.jpg"],"+15615734535"],"retry":false,"queue":"critical","jid":"1e0fd68d4e0997ef0152a97d","created_at":1435699812.5728064}
2015-06-30T21:30:30.825363+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+12022518772"],"retry":false,"queue":"critical","jid":"07e7dcf3ce90bc71d2107a11","created_at":1435699812.6284366}
2015-06-30T21:30:30.844143+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+15614796303"],"retry":false,"queue":"critical","jid":"5a8db8568fc44faefbddc422","created_at":1435699812.6561987}
2015-06-30T21:30:30.871928+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+15613056454"],"retry":false,"queue":"critical","jid":"b2e5d924c67443e1a6252a80","created_at":1435699812.6815143}
2015-06-30T21:30:30.850455+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+18456711380"],"retry":false,"queue":"critical","jid":"486328d6fbc6f835f216186a","created_at":1435699812.6689503}
2015-06-30T21:30:30.877893+00:00 app[web.1]: 6 TID-oxrbozdlc DEBUG: enqueued schedule: {"class":"NewTextWorker","args":["StoryTime: Hi! You can now choose new stories. Do you want stories about Marley the puppy or about Bruce the moose?\n\nReply \"p\" for puppy or \"m\" for moose.","+15617893548"],"retry":false,"queue":"critical","jid":"4d5812202383601c879a9774","created_at":1435699812.693517}
2015-06-30T21:30:31.159120+00:00 app[web.1]: Sent sms to +12039095780: : Hi! You can now 
2015-06-30T21:30:31.187398+00:00 app[web.1]: 6 TID-oxrbofeo8 NewTextWorker JID-4a7b6d697095ecd670a00078 INFO: start
2015-06-30T21:30:31.257215+00:00 app[web.1]: 6 TID-oxrbo923c NewTextWorker JID-8bf1e1b26054e5b335232f27 INFO: done: 0.621 sec
2015-06-30T21:30:31.321590+00:00 app[web.1]: Sent sms to +12033615947: : Hi! You can now 
2015-06-30T21:30:31.337535+00:00 app[web.1]: 6 TID-oxrbvnftw NewTextWorker JID-2f072b313a0fbe1b3413a466 INFO: start
2015-06-30T21:30:31.183538+00:00 app[web.1]: 6 TID-oxrbofeo8 NewTextWorker JID-ecda1711afd63dffced0cc30 INFO: done: 0.558 sec
2015-06-30T21:30:31.245844+00:00 app[web.1]: Sent sms to +15615422026: : Hi! You can now 
2015-06-30T21:30:31.274294+00:00 app[web.1]: 6 TID-oxrbo923c NewTextWorker JID-29e7553ccab09cada3a0c919 INFO: start
2015-06-30T21:30:31.333168+00:00 app[web.1]: 6 TID-oxrbvnftw NewTextWorker JID-145a78e8a781bdee9d364eaf INFO: done: 0.693 sec
2015-06-30T21:30:31.523343+00:00 app[web.1]: Sent mms to +12034354841: /gNPKPSs.jpgSent sms to +16468878679: : Hi! You can now 
2015-06-30T21:30:31.523387+00:00 app[web.1]: `
Solution

  • Sidekiq's scheduler is not that granular, it checks every 15 seconds by default. If you want it to be more precise, you need to lower the poll interval:

    Sidekiq.configure_server do |config|
  config.average_scheduled_poll_interval = 5
end

    This code goes in config/initializers/sidekiq.rb (see example).