Skip to content
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

Deadlock in preload_indices #1132

Closed
jdelStrother opened this issue Apr 29, 2019 · 5 comments
Closed

Deadlock in preload_indices #1132

jdelStrother opened this issue Apr 29, 2019 · 5 comments

Comments

@jdelStrother
Copy link
Contributor

I run multithreaded puma in development, and get fairly frequent deadlocks if two concurrent requests try to create a record.

The problem appears to be due to the mutex handling in Configuration#preload_indices:

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

<RUBY_HOME>/lib/ruby/2.3.0/monitor.rb:111:in `sleep'
<RUBY_HOME>/lib/ruby/2.3.0/monitor.rb:111:in `wait'
<RUBY_HOME>/lib/ruby/2.3.0/monitor.rb:111:in `wait'
<RUBY_HOME>/lib/ruby/2.3.0/monitor.rb:123:in `wait_while'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/concurrency/share_lock.rb:221:in `wait_for'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/concurrency/share_lock.rb:83:in `block (2 levels) in start_exclusive'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/concurrency/share_lock.rb:82:in `block in start_exclusive'
<RUBY_HOME>/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/concurrency/share_lock.rb:77:in `start_exclusive'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/concurrency/share_lock.rb:149:in `exclusive'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/dependencies/interlock.rb:13:in `loading'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/dependencies.rb:37:in `load_interlock'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/dependencies.rb:356:in `require_or_load'
<GEM_HOME>/gems/bootsnap-1.3.2/lib/bootsnap/load_path_cache/core_ext/active_support.rb:46:in `block in require_or_load'
<GEM_HOME>/gems/bootsnap-1.3.2/lib/bootsnap/load_path_cache/core_ext/active_support.rb:16:in `allow_bootsnap_retry'
<GEM_HOME>/gems/bootsnap-1.3.2/lib/bootsnap/load_path_cache/core_ext/active_support.rb:45:in `require_or_load'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/configuration.rb:90:in `block (3 levels) in preload_indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/configuration.rb:89:in `each'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/configuration.rb:89:in `block (2 levels) in preload_indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/configuration.rb:88:in `each'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/configuration.rb:88:in `block in preload_indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/configuration.rb:85:in `synchronize'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/configuration.rb:85:in `preload_indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/index_set.rb:32:in `all_indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/index_set.rb:68:in `indices_for_references'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/index_set.rb:63:in `indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/index_set.rb:11:in `each'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:47:in `select'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:47:in `indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:38:in `delta_indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:42:in `delta_indices?'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:21:in `before_save'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/callbacks.rb:9:in `block (2 levels) in callbacks'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:426:in `block in make_lambda'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:198:in `block (2 levels) in halting'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:606:in `block (2 levels) in default_terminator'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:605:in `catch'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:605:in `block in default_terminator'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:199:in `block in halting'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:513:in `block in invoke_before'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:513:in `each'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:513:in `invoke_before'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:131:in `run_callbacks'
<GEM_HOME>/gems/airbrake-9.0.0/lib/airbrake/rails/active_record.rb:20:in `run_callbacks'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/callbacks.rb:342:in `create_or_update'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/persistence.rb:306:in `save!'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/validations.rb:52:in `save!'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:315:in `block in save!'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:259:in `block in transaction'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
<RUBY_HOME>/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:259:in `transaction'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:212:in `transaction'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:315:in `save!'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/suppressor.rb:48:in `save!'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/persistence.rb:53:in `create!'
<RAILS_ROOT>/app/controllers/base_controller.rb:18:in `record_audit'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:426:in `block in make_lambda'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:198:in `block (2 levels) in halting'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:199:in `block in halting'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:513:in `block in invoke_before'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:513:in `each'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:513:in `invoke_before'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:107:in `block in run_callbacks'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/notifications.rb:168:in `block in instrument'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/notifications.rb:168:in `instrument'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/abstract_controller/base.rb:134:in `process'
<GEM_HOME>/gems/actionview-5.2.2.1/lib/action_view/rendering.rb:32:in `process'
<GEM_HOME>/gems/rack-mini-profiler-1.0.2/lib/mini_profiler/profiling_methods.rb:78:in `block in profile_method'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_controller/metal.rb:191:in `dispatch'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_controller/metal.rb:252:in `dispatch'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/routing/route_set.rb:34:in `serve'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/journey/router.rb:52:in `block in serve'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/journey/router.rb:35:in `each'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/journey/router.rb:35:in `serve'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/routing/route_set.rb:840:in `call'
<GEM_HOME>/gems/rack-attack-5.4.2/lib/rack/attack.rb:175:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/tempfile_reaper.rb:15:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/etag.rb:25:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/conditional_get.rb:25:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/head.rb:12:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:232:in `context'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:226:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/cookies.rb:670:in `call'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/migration.rb:559:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
<GEM_HOME>/gems/airbrake-9.0.0/lib/airbrake/rack/middleware.rb:33:in `call!'
<GEM_HOME>/gems/airbrake-9.0.0/lib/airbrake/rack/middleware.rb:21:in `call'
<GEM_HOME>/gems/better_errors-2.5.0/lib/better_errors/middleware.rb:84:in `protected_app_call'
<GEM_HOME>/gems/better_errors-2.5.0/lib/better_errors/middleware.rb:79:in `better_errors_call'
<GEM_HOME>/gems/better_errors-2.5.0/lib/better_errors/middleware.rb:57:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
<GEM_HOME>/gems/railties-5.2.2.1/lib/rails/rack/logger.rb:38:in `call_app'
<GEM_HOME>/gems/railties-5.2.2.1/lib/rails/rack/logger.rb:26:in `block in call'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/tagged_logging.rb:71:in `block in tagged'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/tagged_logging.rb:28:in `tagged'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/tagged_logging.rb:71:in `tagged'
<GEM_HOME>/gems/railties-5.2.2.1/lib/rails/rack/logger.rb:26:in `call'
<GEM_HOME>/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
<GEM_HOME>/gems/request_store-1.4.1/lib/request_store/middleware.rb:19:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/method_override.rb:22:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/runtime.rb:22:in `call'
<GEM_HOME>/gems/rack-timeout-0.5.1/lib/rack/timeout/core.rb:123:in `block in call'
<GEM_HOME>/gems/rack-timeout-0.5.1/lib/rack/timeout/support/timeout.rb:19:in `timeout'
<GEM_HOME>/gems/rack-timeout-0.5.1/lib/rack/timeout/core.rb:122:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/sendfile.rb:111:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/debug_locks.rb:41:in `call'
<GEM_HOME>/gems/rack-cors-1.0.2/lib/rack/cors.rb:97:in `call'
<GEM_HOME>/gems/rack-mini-profiler-1.0.2/lib/mini_profiler/profiler.rb:189:in `call'
<GEM_HOME>/gems/railties-5.2.2.1/lib/rails/engine.rb:524:in `call'
<GEM_HOME>/gems/puma-3.12.0/lib/puma/configuration.rb:225:in `call'
<GEM_HOME>/gems/puma-3.12.0/lib/puma/server.rb:658:in `handle_request'
<GEM_HOME>/gems/puma-3.12.0/lib/puma/server.rb:472:in `process_client'
<GEM_HOME>/gems/puma-3.12.0/lib/puma/server.rb:332:in `block in run'
<GEM_HOME>/gems/puma-3.12.0/lib/puma/thread_pool.rb:133:in `block in spawn_thread'


---


Thread 1 [0x3fc4947a748c sleep]  Sharing
  blocking: 0

<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/configuration.rb:85:in `synchronize'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/configuration.rb:85:in `preload_indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/index_set.rb:32:in `all_indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/index_set.rb:68:in `indices_for_references'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/index_set.rb:63:in `indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/index_set.rb:11:in `each'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:47:in `select'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:47:in `indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:38:in `delta_indices'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:42:in `delta_indices?'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/active_record/callbacks/delta_callbacks.rb:21:in `before_save'
<GEM_HOME>/bundler/gems/thinking-sphinx-f252bf4efb2e/lib/thinking_sphinx/callbacks.rb:9:in `block (2 levels) in callbacks'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:426:in `block in make_lambda'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:198:in `block (2 levels) in halting'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:606:in `block (2 levels) in default_terminator'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:605:in `catch'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:605:in `block in default_terminator'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:199:in `block in halting'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:513:in `block in invoke_before'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:513:in `each'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:513:in `invoke_before'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:131:in `run_callbacks'
<GEM_HOME>/gems/airbrake-9.0.0/lib/airbrake/rails/active_record.rb:20:in `run_callbacks'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/callbacks.rb:342:in `create_or_update'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/persistence.rb:306:in `save!'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/validations.rb:52:in `save!'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:315:in `block in save!'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:259:in `block in transaction'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
<RUBY_HOME>/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:259:in `transaction'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:212:in `transaction'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:315:in `save!'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/suppressor.rb:48:in `save!'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/persistence.rb:53:in `create!'
<RAILS_ROOT>/app/controllers/base_controller.rb:18:in `record_audit'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:426:in `block in make_lambda'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:198:in `block (2 levels) in halting'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:199:in `block in halting'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:513:in `block in invoke_before'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:513:in `each'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:513:in `invoke_before'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:107:in `block in run_callbacks'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/notifications.rb:168:in `block in instrument'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/notifications.rb:168:in `instrument'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/abstract_controller/base.rb:134:in `process'
<GEM_HOME>/gems/actionview-5.2.2.1/lib/action_view/rendering.rb:32:in `process'
<GEM_HOME>/gems/rack-mini-profiler-1.0.2/lib/mini_profiler/profiling_methods.rb:78:in `block in profile_method'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_controller/metal.rb:191:in `dispatch'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_controller/metal.rb:252:in `dispatch'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/routing/route_set.rb:34:in `serve'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/journey/router.rb:52:in `block in serve'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/journey/router.rb:35:in `each'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/journey/router.rb:35:in `serve'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/routing/route_set.rb:840:in `call'
<GEM_HOME>/gems/rack-attack-5.4.2/lib/rack/attack.rb:175:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/tempfile_reaper.rb:15:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/etag.rb:25:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/conditional_get.rb:25:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/head.rb:12:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:232:in `context'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:226:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/cookies.rb:670:in `call'
<GEM_HOME>/gems/activerecord-5.2.2.1/lib/active_record/migration.rb:559:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
<GEM_HOME>/gems/airbrake-9.0.0/lib/airbrake/rack/middleware.rb:33:in `call!'
<GEM_HOME>/gems/airbrake-9.0.0/lib/airbrake/rack/middleware.rb:21:in `call'
<GEM_HOME>/gems/better_errors-2.5.0/lib/better_errors/middleware.rb:84:in `protected_app_call'
<GEM_HOME>/gems/better_errors-2.5.0/lib/better_errors/middleware.rb:79:in `better_errors_call'
<GEM_HOME>/gems/better_errors-2.5.0/lib/better_errors/middleware.rb:57:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
<GEM_HOME>/gems/railties-5.2.2.1/lib/rails/rack/logger.rb:38:in `call_app'
<GEM_HOME>/gems/railties-5.2.2.1/lib/rails/rack/logger.rb:26:in `block in call'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/tagged_logging.rb:71:in `block in tagged'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/tagged_logging.rb:28:in `tagged'
<GEM_HOME>/gems/activesupport-5.2.2.1/lib/active_support/tagged_logging.rb:71:in `tagged'
<GEM_HOME>/gems/railties-5.2.2.1/lib/rails/rack/logger.rb:26:in `call'
<GEM_HOME>/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
<GEM_HOME>/gems/request_store-1.4.1/lib/request_store/middleware.rb:19:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/method_override.rb:22:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/runtime.rb:22:in `call'
<GEM_HOME>/gems/rack-timeout-0.5.1/lib/rack/timeout/core.rb:123:in `block in call'
<GEM_HOME>/gems/rack-timeout-0.5.1/lib/rack/timeout/support/timeout.rb:19:in `timeout'
<GEM_HOME>/gems/rack-timeout-0.5.1/lib/rack/timeout/core.rb:122:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
<GEM_HOME>/gems/rack-2.0.6/lib/rack/sendfile.rb:111:in `call'
<GEM_HOME>/gems/actionpack-5.2.2.1/lib/action_dispatch/middleware/debug_locks.rb:41:in `call'
<GEM_HOME>/gems/rack-cors-1.0.2/lib/rack/cors.rb:97:in `call'
<GEM_HOME>/gems/rack-mini-profiler-1.0.2/lib/mini_profiler/profiler.rb:189:in `call'
<GEM_HOME>/gems/railties-5.2.2.1/lib/rails/engine.rb:524:in `call'
<GEM_HOME>/gems/puma-3.12.0/lib/puma/configuration.rb:225:in `call'
<GEM_HOME>/gems/puma-3.12.0/lib/puma/server.rb:658:in `handle_request'
<GEM_HOME>/gems/puma-3.12.0/lib/puma/server.rb:472:in `process_client'
<GEM_HOME>/gems/puma-3.12.0/lib/puma/server.rb:332:in `block in run'
<GEM_HOME>/gems/puma-3.12.0/lib/puma/thread_pool.rb:133:in `block in spawn_thread'

