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

ActionDispatch::DebugLocks #25344

Merged
merged 1 commit into from Jul 1, 2016

Conversation

Projects
None yet
7 participants
@matthewd
Member

matthewd commented Jun 10, 2016

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.

Provide a middleware to debug misbehaving locks
Only intended to be enabled when in use; by necessity, it sits above any
reasonable access control.

@matthewd matthewd added this to the 5.0.1 milestone Jun 10, 2016

@matthewd

This comment has been minimized.

Member

matthewd commented Jun 10, 2016

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

This comment has been minimized.

Contributor

thedarkone commented Jun 13, 2016

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

@rafaelfranca

This comment has been minimized.

Member

rafaelfranca commented Jun 13, 2016

:shipit:

@matthewd matthewd merged commit ad95b6f into rails:master Jul 1, 2016

1 check passed

continuous-integration/travis-ci/pr The Travis CI build passed
Details

matthewd added a commit to matthewd/rails that referenced this pull request Jul 1, 2016

@matthewd

This comment has been minimized.

Member

matthewd commented Jul 1, 2016

Backported as ae40629

@matthewd matthewd removed the needs backport label Jul 1, 2016

matthewd added a commit that referenced this pull request Jul 1, 2016

Merge pull request #25344 from matthewd/debug-locks
ActionDispatch::DebugLocks
@grosser

This comment has been minimized.

Contributor

grosser commented Sep 23, 2016

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

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

@connorshea

This comment has been minimized.

Contributor

connorshea commented Sep 28, 2016

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

@sevenseacat

This comment has been minimized.

Contributor

sevenseacat commented Mar 28, 2017

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

@matthewd

This comment has been minimized.

Member

matthewd commented Mar 28, 2017

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. 😔

@matthewd matthewd deleted the matthewd:debug-locks branch Jun 11, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment