LoadInterlockAwareMonitor deadlock when clearing cache (multiple databases, test)

[kuahyeow]

With multiple databases, we observe hangs within system tests.

See also https://gitlab.com/gitlab-org/gitlab/-/issues/371468 (GitLab is at Rails 6.1, Ruby 2.7.5)

Steps to reproduce

Here's a minimal reproduction with Rails 7.0.3.1

1. Checkout https://gitlab.com/tkuah/multi_database_system_test
2. bundle install
3. bundle exec rails db:migrate
4. bundle exec rails test test/system/home_pages_test.rb

The conditions are:

1. Multiple databases
2. System test where there's an async request which overlaps with the main thread

Expected behavior

It does not hang, and the test completes

Actual behavior

It hangs. It looks like it's hanging when clearing query cache (see https://gitlab.com/gitlab-org/gitlab/-/issues/371468#note_1087203883, and https://gitlab.com/gitlab-org/gitlab/-/issues/371468#note_1088779499)

A backtrace dump taken while the test is hanging sigdump-68442.log

My suspicion is that:

1. lock_thread is true for system tests
2. Therefore both the main thread, and the Puma thread attempt to clear query cache for the same set of connections

So we have two connections:

1. Puma thread takes a LoadInterlockAwareMonitor lock for primary connection via Post.transaction
2. Main thread takes a LoadInterlockAwareMonitor lock for animal connection via implicit transaction that create does
3. Due to 2, main thread attempts to clear query cache for primary connection. Waits for 1's lock
4. Due to 1, and because of lock_thread, puma thread clears query cache for primary connection. It takes a LoadInterlockAwareMonitor lock for primary connection which succeds
5. Due to 1, puma thread now attempts clears query cache for animal connection. Waits for 2's lock

See clear_query_caches_for_current_thread method

System configuration

Rails version: 7.0.3.1

Ruby version: ruby 2.7.5p203 (2021-11-24 revision f69aeb8314) [arm64-darwin21]

[casperisfine]

So I dug into this a bit.

Your suspicion is correct about the fact that both the puma and the test threads are blocked on the monitor trying to clear the query cache.

However it makes very little sense, because monitor is supposed to be re-entrant. Since the main thread already hold the lock, it should be able to enter the monitor again to clear the query cache without blocking.

I'll keep digging a bit more, but I must admit I'm quite puzzled about this.

[casperisfine]

Essentially what we notice is more or less:

monitor = ActiveSupport::Concurrency::LoadInterlockAwareMonitor.new
monitor.synchronize do
 Thread.new { monitor.synchronize { p 2} }.join(1)
  monitor.synchronize { p 1 }
end

But of course this works as expected. It's very unclear what is special in the reproduction repo so that monitor.synchronize { p 1 } blocks.

[casperisfine]

Oh wow, I tried to add the above snippet in the test case to see if there was anything special, and it does somehow fix the problem:

diff --git a/test/system/home_pages_test.rb b/test/system/home_pages_test.rb
index e2466d4..c4c9571 100644
--- a/test/system/home_pages_test.rb
+++ b/test/system/home_pages_test.rb
@@ -6,6 +6,13 @@ class HomePagesTest < ApplicationSystemTestCase
 
     visit 'home_page/index'
 
+    monitor = ActiveSupport::Concurrency::LoadInterlockAwareMonitor.new
+    monitor.synchronize do
+     Thread.new { monitor.synchronize { p 2} }.join(1)
+      monitor.synchronize { p 1 }
+    end
+
+    Thread.current[:deb] = true
     Animal.create!(name: 'cat')
 
     assert_selector "h1", text: "HomePage"

This is getting really weird.

From my observations the puma thread was blocked inside ActiveSupport::Dependencies.interlock.permit_concurrent_loads { super }, so it seems that having the main thread call permit_concurrent_loads unblocks the whole thing. Still no idea why but that's an interesting clue.

[eileencodes]

One thing that's special about system tests is they need to share the DB thread for the process, otherwise Puma will spin up one thread and Capybara will spin up another and then transactions in tests won't work. I implemented that a long time ago here #28083. I suspect any issues with multi-db and system tests are directly related to that "feature".

[eileencodes]

Or I would check whether parallelization is a component in this as well. Does this occur with PARALLEL_WORKERS set to 1 or 0?

[casperisfine]

One thing that's special about system tests is they need to share the DB thread for the process

Yes I'm aware of that. And both threads are stuck calling clear_query_cache on the same connection. It should work though, since the main (test) thread already entered the monitor.