I hoped I could fix this by wrapping the mutex in permit_concurrent_loads, but that doesn't appear to help. Any other suggestions I might try?

@jdelStrother
Copy link
Contributor Author

I'd like to hesitantly propose this as a fix...

diff --git a/lib/thinking_sphinx/configuration.rb b/lib/thinking_sphinx/configuration.rb
index 7ce15dd7..e983e8a5 100644
--- a/lib/thinking_sphinx/configuration.rb
+++ b/lib/thinking_sphinx/configuration.rb
@@ -10,7 +10,7 @@ class ThinkingSphinx::Configuration < Riddle::Configuration
 
   delegate :environment, :to => :framework
 
-  @@mutex = Mutex.new
+  @@mutex = ActiveSupport::Concurrency::LoadInterlockAwareMonitor.new
 
   def initialize
     super

Which appears to fix my deadlocks. I don't understand enough of AS::Dependencies' locking insanity to say for sure it's the correct fix, though.

@pat
Copy link
Owner

pat commented May 2, 2019

I'm glad to know you've found a fix! And I'm a little surprised the issue you've hit hasn't been noted by anyone else… I've used Thinking Sphinx and Puma together in my apps, and I'm sure others have too. 🤔

I'll have a look into the ActiveSupport monitor class soon to confirm it's a good fit - but the fact it's working for you is a great sign.

