Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Client hitting ConnectionPool::TimeoutError in Sidekiq 7 #5702

Closed
andreccosta opened this issue Dec 21, 2022 · 11 comments
Closed

Client hitting ConnectionPool::TimeoutError in Sidekiq 7 #5702

andreccosta opened this issue Dec 21, 2022 · 11 comments

Comments

@andreccosta
Copy link

Ruby version: 3.1.3
Rails version: 7.0.4
Sidekiq / Pro / Enterprise version(s): Sidekiq 7.0.2 / Pro 7.0.5

We are seeing very sporadic ConnectionPool:TimeoutError happening in our client web/puma process.
Since the default concurrency changed from 10 to 5 in Sidekiq 7 (and we didn't face this issue before the upgrade) our first instinct was to up the size of the client connection pool to 10.

Relevant parts of our initializer:

Sidekiq.configure_client do |config|
  config.redis = {
    host: ENV.fetch("REDIS_HOST"),
    password: ENV.fetch("REDIS_PASSWORD"),
    size: 10
  }
end

However adding size: 10 in the initializer had no effect. From what I can gather the client is using the "internal" connection pool which seems to be hard-coded to always have the size of 5 regardless of configuration. And since in Sidekiq 7 these pools are managed internally creating a different connection pool is not an option.

I should add that we are very far from hitting either CPU or connections limit in our Redis instance.

Is the client connection pool size not meant to be configurable in this way?

@mperham
Copy link
Collaborator

mperham commented Dec 21, 2022

Please supply the full backtrace of the error.

@andreccosta
Copy link
Author

Sure. Here's the backtrace:

ConnectionPool::TimeoutError: Waited 1 sec, 0/5 available
  /app/vendor/bundle/ruby/3.1.0/gems/connection_pool-2.3.0/lib/connection_pool/timed_stack.rb:77:in `block (2 levels) in pop'
  /app/vendor/bundle/ruby/3.1.0/gems/connection_pool-2.3.0/lib/connection_pool/timed_stack.rb:69:in `loop'
  /app/vendor/bundle/ruby/3.1.0/gems/connection_pool-2.3.0/lib/connection_pool/timed_stack.rb:69:in `block in pop'
  /app/vendor/bundle/ruby/3.1.0/gems/connection_pool-2.3.0/lib/connection_pool/timed_stack.rb:68:in `synchronize'
  /app/vendor/bundle/ruby/3.1.0/gems/connection_pool-2.3.0/lib/connection_pool/timed_stack.rb:68:in `pop'
  /app/vendor/bundle/ruby/3.1.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:80:in `checkout'
  /app/vendor/bundle/ruby/3.1.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:62:in `block in with'
  /app/vendor/bundle/ruby/3.1.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `handle_interrupt'
  /app/vendor/bundle/ruby/3.1.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `with'
  /app/vendor/bundle/ruby/3.1.0/gems/sidekiq-7.0.2/lib/sidekiq/client.rb:211:in `raw_push'
  /app/vendor/bundle/ruby/3.1.0/gems/sidekiq-pro-7.0.5/lib/sidekiq/batch/client.rb:40:in `raw_push'
  /app/vendor/bundle/ruby/3.1.0/gems/sidekiq-pro-7.0.5/lib/sidekiq/pro/push.rb:41:in `raw_push'
  /app/vendor/bundle/ruby/3.1.0/gems/sidekiq-7.0.2/lib/sidekiq/client.rb:92:in `push'
  /app/vendor/bundle/ruby/3.1.0/gems/sidekiq-7.0.2/lib/sidekiq/job.rb:365:in `client_push'
  /app/vendor/bundle/ruby/3.1.0/gems/sidekiq-7.0.2/lib/sidekiq/job.rb:198:in `perform_async'
  /app/vendor/bundle/ruby/3.1.0/gems/sidekiq-7.0.2/lib/sidekiq/job.rb:290:in `perform_async'
  /app/app/controllers/api/v1/data_controller.rb:261:in `send_data_async'
  /app/app/controllers/api/v1/data_controller.rb:16:in `send_data'

@mperham
Copy link
Collaborator

mperham commented Dec 21, 2022

Sidekiq logs when it actually instantiates a connection pool:

logger&.info { "Sidekiq #{Sidekiq::VERSION} connecting to Redis with options #{scrub(symbolized_options)}" }

Add a puts right before config.redis = { in your configure_client block and see if the connection pool is being created before that block runs (i.e. the log comes before the puts).

@mperham
Copy link
Collaborator

mperham commented Dec 21, 2022

The connection pool is timing out after 1 sec. It shouldn't take more than a few ms to push a job to Redis unless you have something very unusual going on. You need to get backtraces from all threads in the process to determine why 5 threads are actively holding a Redis connection.

@andreccosta
Copy link
Author

Added a log and can confirm the connection pool is being created after the block runs.

web  | [WARN] Sidekiq client config initialized
web  | 2022-12-21T19:48:53.132Z pid=30 tid=2cxe INFO: Sidekiq 7.0.2 connecting to Redis with options {:host=>"redis", :password=>"REDACTED", :size=>5, :pool_name=>"internal", :url=>nil}

I should have stressed how sporadic this has been happening as well. There were 4 occurrences in the last 3 days.
We run with 40 threads on the puma processes and deal with significant traffic from webhooks.
We'll keep looking into it to try and figure out if there may be additional factors at play here such as latency.

@mperham
Copy link
Collaborator

mperham commented Dec 21, 2022

And if you change to size: 10, the log still says 5?

@andreccosta
Copy link
Author

andreccosta commented Dec 21, 2022

And if you change to size: 10, the log still says 5?

Yes. I never changed it back it. It still has size: 10 set.

@mperham
Copy link
Collaborator

mperham commented Dec 21, 2022

Please post your entire initializer.

@andreccosta
Copy link
Author

Sidekiq::Client.reliable_push! unless Rails.env.test?
Sidekiq::Enterprise.unique! unless Rails.env.test?
Sidekiq.strict_args!

Sidekiq.configure_client do |config|
  config.redis = {
    host: ENV.fetch("REDIS_HOST"),
    password: ENV.fetch("REDIS_PASSWORD"),
    size: 10
  }
end

Sidekiq.configure_server do |config|
  config.redis = {host: ENV.fetch("REDIS_HOST"), password: ENV.fetch("REDIS_PASSWORD")}
  config.logger.formatter = Sidekiq::Logger::Formatters::Base.new
  config.super_fetch!
  config.reliable_scheduler!
end

@mperham
Copy link
Collaborator

mperham commented Dec 21, 2022

Move the first three lines to the bottom.

@andreccosta
Copy link
Author

andreccosta commented Dec 21, 2022

For the sake of completeness I also added back the log line. Here's the full initializer after the update:

Sidekiq.configure_client do |config|
  Rails.logger.warn("Sidekiq client config initialized")

  config.redis = {
    host: ENV.fetch("REDIS_HOST"),
    password: ENV.fetch("REDIS_PASSWORD"),
    size: 10
  }
end

Sidekiq.configure_server do |config|
  config.redis = {host: ENV.fetch("REDIS_HOST"), password: ENV.fetch("REDIS_PASSWORD")}
  config.logger.formatter = Sidekiq::Logger::Formatters::Base.new
  config.super_fetch!
  config.reliable_scheduler!
end

Sidekiq::Client.reliable_push! unless Rails.env.test?
Sidekiq::Enterprise.unique! unless Rails.env.test?
Sidekiq.strict_args!

And the resulting log:

web  | [WARN] Sidekiq client config initialized
web  | 2022-12-21T21:12:17.238Z pid=31 tid=2cxf INFO: Sidekiq 7.0.2 connecting to Redis with options {:host=>"redis", :password=>"REDACTED", :size=>5, :pool_name=>"internal", :url=>nil}

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants