CODEWITHSUNDEEP
ruby-on-railsredissidekiqrails-activejob
lobati
lobati

Reputation: 10215

Rails Redis commands timing out requests

We're seeing occasional timeouts in our application that appear to trace to Redis, though I'm not entirely sure. We have a module that we include in some of our jobs to reduce duplication of heavier work:

module UniqueEnqueable

  require 'sidekiq/api'
  extend ActiveSupport::Concern

  included do
    before_enqueue do |job|
      throw(:abort) if already_queued_or_scheduled?(job.queue_name, job.arguments)
    end
  end

private

  def already_queued_or_scheduled?(queue_name, arguments)
    serialized_args = ActiveJob::Arguments.serialize(arguments)

    queued_jobs(queue_name).any? { |job| matches?(job, serialized_args) } ||
      scheduled_jobs.any? { |job| matches?(job, serialized_args) }
  end

  def matches?(job, serialized_args)
    active_job?(job) && class_and_args(job) == [self.class.to_s, serialized_args]
  end

  def active_job?(job)
    job.item['class'] == 'ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper'
  end

  def class_and_args(job)
    job.args[0].slice('job_class', 'arguments').values
  end

  def queued_jobs(queue_name)
    Sidekiq::Queue.new(queue_name)
  end

  def scheduled_jobs
    Sidekiq::ScheduledSet.new
  end

end