Does this occur with PARALLEL_WORKERS set to 1 or 0?

It's stuck with both.

[casperisfine]

So to clarify, here's backtrace of both threads:

main (test) thread:

#<Thread:0x000000012785fae8 sleep_forever>

/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:17:in `enter'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:17:in `block in mon_enter'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/dependencies/interlock.rb:41:in `permit_concurrent_loads'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:17:in `mon_enter'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:23:in `block in synchronize'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_adapters/abstract/query_cache.rb:91:in `clear_query_cache'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_handling.rb:343:in `block in clear_on_handler'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_handling.rb:342:in `each'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_handling.rb:342:in `clear_on_handler'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_handling.rb:272:in `clear_query_caches_for_current_thread'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_adapters/abstract/query_cache.rb:21:in `insert'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/persistence.rb:496:in `_insert_record'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/persistence.rb:1096:in `_create_record'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/counter_cache.rb:166:in `_create_record'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/locking/optimistic.rb:79:in `_create_record'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/attribute_methods/dirty.rb:222:in `_create_record'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/callbacks.rb:461:in `block in _create_record'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:99:in `run_callbacks'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:929:in `_run_create_callbacks'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/callbacks.rb:461:in `_create_record'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/timestamp.rb:108:in `_create_record'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/persistence.rb:1067:in `create_or_update'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/callbacks.rb:457:in `block in create_or_update'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:99:in `run_callbacks'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:929:in `_run_save_callbacks'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/callbacks.rb:457:in `create_or_update'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/timestamp.rb:126:in `create_or_update'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/persistence.rb:648:in `save!'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/validations.rb:53:in `save!'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/transactions.rb:302:in `block in save!'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_adapters/abstract/transaction.rb:319:in `block in within_new_transaction'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:27:in `handle_interrupt'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:27:in `block in synchronize'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_adapters/abstract/database_statements.rb:316:in `transaction'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/transactions.rb:302:in `save!'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/suppressor.rb:54:in `save!'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/persistence.rb:55:in `create!'
/Users/byroot/src/github.com/Shopify/multi_database_system_test/test/system/home_pages_test.rb:18:in `block in <class:HomePagesTest>'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest/test.rb:98:in `block (3 levels) in run'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest/test.rb:195:in `capture_exceptions'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest/test.rb:95:in `block (2 levels) in run'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:296:in `time_it'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest/test.rb:94:in `block in run'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:391:in `on_signal'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest/test.rb:243:in `with_info_handler'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest/test.rb:93:in `run'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/executor/test_helper.rb:5:in `block in run'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/execution_wrapper.rb:105:in `perform'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/executor/test_helper.rb:5:in `run'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:1059:in `run_one_method'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:365:in `run_one_method'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:352:in `block (2 levels) in run'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:351:in `each'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:351:in `block in run'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:391:in `on_signal'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:378:in `with_info_handler'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:350:in `run'
/Users/byroot/.gem/ruby/2.7.5/gems/railties-7.0.3.1/lib/rails/test_unit/line_filtering.rb:10:in `run'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:182:in `block in __run'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:182:in `map'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:182:in `__run'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:159:in `run'
/Users/byroot/.gem/ruby/2.7.5/gems/minitest-5.16.3/lib/minitest.rb:83:in `block in autorun'

puma thread

#<Thread:0x00000001131cb448@puma srv tp 004 /Users/byroot/.gem/ruby/2.7.5/gems/puma-5.6.5/lib/puma/thread_pool.rb:104 sleep_forever>

/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:17:in `enter'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:17:in `block in mon_enter'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/dependencies/interlock.rb:41:in `permit_concurrent_loads'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:17:in `mon_enter'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:23:in `block in synchronize'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_adapters/abstract/query_cache.rb:91:in `clear_query_cache'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_handling.rb:343:in `block in clear_on_handler'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_handling.rb:342:in `each'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_handling.rb:342:in `clear_on_handler'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_handling.rb:272:in `clear_query_caches_for_current_thread'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_adapters/abstract/query_cache.rb:21:in `update'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/persistence.rb:513:in `_update_record'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/persistence.rb:1058:in `_update_row'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/locking/optimistic.rb:88:in `_update_row'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/persistence.rb:1054:in `_touch_row'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/locking/optimistic.rb:84:in `_touch_row'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/attribute_methods/dirty.rb:189:in `_touch_row'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/persistence.rb:1004:in `touch'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/callbacks.rb:448:in `block in touch'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:99:in `run_callbacks'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:929:in `_run_touch_callbacks'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/callbacks.rb:448:in `touch'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/transactions.rb:306:in `block in touch'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_adapters/abstract/database_statements.rb:314:in `transaction'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/transactions.rb:306:in `touch'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/touch_later.rb:40:in `touch'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/no_touching.rb:62:in `touch'
/Users/byroot/src/github.com/Shopify/multi_database_system_test/app/controllers/home_page_controller.rb:8:in `block in touch'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_adapters/abstract/transaction.rb:319:in `block in within_new_transaction'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:27:in `handle_interrupt'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:27:in `block in synchronize'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/connection_adapters/abstract/database_statements.rb:316:in `transaction'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/transactions.rb:209:in `transaction'
/Users/byroot/src/github.com/Shopify/multi_database_system_test/app/controllers/home_page_controller.rb:6:in `touch'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/abstract_controller/base.rb:215:in `process_action'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_controller/metal/rendering.rb:53:in `process_action'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/abstract_controller/callbacks.rb:234:in `block in process_action'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/Users/byroot/.gem/ruby/2.7.5/gems/actiontext-7.0.3.1/lib/action_text/rendering.rb:20:in `with_renderer'
/Users/byroot/.gem/ruby/2.7.5/gems/actiontext-7.0.3.1/lib/action_text/engine.rb:69:in `block (4 levels) in <class:Engine>'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:127:in `instance_exec'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:127:in `block in run_callbacks'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:138:in `run_callbacks'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/abstract_controller/callbacks.rb:233:in `process_action'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_controller/metal/instrumentation.rb:67:in `block in process_action'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/notifications.rb:206:in `block in instrument'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/notifications.rb:206:in `instrument'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_controller/metal/instrumentation.rb:66:in `process_action'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_controller/metal/params_wrapper.rb:259:in `process_action'
/Users/byroot/.gem/ruby/2.7.5/gems/activerecord-7.0.3.1/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/abstract_controller/base.rb:151:in `process'
/Users/byroot/.gem/ruby/2.7.5/gems/actionview-7.0.3.1/lib/action_view/rendering.rb:39:in `process'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_controller/metal.rb:188:in `dispatch'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_controller/metal.rb:251:in `dispatch'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/routing/route_set.rb:32:in `serve'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/journey/router.rb:50:in `block in serve'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/journey/router.rb:32:in `each'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/journey/router.rb:32:in `serve'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/routing/route_set.rb:852:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/tempfile_reaper.rb:15:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/etag.rb:27:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/conditional_get.rb:27:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/head.rb:12:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/http/permissions_policy.rb:38:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/http/content_security_policy.rb:36:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/session/abstract/id.rb:266:in `context'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/session/abstract/id.rb:260:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/middleware/cookies.rb:697:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/callbacks.rb:99:in `run_callbacks'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/middleware/debug_exceptions.rb:28:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/middleware/show_exceptions.rb:26:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/railties-7.0.3.1/lib/rails/rack/logger.rb:40:in `call_app'
/Users/byroot/.gem/ruby/2.7.5/gems/railties-7.0.3.1/lib/rails/rack/logger.rb:25:in `block in call'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/tagged_logging.rb:114:in `block in tagged'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/tagged_logging.rb:38:in `tagged'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/tagged_logging.rb:114:in `tagged'
/Users/byroot/.gem/ruby/2.7.5/gems/railties-7.0.3.1/lib/rails/rack/logger.rb:25:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/middleware/remote_ip.rb:93:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/middleware/request_id.rb:26:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/method_override.rb:24:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/runtime.rb:22:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/activesupport-7.0.3.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/middleware/static.rb:23:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/sendfile.rb:110:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/actionpack-7.0.3.1/lib/action_dispatch/middleware/host_authorization.rb:131:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/railties-7.0.3.1/lib/rails/engine.rb:530:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/urlmap.rb:74:in `block in call'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/urlmap.rb:58:in `each'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/urlmap.rb:58:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/rack-2.2.4/lib/rack/builder.rb:244:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/capybara-3.37.1/lib/capybara/server/middleware.rb:60:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/puma-5.6.5/lib/puma/configuration.rb:252:in `call'
/Users/byroot/.gem/ruby/2.7.5/gems/puma-5.6.5/lib/puma/request.rb:77:in `block in handle_request'
/Users/byroot/.gem/ruby/2.7.5/gems/puma-5.6.5/lib/puma/thread_pool.rb:340:in `with_force_shutdown'
/Users/byroot/.gem/ruby/2.7.5/gems/puma-5.6.5/lib/puma/request.rb:76:in `handle_request'
/Users/byroot/.gem/ruby/2.7.5/gems/puma-5.6.5/lib/puma/server.rb:443:in `process_client'
/Users/byroot/.gem/ruby/2.7.5/gems/puma-5.6.5/lib/puma/thread_pool.rb:147:in `block in spawn_thread'

Both ar eclearly in sleep_forever state, so no way they can wake each others.

[kuahyeow]

Thanks for looking into this !

Essentially what we notice is more or less:

monitor = ActiveSupport::Concurrency::LoadInterlockAwareMonitor.new
monitor.synchronize do
 Thread.new { monitor.synchronize { p 2} }.join(1)
  monitor.synchronize { p 1 }
end

But of course this works as expected. It's very unclear what is special in the reproduction repo so that monitor.synchronize { p 1 } blocks.

The thing here is that we are dealing with two LoadInterlockAwareMonitor objects. You can see this by adding puts to clear_on_handler:

     # lib/active_record/connection_handling.rb
     private                                                                                                                                           
       def clear_on_handler(handler)                                                                                                                   
         handler.all_connection_pools.each do |pool|                                                                                                   
++        puts "#{Thread.current} #{pool.connection.lock}" if pool.active_connection?                                                                 
           pool.connection.clear_query_cache if pool.active_connection?                                                                                
         end                                                                                                                                           
       end 

And then when we run the test we see:

$     bundle exec rails test test/system/home_pages_test.rb
Running 1 tests in a single process (parallelization threshold is 50)
Run options: --seed 59645

# Running:

#<Thread:0x000000015805fb00 run> #<ActiveSupport::Concurrency::LoadInterlockAwareMonitor:0x0000000112b92518>
#<Thread:0x000000015805fb00 run> #<ActiveSupport::Concurrency::LoadInterlockAwareMonitor:0x0000000112cfa6f8>
DEBUGGER: Attaching after process 5798 fork to child process 5819
Capybara starting Puma...
* Version 5.6.5 , codename: Birdie's Version
* Min threads: 0, max threads: 4
* Listening on http://127.0.0.1:63906
#<Thread:0x000000015805fb00 run> #<ActiveSupport::Concurrency::LoadInterlockAwareMonitor:0x0000000112b92518>
#<Thread:0x0000000116074fb0@puma srv tp 003 /Users/tkuah/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/puma-5.6.5/lib/puma/thread_pool.rb:104 run> #<ActiveSupport::Concurrency::LoadInterlockAwareMonitor:0x0000000112b92518>
#<Thread:0x0000000116074fb0@puma srv tp 003 /Users/tkuah/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/puma-5.6.5/lib/puma/thread_pool.rb:104 run> #<ActiveSupport::Concurrency::LoadInterlockAwareMonitor:0x0000000112cfa6f8>

[matthewd]

The thing here is that we are dealing with two LoadInterlockAwareMonitor objects

Ah yep, the two threads are deadlocking because they each hold a (transaction-length) lock of one database, and then try to lock the other.

It's happening because each thread directly modifies one connection, then attempts to clear all connections' query caches.

Ideally we should only be clearing the query cache for the subset of connections that point to the same physical database or its replicants... but we don't really have a good way of distinguishing that subset.

[casperisfine]

Oh wow, I totally missed these were distinct locks 🤦

Ideally we should only be clearing the query cache for the subset of connections that point to the same physical database or its replicants...

Hum, didn't revert a PR that tries to do just that recently?

Either way, this can probably be solved by adding another lock that is to be acquired before trying to clear ALL caches.

[casperisfine]

Either way, this can probably be solved by adding another lock that is to be acquired before trying to clear ALL caches.

Nevermind, that doesn't work because the main thread already locked one connection. 🤔

[matthewd]

This might be an option, though I'm not sure how I feel about it: e5a815d

[casperisfine]

This might be an option, though I'm not sure how I feel about it: e5a815d

Is this a situation that would ever happen in production? I think not, right? This only happens with system tests because we need the puma thread to be able to be inside the same transactional fixtures transaction.

So rather than to impact production, I'd tend to suggest a "test only" workaround. Like maybe skip that log in test, or maybe even disable transactional fixtures for system tests?

[matthewd]

It will only happen in test, but the above change will also only functionally affect test for the same reason: in production, no two threads will believe they co-own a connection, so the thread safety of clearing a given connection's query cache is immaterial.

Like maybe skip that log in test, or maybe even disable transactional fixtures for system tests?

The lock is specifically for test (because multiple threads have to share the connection, in order to both see the uncommitted transaction state). Removing the lock would convert this deadlock into a potential segfault.