ActionDispatch::DebugLocks

[matthewd]

While looking at #25117, I was again struck by how uninformative "hang on all new requests" is as a diagnostic output.

We'd thrown around the idea of checking thread statuses and guessing when things might be stuck, but I'm still nervous that we'd trip on too many legitimately slow operations.

Instead, I propose this middleware.

If your application appears to be experiencing a deadlock, you can insert this, then go to /rails/locks, to see output like:

Thread 0 [0x3fda9bc30cfc sleep]  No interlock (yielded share)
  Waiting in start_exclusive to "load"
  may be pre-empted for: "load"
  blocked by: 1

/Users/matthew/.rbenv/versions/2.3.0/lib/ruby/2.3.0/monitor.rb:111:in `sleep'
/Users/matthew/.rbenv/versions/2.3.0/lib/ruby/2.3.0/monitor.rb:111:in `wait'
/Users/matthew/.rbenv/versions/2.3.0/lib/ruby/2.3.0/monitor.rb:111:in `wait'
/Users/matthew/.rbenv/versions/2.3.0/lib/ruby/2.3.0/monitor.rb:123:in `wait_while'
/Users/matthew/src/rails/activesupport/lib/active_support/concurrency/share_lock.rb:220:in `wait_for'
/Users/matthew/src/rails/activesupport/lib/active_support/concurrency/share_lock.rb:82:in `block (2 levels) in start_exclusive'
/Users/matthew/src/rails/activesupport/lib/active_support/concurrency/share_lock.rb:186:in `yield_shares'
/Users/matthew/src/rails/activesupport/lib/active_support/concurrency/share_lock.rb:81:in `block in start_exclusive'
/Users/matthew/.rbenv/versions/2.3.0/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
/Users/matthew/src/rails/activesupport/lib/active_support/concurrency/share_lock.rb:76:in `start_exclusive'
/Users/matthew/src/rails/activesupport/lib/active_support/concurrency/share_lock.rb:148:in `exclusive'
/Users/matthew/src/rails/activesupport/lib/active_support/dependencies/interlock.rb:11:in `loading'
/Users/matthew/src/rails/activesupport/lib/active_support/dependencies.rb:37:in `load_interlock'
/Users/matthew/src/rails/activesupport/lib/active_support/dependencies.rb:358:in `require_or_load'
/Users/matthew/src/rails/activesupport/lib/active_support/dependencies.rb:511:in `load_missing_constant'
/Users/matthew/src/rails/activesupport/lib/active_support/dependencies.rb:203:in `const_missing'
/Users/matthew/tmp/puma_channel_problem/app/channels/first_channel.rb:3:in `<top (required)>'
/Users/matthew/src/rails/activesupport/lib/active_support/dependencies.rb:293:in `require'
/Users/matthew/src/rails/activesupport/lib/active_support/dependencies.rb:293:in `block in require'
/Users/matthew/src/rails/activesupport/lib/active_support/dependencies.rb:259:in `load_dependency'
/Users/matthew/src/rails/activesupport/lib/active_support/dependencies.rb:293:in `require'
/Users/matthew/src/rails/actioncable/lib/action_cable/server/base.rb:74:in `block (2 levels) in channel_classes'
/Users/matthew/src/rails/actioncable/lib/action_cable/server/base.rb:74:in `each'
/Users/matthew/src/rails/actioncable/lib/action_cable/server/base.rb:74:in `block in channel_classes'
/Users/matthew/.rbenv/versions/2.3.0/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
/Users/matthew/src/rails/actioncable/lib/action_cable/server/base.rb:72:in `channel_classes'
/Users/matthew/src/rails/actioncable/lib/action_cable/connection/subscriptions.rb:29:in `add'
/Users/matthew/src/rails/actioncable/lib/action_cable/connection/subscriptions.rb:15:in `execute_command'
/Users/matthew/src/rails/actioncable/lib/action_cable/connection/base.rb:88:in `dispatch_websocket_message'
/Users/matthew/src/rails/actioncable/lib/action_cable/server/worker.rb:54:in `block in invoke'
/Users/matthew/src/rails/actioncable/lib/action_cable/server/worker.rb:39:in `block in work'
[snip]


---


Thread 1 [0x3fda9a3cf460 sleep]  Sharing
  blocking: 0

/Users/matthew/.rbenv/versions/2.3.0/lib/ruby/2.3.0/monitor.rb:187:in `lock'
/Users/matthew/.rbenv/versions/2.3.0/lib/ruby/2.3.0/monitor.rb:187:in `mon_enter'
/Users/matthew/.rbenv/versions/2.3.0/lib/ruby/2.3.0/monitor.rb:212:in `mon_synchronize'
/Users/matthew/src/rails/actioncable/lib/action_cable/server/base.rb:72:in `channel_classes'
/Users/matthew/src/rails/actioncable/lib/action_cable/connection/subscriptions.rb:29:in `add'
/Users/matthew/src/rails/actioncable/lib/action_cable/connection/subscriptions.rb:15:in `execute_command'
/Users/matthew/src/rails/actioncable/lib/action_cable/connection/base.rb:88:in `dispatch_websocket_message'
/Users/matthew/src/rails/actioncable/lib/action_cable/server/worker.rb:54:in `block in invoke'
/Users/matthew/src/rails/actioncable/lib/action_cable/server/worker.rb:39:in `block in work'
[snip]

Naturally, we're able to provide lots of information about the actual interlock state (some of which is derived from duplicated logic for now, but that could be refactored later), but we can't offer much about whatever "other" lock is involved. However, the above example demonstrates that the backtraces may often be sufficient.

[matthewd]

Targeted for 5.0.1 because although it's a new feature, its whole purpose is to help people diagnose surprising behaviours they may encounter in 5.0: not having it until 5.1 would rather defeat the point.

[thedarkone]

lgtm. Defaulting to auto-use ActionDispatch::DebugLocks in dev mode, right?

[rafaelfranca]

[matthewd]

Backported as ae40629

[grosser]

Good stuff! ... nice to get the backtraces :)

(copy-pasted it into config/application.rb)

[connorshea]

@matthewd why no Changelog entry? This seems super useful!

[sevenseacat]

it is super useful, it confirmed that I do indeed have deadlocks in constant autoloading across my threads :)

[matthewd]

This middleware, along with what you might want to know after it's pointed out problems, is covered in #27494... which I really need to get back to, and get merged. 😔