Sidekiq: perform_in(1.second, args) takes a lot longer than 1 second to perform

[homanchou]

I've noticed that when using perform_in(1.seconds, args), the job takes a lot longer than 1.seconds to get enqueued and worked on even if there is nothing else going on. I haven't timed it but it feels like it takes about 1 minute to get enqueued.

Are there settings that might effect how frequently the jobs go from scheduled to enqueued?

Could it be our weighted queue numbers?

Here is our Procfile

worker: bundle exec sidekiq -e ${RACK_ENV:-development} -i ${DYNO:-1} -q critical,10 -q priority,7 -q default,4 -q low,1 -c ${WORKER_CONCURRENCY:-10}

beefy_worker: bundle exec sidekiq -e ${RACK_ENV:-development} -i ${DYNO:-1} -q beefy,10 -q critical,9 -q priority,8 -q default,5 -c ${BEEFY_CONCURRENCY:-10}

report_worker: bundle exec sidekiq -e ${RACK_ENV:-development} -i ${DYNO:-1} -q reports,10 -q priority,8 -q default,10 -c ${REPORT_WORKER_CONCURRENCY:-5}

Gemfile:

sidekiq (3.3.0)
      celluloid (>= 0.16.0)
      connection_pool (>= 2.0.0)
      json
      redis (>= 3.0.6)
      redis-namespace (>= 1.3.1)
    sidekiq-cron (0.2.0)
      rufus-scheduler (>= 2.0.24)
      sidekiq (>= 2.17.3)
      tilt (< 2.0.0)


sidekiq-pro (1.9.2)
      sidekiq (>= 3.2.3)


sidekiq-status (0.5.1)
      sidekiq (>= 2.7, < 3.4)
    sidekiq-unique-jobs (3.0.11)
      sidekiq (>= 2.6)

[mperham]

Note that Sidekiq's scheduler by default checks for jobs every 15 seconds so that'll add 15 seconds of latency. Then the scheduler just enqueues the job - if your queues are backed up, it might take a few seconds to execute the job.

[machineboy2045]

I created a worker to test this.

class TimeTest
    include Sidekiq::Worker

    def perform(args)
      raise (Time.now - Time.parse(args['start_time'])).to_i.to_s
    end
  end

TimeTest.perform_in(1.second, {'start_time' => Time.now})

The first time I ran it, it raised '48' seconds. Could it be because we are using custom queue weights?

[mperham]

@machineboy2045 Try it several times and give me the times. Are you on 3.3? The poll time is actually random based on config.poll_interval and defaults to 15. Have you customized that or are you using the default?

[homanchou]

@machineboy2045 and I are co-workers on the same codebase. Yes we are using 3.3. We have not customized poll time. We are using rails 4.2

Our sidekiq.rb initializer looks like this (does anything look suspicious?):

require 'sidekiq'

require 'sidekiq-status'

Sidekiq.configure_client do |config|
  config.client_middleware do |chain|
    chain.add Sidekiq::Status::ClientMiddleware
  end
end

Sidekiq.configure_server do |config|
  config.server_middleware do |chain|
    chain.add Sidekiq::Status::ServerMiddleware, expiration: 30.minutes #default
  end
  config.client_middleware do |chain|
    chain.add Sidekiq::Status::ClientMiddleware
  end
end

Sidekiq.configure_client do |config|
  config.redis = { :size => 1 }
end

Sidekiq.default_worker_options = {
  :backtrace => true
}

Sidekiq.configure_server do |config|
  if Rails.env.production?
    config.error_handlers << Proc.new { |ex,context| Airbrake.notify_or_ignore(ex,parameters: context) }
  end
end

[mperham]

Nothing looks suspicious. Run that TimeWorker several times, restarting Sidekiq each time and let me know the values.

The latest Airbrake gem will do that last part for you. Why are you storing backtraces if you are using Airbrake?

[machineboy2045]

Ran it several more times, restarting Sidekiq in-between like you asked.

59
7
3
9
34
8
45
4

[mperham]

If you are running in development, can you flush your Redis DB redis-cli flushall and retry?

[mperham]

Any progress on this?

[machineboy2045]

flushed redis and ran it again. this extended delay problem happens on at least 2 of our dev machines. so I don't think its a fluke.

9
19
4
4
27
10
6
37

[mperham]

Open your Rails console, what does p [Sidekiq::ProcessSet.new.size, Sidekiq.options] print?

[machineboy2045]

[3,
 {:queues=>[],
  :labels=>[],
  :concurrency=>25,
  :require=>".",
  :environment=>nil,
  :timeout=>8,
  :error_handlers=>[#<Sidekiq::ExceptionHandler::Logger:0x00000004ae0e08>],
  :lifecycle_events=>{:startup=>[], :quiet=>[], :shutdown=>[]},
  :notifications=>{}}]

[mperham]

So Sidekiq thinks there are three processes running. 3 * 15 = up to 45 sec. I assume in development that you are running only one process. Are you shutting down Sidekiq via kill -9?

[machineboy2045]

Using foreman (procfile at the top of this discussion) to start it and ctrl+c in terminal to stop.

[mperham]

Well, then everything is working as expected. You are running three processes, and should see jobs scheduled every 15 seconds on average. The times you posted average out to about 15 seconds.

[mperham]

If you want to ensure faster scheduling, set poll_interval as appropriate. https://github.com/mperham/sidekiq/wiki/Scheduled-Jobs#checking-for-new-jobs

[mperham]

e.g. If you have 3 processes and want to ensure a check every 5 seconds, set poll_interval to 15.

[machineboy2045]

Thanks for the explanation and sorry to have taken so much time. It sounds
like polling is expensive? So I shouldn't set it to check every second?

On Wed, Feb 18, 2015 at 10:41 AM, Mike Perham [email protected]
wrote:

e.g. If you have 3 processes and want to ensure a check every 5 seconds,
set poll_interval to 15.

—
Reply to this email directly or view it on GitHub
https://github.com/mperham/sidekiq/issues/2187#issuecomment-74921276.

[mperham]

It's not very expensive but it gets worse when you are running hundreds of Sidekiqs, all pounding Redis for jobs to schedule.

I wouldn't check every second personally but I've tried to educate people how it works so each person can determine the right poll interval for their application.

[david-vega]

Just got the same issue here, I follow the recommendations here and according to the docs and this threat if I have 16 queues and I want them to be checked every 5 seconds I set the poll_interval to 80 with that configuration I still had issues, so I start playing with the poll_interval and even in 15 doesn't have the random behavior. I set it to 5 and now it works.

So far it looks good but not sure if the docs are incorrect, there's a bug in the gem or I'm doing it wrong.

Any thoughts on this?

[mperham]

@david-vega It's not 16 queues, it's 16 Sidekiq processes. Number of queues does not matter.

[david-vega]

then that means I have 5 processes 0:08.69 sidekiq 3.3.3 local [0 of 5 busy] therefore the poll_interval to be checked every 5 seconds needs to be set at 25, however if I do that I still have the random timing.

I'm still confused.

[mperham]

@david-vega Correct. Randomness is required or else all processes would check at the same time. If you need guaranteed timing precision at the second granularity, Sidekiq cannot do that.