And we're seeing timeout errors coming from inside of redis where it appears to be taking a long time synchronizing requests:

 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/connection/ruby.rb:68 :in `select`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/connection/ruby.rb:68 :in `rescue in _read_from_socket`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/connection/ruby.rb:64 :in `_read_from_socket`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/connection/ruby.rb:56 :in `gets`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/connection/ruby.rb:363 :in `read`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/client.rb:265 :in `block in read`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/client.rb:253 :in `io`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/client.rb:264 :in `read`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/client.rb:123 :in `block in call`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/client.rb:234 :in `block (2 levels) in process`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/client.rb:372 :in `ensure_connected`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/client.rb:224 :in `block in process`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/client.rb:309 :in `logging`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/client.rb:223 :in `process`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis/client.rb:123 :in `call`
 [GEM_ROOT]/gems/scout_apm-2.4.20/lib/scout_apm/instruments/redis.rb:32 :in `block in call_with_scout_instruments`
 [GEM_ROOT]/gems/scout_apm-2.4.20/lib/scout_apm/tracer.rb:34 :in `instrument`
 [GEM_ROOT]/gems/scout_apm-2.4.20/lib/scout_apm/tracer.rb:44 :in `instrument`
 [GEM_ROOT]/gems/scout_apm-2.4.20/lib/scout_apm/instruments/redis.rb:31 :in `call_with_scout_instruments`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis.rb:1075 :in `block in llen`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis.rb:50 :in `block in synchronize`
 [PROJECT_ROOT]/vendor/ruby-2.5.1/lib/ruby/2.5.0/monitor.rb:226 :in `mon_synchronize`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis.rb:50 :in `synchronize`
 [GEM_ROOT]/gems/redis-4.0.3/lib/redis.rb:1074 :in `llen`
 [GEM_ROOT]/gems/sidekiq-5.2.3/lib/sidekiq/api.rb:242 :in `block in size`
 [GEM_ROOT]/gems/sidekiq-5.2.3/lib/sidekiq.rb:95 :in `block in redis`
 [GEM_ROOT]/gems/connection_pool-2.2.2/lib/connection_pool.rb:65 :in `block (2 levels) in with`
 [GEM_ROOT]/gems/connection_pool-2.2.2/lib/connection_pool.rb:64 :in `handle_interrupt`
 [GEM_ROOT]/gems/connection_pool-2.2.2/lib/connection_pool.rb:64 :in `block in with`
 [GEM_ROOT]/gems/connection_pool-2.2.2/lib/connection_pool.rb:61 :in `handle_interrupt`
 [GEM_ROOT]/gems/connection_pool-2.2.2/lib/connection_pool.rb:61 :in `with`
 [GEM_ROOT]/gems/sidekiq-5.2.3/lib/sidekiq.rb:92 :in `redis`
 [GEM_ROOT]/gems/sidekiq-5.2.3/lib/sidekiq/api.rb:242 :in `size`
 [GEM_ROOT]/gems/sidekiq-5.2.3/lib/sidekiq/api.rb:283 :in `each`
 [PROJECT_ROOT]/app/jobs/concerns/unique_enqueable.rb:17 :in `any?`
 [PROJECT_ROOT]/app/jobs/concerns/unique_enqueable.rb:17 :in `already_queued_or_scheduled?`
 [PROJECT_ROOT]/app/jobs/concerns/unique_enqueable.rb:8 :in `block (2 levels) in <module:UniqueEnqueable>`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:413 :in `instance_exec`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:413 :in `block in make_lambda`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:197 :in `block (2 levels) in halting`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:601 :in `block (2 levels) in default_terminator`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:600 :in `catch`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:600 :in `block in default_terminator`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:198 :in `block in halting`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:507 :in `block in invoke_before`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:507 :in `each`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:507 :in `invoke_before`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:106 :in `block in run_callbacks`
 [GEM_ROOT]/gems/activejob-5.1.6/lib/active_job/logging.rb:15 :in `block (3 levels) in <module:Logging>`
 [GEM_ROOT]/gems/activejob-5.1.6/lib/active_job/logging.rb:44 :in `block in tag_logger`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:69 :in `block in tagged`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:26 :in `tagged`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:69 :in `tagged`
 [GEM_ROOT]/gems/activejob-5.1.6/lib/active_job/logging.rb:44 :in `tag_logger`
 [GEM_ROOT]/gems/activejob-5.1.6/lib/active_job/logging.rb:14 :in `block (2 levels) in <module:Logging>`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117 :in `instance_exec`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117 :in `block in run_callbacks`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:135 :in `run_callbacks`
 [GEM_ROOT]/gems/activejob-5.1.6/lib/active_job/enqueuing.rb:47 :in `enqueue`
 [GEM_ROOT]/gems/activejob-5.1.6/lib/active_job/enqueuing.rb:18 :in `perform_later`
 [PROJECT_ROOT]/app/domains/responses/creator.rb:66 :in `call`
 [PROJECT_ROOT]/app/controllers/responses_controller.rb:68 :in `create`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_controller/metal/basic_implicit_render.rb:4 :in `send_action`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/abstract_controller/base.rb:186 :in `process_action`
 [GEM_ROOT]/gems/scout_apm-2.4.20/lib/scout_apm/instruments/action_controller_rails_3_rails4.rb:72 :in `process_action`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_controller/metal/rendering.rb:30 :in `process_action`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/abstract_controller/callbacks.rb:20 :in `block in process_action`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:108 :in `block in run_callbacks`
 [GEM_ROOT]/gems/react-rails-2.4.7/lib/react/rails/controller_lifecycle.rb:31 :in `use_react_component_helper`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:117 :in `block in run_callbacks`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:135 :in `run_callbacks`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/abstract_controller/callbacks.rb:19 :in `process_action`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_controller/metal/rescue.rb:20 :in `process_action`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_controller/metal/instrumentation.rb:32 :in `block in process_action`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/notifications.rb:166 :in `block in instrument`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/notifications/instrumenter.rb:21 :in `instrument`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/notifications.rb:166 :in `instrument`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_controller/metal/instrumentation.rb:30 :in `process_action`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_controller/metal/params_wrapper.rb:252 :in `process_action`
 [GEM_ROOT]/gems/activerecord-5.1.6/lib/active_record/railties/controller_runtime.rb:22 :in `process_action`
 [GEM_ROOT]/gems/scout_apm-2.4.20/lib/scout_apm/instruments/action_controller_rails_3_rails4.rb:83 :in `process_action`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/abstract_controller/base.rb:124 :in `process`
 [GEM_ROOT]/gems/actionview-5.1.6/lib/action_view/rendering.rb:30 :in `process`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_controller/metal.rb:189 :in `dispatch`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_controller/metal.rb:253 :in `dispatch`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/routing/route_set.rb:49 :in `dispatch`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/routing/route_set.rb:31 :in `serve`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/journey/router.rb:50 :in `block in serve`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/journey/router.rb:33 :in `each`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/journey/router.rb:33 :in `serve`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/routing/route_set.rb:844 :in `call`
 [GEM_ROOT]/gems/scout_apm-2.4.20/lib/scout_apm/instruments/rails_router.rb:29 :in `call_with_scout_instruments`
 [GEM_ROOT]/gems/scout_apm-2.4.20/lib/scout_apm/middleware.rb:17 :in `call`
 [GEM_ROOT]/gems/rack-attack-5.4.2/lib/rack/attack.rb:182 :in `call`
 [GEM_ROOT]/gems/rack-2.0.6/lib/rack/etag.rb:25 :in `call`
 [GEM_ROOT]/gems/rack-2.0.6/lib/rack/conditional_get.rb:38 :in `call`
 [GEM_ROOT]/gems/rack-2.0.6/lib/rack/head.rb:12 :in `call`
 [GEM_ROOT]/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:232 :in `context`
 [GEM_ROOT]/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:226 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/middleware/cookies.rb:613 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/middleware/callbacks.rb:26 :in `block in call`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/callbacks.rb:97 :in `run_callbacks`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/middleware/callbacks.rb:24 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/middleware/debug_exceptions.rb:59 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/middleware/show_exceptions.rb:31 :in `call`
 [GEM_ROOT]/gems/railties-5.1.6/lib/rails/rack/logger.rb:36 :in `call_app`
 [GEM_ROOT]/gems/railties-5.1.6/lib/rails/rack/logger.rb:24 :in `block in call`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:69 :in `block in tagged`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:26 :in `tagged`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/tagged_logging.rb:69 :in `tagged`
 [GEM_ROOT]/gems/railties-5.1.6/lib/rails/rack/logger.rb:24 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/middleware/remote_ip.rb:79 :in `call`
 [GEM_ROOT]/gems/request_store-1.4.1/lib/request_store/middleware.rb:19 :in `call`
 [GEM_ROOT]/gems/rack-timeout-0.5.1/lib/rack/timeout/core.rb:123 :in `block in call`
 [GEM_ROOT]/gems/rack-timeout-0.5.1/lib/rack/timeout/support/timeout.rb:19 :in `timeout`
 [GEM_ROOT]/gems/rack-timeout-0.5.1/lib/rack/timeout/core.rb:122 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/middleware/request_id.rb:25 :in `call`
 [GEM_ROOT]/gems/rack-2.0.6/lib/rack/method_override.rb:22 :in `call`
 [GEM_ROOT]/gems/rack-2.0.6/lib/rack/runtime.rb:22 :in `call`
 [GEM_ROOT]/gems/activesupport-5.1.6/lib/active_support/cache/strategy/local_cache_middleware.rb:27 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/middleware/executor.rb:12 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/middleware/static.rb:125 :in `call`
 [GEM_ROOT]/gems/font_assets-0.1.14/lib/font_assets/middleware.rb:17 :in `block in call`
 [GEM_ROOT]/gems/font_assets-0.1.14/lib/font_assets/middleware.rb:40 :in `do_request`
 [GEM_ROOT]/gems/font_assets-0.1.14/lib/font_assets/middleware.rb:16 :in `call`
 [GEM_ROOT]/gems/rack-2.0.6/lib/rack/sendfile.rb:111 :in `call`
 [GEM_ROOT]/gems/actionpack-5.1.6/lib/action_dispatch/middleware/ssl.rb:68 :in `call`
 [PROJECT_ROOT]/config/middleware/null_byte_sanitizer.rb:9 :in `call`
 [GEM_ROOT]/gems/rack-utf8_sanitizer-1.6.0/lib/rack/utf8_sanitizer.rb:22 :in `call`
 [GEM_ROOT]/gems/scout_apm-2.4.20/lib/scout_apm/instruments/middleware_summary.rb:58 :in `call`
 [GEM_ROOT]/gems/railties-5.1.6/lib/rails/engine.rb:522 :in `call`
 [GEM_ROOT]/gems/railties-5.1.6/lib/rails/railtie.rb:185 :in `public_send`
 [GEM_ROOT]/gems/railties-5.1.6/lib/rails/railtie.rb:185 :in `method_missing`
 [GEM_ROOT]/gems/rack-2.0.6/lib/rack/static.rb:149 :in `call`
 [GEM_ROOT]/gems/puma-3.12.0/lib/puma/configuration.rb:225 :in `call`
 [GEM_ROOT]/gems/puma-3.12.0/lib/puma/server.rb:658 :in `handle_request`
 [GEM_ROOT]/gems/puma-3.12.0/lib/puma/server.rb:472 :in `process_client`
 [GEM_ROOT]/gems/puma-3.12.0/lib/puma/server.rb:332 :in `block in run`
 [GEM_ROOT]/gems/puma-3.12.0/lib/puma/thread_pool.rb:133 :in `block in spawn_thread`

Any tips as to why this might be happening? Happy to add more information as needed.

Upvotes: 1

Views: 366

Answers (1)

Mike Perham
Mike Perham

Reputation: 22208

The API page says this:

WARNING the API exposes some operations which are not scalable and should not be used in an automated fashion or in bulk as part of your application functionality. You should not be scanning through queues/sets and deleting jobs unless something has gone wrong and you need to repair data manually.

You want this: https://github.com/mperham/sidekiq/wiki/Ent-Unique-Jobs

Upvotes: 2

Related Questions