search

pat / thinking-sphinx

Sphinx/Manticore plugin for ActiveRecord/Rails
http://freelancing-gods.com/thinking-sphinx
MIT License
1.63k stars 470 forks source link

Deadlock in preload_indices #1132

Closed jdelStrother closed 5 years ago

jdelStrother commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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