Sidekiq: ActiveRecord::ConnectionTimeoutError with rails eager loading

[DemonGiggle]

Ruby version: 2.5.0
Sidekiq / Pro / Enterprise version(s): Sidekiq 5.1.3
Rails version: 5.1.5

Please include your initializer and any error message with the full backtrace.

# config/initializers/sidekiq.rb

Sidekiq.configure_server do |config|
  config.redis = { url: Cfg['redis']['url'] }
end

Sidekiq.configure_client do |config|
  config.redis = { url: Cfg['redis']['url'] }
end

backtrace

ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use
  from active_record/connection_adapters/abstract/connection_pool.rb:202:in `block in wait_poll'
  from active_record/connection_adapters/abstract/connection_pool.rb:193:in `loop'
  from active_record/connection_adapters/abstract/connection_pool.rb:193:in `wait_poll'
  from active_record/connection_adapters/abstract/connection_pool.rb:154:in `internal_poll'
  from active_record/connection_adapters/abstract/connection_pool.rb:278:in `internal_poll'
  from active_record/connection_adapters/abstract/connection_pool.rb:148:in `block in poll'
  from monitor.rb:226:in `mon_synchronize'
  from active_record/connection_adapters/abstract/connection_pool.rb:158:in `synchronize'
  from active_record/connection_adapters/abstract/connection_pool.rb:148:in `poll'
  from active_record/connection_adapters/abstract/connection_pool.rb:747:in `acquire_connection'
  from active_record/connection_adapters/abstract/connection_pool.rb:500:in `checkout'
  from active_record/connection_adapters/abstract/connection_pool.rb:374:in `connection'
  from active_record/connection_adapters/abstract/connection_pool.rb:931:in `retrieve_connection'
  from active_record/connection_handling.rb:116:in `retrieve_connection'
  from active_record/connection_handling.rb:88:in `connection'
  from active_record/relation/delegation.rb:44:in `connection'
  from active_record/relation/query_methods.rb:81:in `bound_attributes'
  from active_record/relation.rb:678:in `exec_queries'
  from active_record/relation.rb:546:in `load'
  from active_record/relation.rb:255:in `records'
  from active_record/relation/finder_methods.rb:508:in `find_take'
  from active_record/relation/finder_methods.rb:100:in `take'
  from active_record/relation/finder_methods.rb:458:in `find_one'
  from active_record/relation/finder_methods.rb:440:in `find_with_ids'
  from active_record/relation/finder_methods.rb:66:in `find'
  from active_record/querying.rb:3:in `find'
  from active_record/core.rb:171:in `find'
  from app/workers/test_worker.rb:6:in `perform'
  from sidekiq/processor.rb:187:in `execute_job'
  from sidekiq/processor.rb:169:in `block (2 levels) in process'
  from sidekiq/middleware/chain.rb:128:in `block in invoke'
  from raven/integrations/sidekiq.rb:9:in `call'
  from sidekiq/middleware/chain.rb:130:in `block in invoke'
  from sidekiq/middleware/chain.rb:133:in `invoke'
  from sidekiq/processor.rb:168:in `block in process'
  from sidekiq/processor.rb:139:in `block (6 levels) in dispatch'
  from sidekiq/job_retry.rb:98:in `local'
  from sidekiq/processor.rb:138:in `block (5 levels) in dispatch'
  from sidekiq/rails.rb:42:in `block in call'
  from active_support/execution_wrapper.rb:85:in `wrap'
  from active_support/reloader.rb:68:in `block in wrap'
  from active_support/execution_wrapper.rb:85:in `wrap'
  from active_support/reloader.rb:67:in `wrap'
  from sidekiq/rails.rb:41:in `call'
  from sidekiq/processor.rb:134:in `block (4 levels) in dispatch'
  from sidekiq/processor.rb:199:in `stats'
  from sidekiq/processor.rb:129:in `block (3 levels) in dispatch'
  from sidekiq/job_logger.rb:8:in `call'
  from sidekiq/processor.rb:128:in `block (2 levels) in dispatch'
  from sidekiq/job_retry.rb:73:in `global'
  from sidekiq/processor.rb:127:in `block in dispatch'
  from sidekiq/logging.rb:48:in `with_context'
  from sidekiq/logging.rb:42:in `with_job_hash_context'
  from sidekiq/processor.rb:126:in `dispatch'
  from sidekiq/processor.rb:167:in `process'
  from sidekiq/processor.rb:85:in `process_one'
  from sidekiq/processor.rb:73:in `run'
  from sidekiq/util.rb:16:in `watchdog'
  from sidekiq/util.rb:25:in `block in safe_thread'

Are you using an old version? No
Have you checked the changelogs to see if your issue has been fixed in a later version? Yes

https://github.com/mperham/sidekiq/blob/master/Changes.md
https://github.com/mperham/sidekiq/blob/master/Pro-Changes.md
https://github.com/mperham/sidekiq/blob/master/Ent-Changes.md

Description

Actually, I think I found the root cause. Here is my test worker.

class TestWorker
  include Sidekiq::Worker

  def perform(user_id)
    dump_rails_thread_cached_conn
    dump_thread_backtraces

    user = User.find(user_id)
    user.touch
    sleep 6
  end

  def dump_rails_thread_cached_conn
    t_conns =ActiveRecord::Base.connection_pool.instance_variable_get("@thread_cached_conns")
    t_conns.each_pair { |k, v| puts "cached #{k} => #{v}\n" }
  end 

  def dump_thread_backtraces
    Thread.list.each do |t| 
      puts "thread #{t}"
      t.backtrace.each { |bt| puts bt }
    end 
  end 
end

sidekiq.yml

:concurrency: <%= ENV.fetch("RAILS_MAX_THREADS") { 5 } %>
:queues:
  - ['default', 2]

The rails cached connection would have the keys from thread object. By comparing with all thread objects, I found the main thread of sidekiq was helding a database connection.

After further investigation, I found after this line, rails will eager loading classes which would in turn accessing database.
https://github.com/mperham/sidekiq/blob/v5.1.3/lib/sidekiq/cli.rb#L272

I end up with the following solution in config/initializers/sidekiq.rb

Sidekiq.configure_server do |config|
  config.redis = { url: Cfg['redis']['url'] }
  config.on(:startup) do
    ActiveRecord::Base.clear_active_connections!
  end 
end

Sidekiq.configure_client do |config|
  config.redis = { url: Cfg['redis']['url'] }
end

I don't know whether it should be sidekiq to release the db connection after main thread initialize environment.rb or it's application side to clear up the connections.

Either way, this could give hint for someone who suffers the same issue and he or she makes sure there is no extra thread to steal the connection.

[mperham]

Good tip, thanks for the detail. It's a bad idea to access models within app initializers but it's very common. I wonder if Rails should add a fix for this and have the main thread release any held db connection upon app boot completion.

[mperham]

@matthewd Any tips here? Is it possible for Rails to clean up DB conn usage on the main thread after boot is complete? I could add ActiveRecord::Base.clear_active_connections! in an after_initialize block.

[mperham]

I can't reproduce the problem on Rails 5.2 and can't easily downgrade to 5.1.5. Can you try 5.2?

[matthewd]

I wonder if Rails should add a fix for this and have the main thread release any held db connection upon app boot completion.

Here's one I prepared earlier :wink: https://github.com/rails/rails/pull/31221

[mperham]

Yep, looks like AR clears active connections after initialize in 5.2. Upgrade and this won't be a problem anymore.

[matthewd]

Oh, the part you're interested in was actually added by https://github.com/rails/rails/pull/28057. As you've noted, though, they're both in 5.2.

You could certainly add such a call to make life better for people on older Rails versions, but if they've survived this far, yeah, I'd recommend upgrading as the fix.

[brian-kephart]

Zombie issue alert. I'm experiencing this on newer versions after installing Sidekiq this week.

Rails 6.0.3.1
Sidekiq 6.0.7
Ruby 2.7.1

In short, I was receiving connection pool errors despite using RAILS_MAX_THREADS for both the db pool and sidekiq concurrency. I successfully resolved the issue with the instructions in this issue report:

Sidekiq.configure_server do |config|
  config.on(:startup) do
    ActiveRecord::Base.clear_active_connections!
  end 
end

This issue was supposed to be fixed in Rails 5.2, so I'm wondering if a more recent change in Rails resurfaced it.

Even if it's a Rails issue, I'd like this to be considered for addition to the wiki. I spent hours searching for the cause of this issue, because searching for the error message buries this page under results about other problems/fixes (AR pool size, RAILS_MAX_THREADS, explicitly starting threads within jobs...). I'm speaking here as a first-time Sidekiq user who ran into this problem immediately.

[zhyhun-ivan]

Is there any update on this issue? Have the same problem using rails 6.0.3.2

[allomov]

I have the same issue with Rails 6.0.3.2