Reputation: 5862
I have a job that runs every single minute that basically just SSHes into a server, runs netstat, retrieves its output, and puts it into the database. It usually takes 2-5 seconds max from start to finish. However, when I'm running other jobs, sometimes this job will end up getting stuck and won't finish until the other jobs finish, and I'm unsure as to why. Here's what the EveryMinuteWorker
looks like:
# app/workers/every_minute_worker.rb
class EveryMinuteWorker
include Sidekiq::Worker
sidekiq_options queue: Rails.env.to_sym
sidekiq_options :retry => false
def perform
@slack = SlackBot.new
check_agent_statuses
end
end
As you can see in the sidekiq log below, the EveryMinuteWorker
runs just perfectly fine and lasts just less than three seconds every time it runs. At one point, it started and never finished until the HttpsWorker finished further down:
[root:a8cd613bc7a5:~/myapp]# sidekiq -e production -q production
2020-07-02T21:44:45.024Z pid=1807172 tid=go3qqgj28 INFO: Booted Rails 5.2.4 application in production environment
2020-07-02T21:44:45.024Z pid=1807172 tid=go3qqgj28 INFO: Running in ruby 2.5.8p224 (2020-03-31 revision 67882) [x86_64-linux]
2020-07-02T21:44:45.024Z pid=1807172 tid=go3qqgj28 INFO: See LICENSE and the LGPL-3.0 for licensing details.
2020-07-02T21:44:45.024Z pid=1807172 tid=go3qqgj28 INFO: Upgrade to Sidekiq Pro for more features and support: http://sidekiq.org
2020-07-02T21:44:45.024Z pid=1807172 tid=go3qqgj28 INFO: Booting Sidekiq 6.0.4 with redis options {:id=>"Sidekiq-server-PID-1807172", :url=>nil}
2020-07-02T21:44:45.027Z pid=1807172 tid=go3qqgj28 INFO: Loading Schedule
2020-07-02T21:44:45.028Z pid=1807172 tid=go3qqgj28 INFO: Scheduling every_minute_worker {"cron"=>"0 * * * * *", "class"=>"EveryMinuteWorker", "queue"=>"production"}
2020-07-02T21:44:45.031Z pid=1807172 tid=go3qqgj28 INFO: Scheduling daily_job_worker {"cron"=>"00 12 * * * America/Detroit", "class"=>"DailyJobWorker", "queue"=>"production"}
2020-07-02T21:44:45.036Z pid=1807172 tid=go3qqgj28 INFO: Schedules Loaded
2020-07-02T21:44:51.599Z pid=1807172 tid=go3rto2tc class=EnumerationWorker jid=6c151ebb7275ac6d3eda1f24 INFO: start
2020-07-02T21:45:00.044Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:45:00.044Z pid=1807172 tid=go3rto384 class=EveryMinuteWorker jid=a54d8cacf904da8599eafb98 INFO: start
2020-07-02T21:45:02.313Z pid=1807172 tid=go3rto384 class=EveryMinuteWorker jid=a54d8cacf904da8599eafb98 elapsed=2.268 INFO: done
2020-07-02T21:45:12.601Z pid=1807172 tid=go3rto384 class=HttpWorker jid=949ba99e2dae36872d3a6bfd INFO: start
2020-07-02T21:45:12.602Z pid=1807172 tid=go3rto19s class=HttpsWorker jid=981f165c4daa82b4c0c065bc INFO: start
2020-07-02T21:46:00.102Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:46:00.102Z pid=1807172 tid=go3rto0nc class=EveryMinuteWorker jid=1aecdcc734c173c953bb6052 INFO: start
2020-07-02T21:46:02.501Z pid=1807172 tid=go3rto0nc class=EveryMinuteWorker jid=1aecdcc734c173c953bb6052 elapsed=2.399 INFO: done
2020-07-02T21:47:00.160Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:47:00.160Z pid=1807172 tid=go3rto1us class=EveryMinuteWorker jid=c5d878b4884d6bffeed222ba INFO: start
2020-07-02T21:47:03.009Z pid=1807172 tid=go3rto1us class=EveryMinuteWorker jid=c5d878b4884d6bffeed222ba elapsed=2.849 INFO: done
2020-07-02T21:48:00.222Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:48:00.223Z pid=1807172 tid=go3rto0gk class=EveryMinuteWorker jid=c05a9e7548c76a986ff90b2c INFO: start
2020-07-02T21:48:02.581Z pid=1807172 tid=go3rto0gk class=EveryMinuteWorker jid=c05a9e7548c76a986ff90b2c elapsed=2.358 INFO: done
2020-07-02T21:49:00.282Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:49:00.283Z pid=1807172 tid=go3rto0gk class=EveryMinuteWorker jid=1c00160fa0d8c909dc874ca0 INFO: start
2020-07-02T21:49:02.653Z pid=1807172 tid=go3rto0gk class=EveryMinuteWorker jid=1c00160fa0d8c909dc874ca0 elapsed=2.369 INFO: done
2020-07-02T21:50:00.042Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:50:00.043Z pid=1807172 tid=go3rto1h0 class=EveryMinuteWorker jid=3eae22a8af2730a0c524727a INFO: start
2020-07-02T21:51:00.102Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:51:00.102Z pid=1807172 tid=go3rto218 class=EveryMinuteWorker jid=6ccbbd6e7dec18c5b0cd270d INFO: start
2020-07-02T21:52:00.159Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:52:00.160Z pid=1807172 tid=go3rto0co class=EveryMinuteWorker jid=521026754ce0d517fa2dcd33 INFO: start
2020-07-02T21:53:00.218Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:53:00.219Z pid=1807172 tid=go3rto0gk class=EveryMinuteWorker jid=ce17658e7bf76c25adfeabae INFO: start
2020-07-02T21:54:00.275Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:54:00.276Z pid=1807172 tid=go3rto2f0 class=EveryMinuteWorker jid=a9ba8969acae516b07d837bd INFO: start
2020-07-02T21:55:00.033Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:55:00.034Z pid=1807172 tid=go3rto0nc class=EveryMinuteWorker jid=2d66f0045c8ab7bcb28fa28b INFO: start
2020-07-02T21:56:00.093Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:56:00.094Z pid=1807172 tid=go3rto1us class=EveryMinuteWorker jid=285067110201c2586a7fd07c INFO: start
2020-07-02T21:57:00.151Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:58:00.207Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T21:59:00.263Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:00:00.020Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:01:00.077Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:01:02.176Z pid=1807172 tid=go3rto384 class=HttpWorker jid=949ba99e2dae36872d3a6bfd elapsed=949.575 INFO: done
2020-07-02T22:01:02.177Z pid=1807172 tid=go3rto384 class=EveryMinuteWorker jid=a856fc66c1a0e81046714c71 INFO: start
2020-07-02T22:02:00.136Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:03:00.196Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:04:00.254Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:05:00.012Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:06:00.072Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:07:00.131Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:08:00.190Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:09:00.248Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:10:00.006Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:11:00.062Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:12:00.120Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:13:00.178Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:14:00.234Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:15:00.291Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:16:00.050Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:17:00.109Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:18:00.167Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:19:00.224Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:20:00.282Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:20:49.618Z pid=1807172 tid=go3rto19s class=HttpsWorker jid=981f165c4daa82b4c0c065bc elapsed=2137.017 INFO: done
2020-07-02T22:20:49.619Z pid=1807172 tid=go3rto19s class=EveryMinuteWorker jid=72cc6c5060105e45e872c7f6 INFO: start
2020-07-02T22:20:53.160Z pid=1807172 tid=go3rto2tc class=EnumerationWorker jid=6c151ebb7275ac6d3eda1f24 elapsed=2161.56 INFO: done
2020-07-02T22:20:53.161Z pid=1807172 tid=go3rto2tc class=EveryMinuteWorker jid=358f556d7f5e49ad0130b1b5 INFO: start
2020-07-02T22:20:56.982Z pid=1807172 tid=go3rto1h0 class=EveryMinuteWorker jid=3eae22a8af2730a0c524727a elapsed=1856.938 INFO: done
2020-07-02T22:20:56.983Z pid=1807172 tid=go3rto1h0 class=EveryMinuteWorker jid=fecc3022964b8c2833381033 INFO: start
2020-07-02T22:21:00.066Z pid=1807172 tid=otv92mi6o INFO: queueing EveryMinuteWorker (every_minute_worker)
2020-07-02T22:21:04.267Z pid=1807172 tid=go3rto0nc class=EveryMinuteWorker jid=2d66f0045c8ab7bcb28fa28b elapsed=1564.233 INFO: done
2020-07-02T22:21:04.268Z pid=1807172 tid=go3rto0nc class=EveryMinuteWorker jid=4dc55fec933e63d8a2375928 INFO: start
2020-07-02T22:21:04.396Z pid=1807172 tid=go3rto0gk class=EveryMinuteWorker jid=ce17658e7bf76c25adfeabae elapsed=1684.177 INFO: done
2020-07-02T22:21:04.406Z pid=1807172 tid=go3rto1h0 class=EveryMinuteWorker jid=fecc3022964b8c2833381033 elapsed=7.423 INFO: done
2020-07-02T22:21:04.507Z pid=1807172 tid=go3rto384 class=EveryMinuteWorker jid=a856fc66c1a0e81046714c71 elapsed=1202.33 INFO: done
2020-07-02T22:21:04.543Z pid=1807172 tid=go3rto2f0 class=EveryMinuteWorker jid=a9ba8969acae516b07d837bd elapsed=1624.267 INFO: done
2020-07-02T22:21:04.842Z pid=1807172 tid=go3rto0co class=EveryMinuteWorker jid=521026754ce0d517fa2dcd33 elapsed=1744.682 INFO: done
2020-07-02T22:21:05.051Z pid=1807172 tid=go3rto2tc class=EveryMinuteWorker jid=358f556d7f5e49ad0130b1b5 elapsed=11.89 INFO: done
2020-07-02T22:21:05.077Z pid=1807172 tid=go3rto19s class=EveryMinuteWorker jid=72cc6c5060105e45e872c7f6 elapsed=15.458 INFO: done
2020-07-02T22:21:05.097Z pid=1807172 tid=go3rto1us class=EveryMinuteWorker jid=285067110201c2586a7fd07c elapsed=1505.003 INFO: done
2020-07-02T22:21:05.223Z pid=1807172 tid=go3rto218 class=EveryMinuteWorker jid=6ccbbd6e7dec18c5b0cd270d elapsed=1805.121 INFO: done
2020-07-02T22:21:06.930Z pid=1807172 tid=go3rto0nc class=EveryMinuteWorker jid=4dc55fec933e63d8a2375928 elapsed=2.663 INFO: done
What would cause this to happen and what may I be able to do to resolve this issue?
Upvotes: 0
Views: 467
Reputation: 15985
You need to create queues and give weightage to each to prioritise.
https://github.com/mperham/sidekiq/wiki/Advanced-Options
Also check how many concurrent threads are configured and optimize as per your need. Be careful here, as there is relation between sidekiq threads and database connection pool. Check out https://dev.to/appaloosastore/active-record-sidekiq-pools-and-threads-18d5
Upvotes: 1