@jdelStrother
Copy link
Contributor Author

I think the reason I'm consistently running into it is that we have a before_filter that creates an AuditLog activerecord object on every single request, and pages that fire multiple simultaneous ajax calls, so I'm probably doing more concurrent inserts than most people.

I've created a demo repository here - https://github.com/jdelStrother/thinkingsphinx-deadlock. The readme has instructions on reproducing the problem, but the money shot is here: https://github.com/jdelStrother/thinkingsphinx-deadlock/blob/master/app/controllers/application_controller.rb#L32. Let me know if I can do anything to help.

pat added a commit that referenced this issue May 14, 2019
This seems to be related to some changes with Rails' database locking behaviour, which was added in Rails 5.1. This monitor class was added in response to similar issues - and is only present since 5.1.5. The underlying issue noted in #1132 may possibly crop up in earlier Rails 5.1.x releases, but this should resolve things for anything newer. Thanks to @jdelStrother for doing all the hard work on this!
@pat
Copy link
Owner

pat commented May 14, 2019

Just pushed a commit that should resolve this - essentially, your solution, but only when that ActiveSupport class is available (which seems to be from 5.1.5 onwards, for an issue that was introduced at some point in the 5.1.x releases). Thanks so much for the test app too, that was a great way to review the problem! 👏

@pat
Copy link
Owner

pat commented May 18, 2019

This fix is available in the newly-released v4.3.0, with credit to you in the release notes/changelog 😄

@pat pat closed this as completed May 18, 2019
guicassolato added a commit to 3scale/porta that referenced this issue Jul 2, 2020
Otherwise concurrent threads (e.g. sidekiq, puma) can deadlock while
racing to obtain access to the mutex block at
https://github.com/pat/thinking-sphinx/blob/v3.4.2/lib/thinking_sphinx/configuration.rb#L78.

This bug was fixed in ThinkingSphinx v4.3.0+.

See
- pat/thinking-sphinx#1051
- pat/thinking-sphinx#1132
@pat pat mentioned this issue Jun 9, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants