ActiveRecord::ConnectionTimeoutError "all pooled connections were in use" after enabling concurrency

[MattFenelon]

I recently enabled concurrency on a system and it resulted in a lot of ActiveRecord::ConnectionTimeoutError errors.

I believe it's because ActiveRecord has a 1 thread = 1 connection policy and the database connection pool for this system is limited to the number of puma threads. As soon as the system receives enough requests to use up the connection pool, the concurrently side-loaded resource threads are unable to get a connection from the pool, and vice versa.

But I'm surprised no one has come across this issue before so perhaps I've misunderstood the problem.

One solution might be to increase the system's database connection pool size. This would allow Graphiti's threads to have enough connections to not exhaust the thread pool. The difficulty would be in sizing the db pool. Given each request can sideload x resources, the total number of database connections required at any given time would be x * number of concurrent requests.

Ideally though I think it would make sense to allow the thread pool size to be configured. Concurrent::Promise, used to side-loaded resources, has by default a thread pool equal to java's int max.

What do you think?

vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:128:in `block in wait_poll': could not obtain a connection from the pool within 5.000 seconds (waited 5.005 seconds); all pooled connections were in use (ActiveRecord::ConnectionTimeoutError)
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:117:in `loop'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:117:in `wait_poll'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:78:in `internal_poll'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:204:in `internal_poll'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:73:in `block in poll'
    from vendor/ruby-3.2.2/lib/ruby/3.2.0/monitor.rb:202:in `synchronize'
    from vendor/ruby-3.2.2/lib/ruby/3.2.0/monitor.rb:202:in `mon_synchronize'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:82:in `synchronize'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:73:in `poll'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:663:in `acquire_connection'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:353:in `checkout'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:182:in `connection'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_adapters/abstract/connection_handler.rb:246:in `retrieve_connection'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_handling.rb:287:in `retrieve_connection'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/connection_handling.rb:254:in `connection'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/querying.rb:62:in `_query_by_sql'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/relation.rb:998:in `block in exec_main_query'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/relation.rb:1018:in `skip_query_cache_if_necessary'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/relation.rb:984:in `exec_main_query'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/relation.rb:962:in `block in exec_queries'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/relation.rb:1018:in `skip_query_cache_if_necessary'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/relation.rb:956:in `exec_queries'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/relation.rb:742:in `load'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/relation.rb:264:in `records'
    from vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3/lib/active_record/relation.rb:259:in `to_ary'
    from lib/graphiti_adapters/an_adapter.rb:19:in `resolve'
    from vendor/bundle/ruby/3.2.0/gems/graphiti-1.3.9/lib/graphiti/resource.rb:117:in `resolve'
    from vendor/bundle/ruby/3.2.0/gems/graphiti-1.3.9/lib/graphiti/scope.rb:22:in `block in resolve'
    from vendor/bundle/ruby/3.2.0/gems/graphiti-1.3.9/lib/graphiti/scope.rb:81:in `block in broadcast_data'
    from vendor/bundle/ruby/3.2.0/gems/graphiti-1.3.9/lib/graphiti.rb:65:in `block in broadcast'
    from vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3/lib/active_support/notifications.rb:206:in `block in instrument'
    from vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
    from vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3/lib/active_support/notifications.rb:206:in `instrument'
    from vendor/bundle/ruby/3.2.0/gems/graphiti-1.3.9/lib/graphiti.rb:64:in `broadcast'
    from vendor/bundle/ruby/3.2.0/gems/graphiti-1.3.9/lib/graphiti/scope.rb:80:in `broadcast_data'
    from vendor/bundle/ruby/3.2.0/gems/graphiti-1.3.9/lib/graphiti/scope.rb:20:in `resolve'
    from vendor/bundle/ruby/3.2.0/gems/graphiti-1.3.9/lib/graphiti/resource_proxy.rb:68:in `data'
    from vendor/bundle/ruby/3.2.0/gems/graphiti-1.3.9/lib/graphiti/sideload.rb:231:in `load'
    from vendor/bundle/ruby/3.2.0/gems/graphiti-1.3.9/lib/graphiti/sideload.rb:299:in `resolve'
    from vendor/bundle/ruby/3.2.0/gems/graphiti-1.3.9/lib/graphiti/scope.rb:47:in `block (2 levels) in resolve_sideloads'
    from vendor/bundle/ruby/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'
    from vendor/bundle/ruby/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `block in synchronize'
    from vendor/bundle/ruby/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'
    from vendor/bundle/ruby/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'
    from vendor/bundle/ruby/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'
    from vendor/bundle/ruby/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/promise.rb:564:in `block in realize'
    from vendor/bundle/ruby/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:359:in `run_task'
    from vendor/bundle/ruby/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:350:in `block (3 levels) in create_worker'
    from vendor/bundle/ruby/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `loop'
    from vendor/bundle/ruby/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `block (2 levels) in create_worker'
    from vendor/bundle/ruby/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `catch'
    from vendor/bundle/ruby/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `block in create_worker'

[github-actions]

🎉 This issue has been resolved in version 1.6.0 🎉

The release is available on:

• v1.6.0
• GitHub release

Your semantic-release bot 📦🚀

[jkeen]

@MattFenelon moving our convo from #470 into here.

In short I'm still having a ton of trouble with web server lockups after this change and it's hard to figure out what exactly is going on… but it seems like without this change everything is a-ok. My DB pool values and the sideload thread max values seem to be reasonable, and yet sometimes things will just hang causing the webserver to not respond to requests.

I think we need to roll this thing back and investigate further on an unreleased branch. The part that worries me most is that there's no error message or any sort of clue that this is the issue, meaning there could be people out there with apps breaking without a clear cut cause. Also for me in order to get things running properly again it has required a server restart, which is a real bummer.

I'm going to put out a new patch release without these changes, and then maybe we can work together to try and resolve what's going on by working off a branch?

[MattFenelon]

Sorry to hear that @jkeen. I see you've reverted, that makes sense until we can clear this up.

In terms of diagnosing:

1. What're your puma thread and workers set to?
2. Did you use the default concurrency_max_threads setting?
3. What's pool set to in database.yml?
4. Does your database have a connection limit? If so, what is it?
5. How many dynos/containers/vms do you have running?

[MattFenelon]

The fact that it's locking up completely makes me think it's a deadlock related to the use of the Mutex. I've gone with a different approach in #472 but I haven't been able to test those changes yet. Do you want to give it a try? I can test them in about a week or so.