-
Notifications
You must be signed in to change notification settings - Fork 18
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
Join listener thread instead of spinning #52
Conversation
Hmm im hesitant to merge this because all the other ActionCable adapters implement shutdown this way inside rails. Are you able to reliably reproduce puma hanging? Also what version are you using and in what environment is it hanging? |
Yep, could reproduce reliably in development. Rails 8.0.0, solid_cable 3.0.4, using a sqlite db with activerecord-enhancedsqlite3-adapter 0.8.0 and sqlite3 2.4.0. Haven't yet traced down the root cause of the other thread not terminating, but in general |
Do you mind sharing a small rails app with repro steps on how to reproduce? |
And just like that, it seems I can't reproduce it this morning. I'll keep working away and if it reoccurs I'll grab a backtrace of all threads and see if we can track down the root cause that way |
This happened again. First, here's the backtrace of the spinning thread: from vendor/bundle/ruby/3.3.0/gems/puma-6.5.0/lib/puma/thread_pool.rb:166:in `block in spawn_thread' from vendor/bundle/ruby/3.3.0/gems/puma-6.5.0/lib/puma/server.rb:249:in `block in run' from vendor/bundle/ruby/3.3.0/gems/puma-6.5.0/lib/puma/server.rb:468:in `process_client' from vendor/bundle/ruby/3.3.0/gems/puma-6.5.0/lib/puma/request.rb:98:in `handle_request' from vendor/bundle/ruby/3.3.0/gems/puma-6.5.0/lib/puma/thread_pool.rb:389:in `with_force_shutdown' from vendor/bundle/ruby/3.3.0/gems/puma-6.5.0/lib/puma/request.rb:99:in `block in handle_request' from vendor/bundle/ruby/3.3.0/gems/puma-6.5.0/lib/puma/configuration.rb:279:in `call' from vendor/bundle/ruby/3.3.0/gems/railties-8.0.0/lib/rails/engine.rb:535:in `call' from vendor/bundle/ruby/3.3.0/gems/actionpack-8.0.0/lib/action_dispatch/middleware/host_authorization.rb:143:in `call' from vendor/bundle/ruby/3.3.0/gems/rack-3.1.8/lib/rack/sendfile.rb:114:in `call' from vendor/bundle/ruby/3.3.0/gems/actionpack-8.0.0/lib/action_dispatch/middleware/static.rb:27:in `call' from vendor/bundle/ruby/3.3.0/gems/actionpack-8.0.0/lib/action_dispatch/middleware/executor.rb:16:in `call' from vendor/bundle/ruby/3.3.0/gems/actionpack-8.0.0/lib/action_dispatch/middleware/server_timing.rb:60:in `call' from vendor/bundle/ruby/3.3.0/gems/actionpack-8.0.0/lib/action_dispatch/middleware/server_timing.rb:26:in `collect_events' from vendor/bundle/ruby/3.3.0/gems/actionpack-8.0.0/lib/action_dispatch/middleware/server_timing.rb:61:in `block in call' from vendor/bundle/ruby/3.3.0/gems/rack-3.1.8/lib/rack/runtime.rb:24:in `call' from vendor/bundle/ruby/3.3.0/gems/rack-3.1.8/lib/rack/method_override.rb:28:in `call' from vendor/bundle/ruby/3.3.0/gems/actionpack-8.0.0/lib/action_dispatch/middleware/request_id.rb:34:in `call' from vendor/bundle/ruby/3.3.0/gems/actionpack-8.0.0/lib/action_dispatch/middleware/remote_ip.rb:96:in `call' from vendor/bundle/ruby/3.3.0/gems/railties-8.0.0/lib/rails/rack/logger.rb:29:in `call' from vendor/bundle/ruby/3.3.0/gems/railties-8.0.0/lib/rails/rack/logger.rb:41:in `call_app' from vendor/bundle/ruby/3.3.0/gems/actionpack-8.0.0/lib/action_dispatch/middleware/show_exceptions.rb:32:in `call' from vendor/bundle/ruby/3.3.0/gems/web-console-4.2.1/lib/web_console/middleware.rb:17:in `call' from vendor/bundle/ruby/3.3.0/gems/web-console-4.2.1/lib/web_console/middleware.rb:17:in `catch' from vendor/bundle/ruby/3.3.0/gems/web-console-4.2.1/lib/web_console/middleware.rb:28:in `block in call' from vendor/bundle/ruby/3.3.0/gems/web-console-4.2.1/lib/web_console/middleware.rb:132:in `call_app' from vendor/bundle/ruby/3.3.0/gems/actionpack-8.0.0/lib/action_dispatch/middleware/debug_exceptions.rb:31:in `call' from vendor/bundle/ruby/3.3.0/gems/actionpack-8.0.0/lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call' from vendor/bundle/ruby/3.3.0/gems/actionpack-8.0.0/lib/action_dispatch/middleware/executor.rb:14:in `call' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/reloader.rb:64:in `run!' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/execution_wrapper.rb:74:in `run!' from :90:in `tap' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/execution_wrapper.rb:77:in `block in run!' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/reloader.rb:122:in `run!' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/execution_wrapper.rb:124:in `run!' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/execution_wrapper.rb:128:in `run' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:108:in `run_callbacks' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:558:in `invoke_before' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:558:in `each' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:558:in `block in invoke_before' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:179:in `call' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:666:in `block in default_terminator' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:666:in `catch' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:667:in `block (2 levels) in default_terminator' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:178:in `block in call' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:406:in `block in make_lambda' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:406:in `instance_exec' from vendor/bundle/ruby/3.3.0/gems/railties-8.0.0/lib/rails/application/finisher.rb:216:in `block (2 levels) in ' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/reloader.rb:128:in `class_unload!' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:108:in `run_callbacks' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:558:in `invoke_before' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:558:in `each' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:558:in `block in invoke_before' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:179:in `call' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:666:in `block in default_terminator' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:666:in `catch' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:667:in `block (2 levels) in default_terminator' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:178:in `block in call' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:406:in `block in make_lambda' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:406:in `instance_exec' from vendor/bundle/ruby/3.3.0/gems/actioncable-8.0.0/lib/action_cable/engine.rb:93:in `block (3 levels) in ' from vendor/bundle/ruby/3.3.0/gems/actioncable-8.0.0/lib/action_cable/server/base.rb:55:in `restart' from vendor/bundle/ruby/3.3.0/gems/actioncable-8.0.0/lib/action_cable/server/base.rb:55:in `synchronize' from vendor/bundle/ruby/3.3.0/gems/actioncable-8.0.0/lib/action_cable/server/base.rb:61:in `block in restart' from vendor/bundle/ruby/3.3.0/gems/solid_cable-3.0.4/lib/action_cable/subscription_adapter/solid_cable.rb:31:in `shutdown' from vendor/bundle/ruby/3.3.0/gems/solid_cable-3.0.4/lib/action_cable/subscription_adapter/solid_cable.rb:62:in `shutdown' from vendor/bundle/ruby/3.3.0/gems/solid_cable-3.0.4/lib/action_cable/subscription_adapter/solid_cable.rb:62:in `alive?' Looks like this is related to reloading in development. I attached gdb and set a breakpoint on
1022304 is the TID of the thread we're spinwaiting to exit. Using from vendor/bundle/ruby/3.3.0/gems/solid_cable-3.0.4/lib/action_cable/subscription_adapter/solid_cable.rb:48:in `block in initialize' from vendor/bundle/ruby/3.3.0/gems/solid_cable-3.0.4/lib/action_cable/subscription_adapter/solid_cable.rb:54:in `listen' from vendor/bundle/ruby/3.3.0/gems/solid_cable-3.0.4/lib/action_cable/subscription_adapter/solid_cable.rb:110:in `with_polling_volume' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/logger_silence.rb:18:in `silence' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/logger_thread_safe_level.rb:37:in `log_at' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/logger_silence.rb:18:in `block in silence' from vendor/bundle/ruby/3.3.0/gems/solid_cable-3.0.4/lib/action_cable/subscription_adapter/solid_cable.rb:110:in `block in with_polling_volume' from vendor/bundle/ruby/3.3.0/gems/solid_cable-3.0.4/lib/action_cable/subscription_adapter/solid_cable.rb:54:in `block in listen' from vendor/bundle/ruby/3.3.0/gems/solid_cable-3.0.4/lib/action_cable/subscription_adapter/solid_cable.rb:99:in `broadcast_messages' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/execution_wrapper.rb:89:in `wrap' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/execution_wrapper.rb:74:in `run!' from :90:in `tap' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/execution_wrapper.rb:77:in `block in run!' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/execution_wrapper.rb:124:in `run!' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/execution_wrapper.rb:128:in `run' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:108:in `run_callbacks' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:558:in `invoke_before' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:558:in `each' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:558:in `block in invoke_before' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:179:in `call' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:666:in `block in default_terminator' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:666:in `catch' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:667:in `block (2 levels) in default_terminator' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:178:in `block in call' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/callbacks.rb:384:in `block in make_lambda' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/execution_wrapper.rb:28:in `before' from vendor/bundle/ruby/3.3.0/gems/railties-8.0.0/lib/rails/application/finisher.rb:112:in `run' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/dependencies/interlock.rb:29:in `start_running' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/concurrency/share_lock.rb:114:in `start_sharing' from /usr/lib/ruby/3.3.0/monitor.rb:201:in `mon_synchronize' from /usr/lib/ruby/3.3.0/monitor.rb:201:in `synchronize' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/concurrency/share_lock.rb:124:in `block in start_sharing' from vendor/bundle/ruby/3.3.0/gems/activesupport-8.0.0/lib/active_support/concurrency/share_lock.rb:219:in `wait_for' from /usr/lib/ruby/3.3.0/monitor.rb:115:in `wait_while' from /usr/lib/ruby/3.3.0/monitor.rb:107:in `wait' from /usr/lib/ruby/3.3.0/monitor.rb:107:in `wait_for_cond' from /usr/lib/ruby/3.3.0/monitor.rb:107:in `wait' from /usr/lib/ruby/3.3.0/monitor.rb:107:in `sleep' We can see here that the listener thread is stuck waiting to take the ActiveSupport::Dependencies interlock in shared mode while the spinwaiting thread has already acquired it in exclusive mode in So, deadlock. The spinwaiting thread is already holding the interlock exclusively as it prepared to unload code, but the teardown involves waiting on the listener thread to terminate, and it is stuck trying to take a shared lock on the very same interlock as part of the usual ceremony to call across the Rails/application boundary. I'm not familiar at all with Rails autoloading these days I'm afraid - the last time I was knee deep in this part of Rails was back in the 3.x era before multithreading was much of a thing :) So while I would struggle to suggest a concrete fix, I hope I've illustrated the problem here clearly enough for someone who is more familiar. |
Have cooked up a small reproducer here: https://github.com/haileys/solidcable-52-repro |
@jorgemanrubia its back :( haha. Ill take a look but in case you happen to have any ideas |
Still, not sure what's going on, but I've seen that wrapping with the executor just the individual |
Nope, this won't fly, as there would still be a reference to I gotta go now but I'll try more things when I'm back. |
@haileys @jorgemanrubia Do you mind giving #53 a spin and see if the hanging still happens? |
Awesome @jorgemanrubia. Ill let @haileys take it for a spin to double check and then ill merge |
I'll try this and report back! There's another potential solution I experimented with using This is the patch. Haven't seriously tested it out yet, but comments welcome: diff --git a/lib/action_cable/subscription_adapter/solid_cable.rb b/lib/action_cable/subscription_adapter/solid_cable.rb
index 65944aa..c197fb6 100644
--- a/lib/action_cable/subscription_adapter/solid_cable.rb
+++ b/lib/action_cable/subscription_adapter/solid_cable.rb
@@ -3,6 +3,7 @@
require "action_cable/subscription_adapter/base"
require "action_cable/subscription_adapter/channel_prefix"
require "action_cable/subscription_adapter/subscriber_map"
+require "concurrent/atomic/semaphore"
module ActionCable
module SubscriptionAdapter
@@ -38,28 +39,54 @@ module ActionCable
end
class Listener < ::ActionCable::SubscriptionAdapter::SubscriberMap
+ Stop = Class.new(Exception)
+
def initialize(event_loop)
super()
@event_loop = event_loop
+ # critical section begins with 0 permits - it can be understood as
+ # being "normally held" by the listener thread - it is released
+ # for specific sections of code, rather than acquired.
+ @critical = Concurrent::Semaphore.new(0)
+
@thread = Thread.new do
- Thread.current.abort_on_exception = true
listen
end
end
def listen
- while running?
+ loop do
+ begin
+ instance = interruptible { Rails.application.executor.run! }
+
with_polling_volume { broadcast_messages }
+ ensure
+ instance.complete! if instance
+ end
- sleep ::SolidCable.polling_interval
+ interruptible { sleep ::SolidCable.polling_interval }
+ end
+ rescue Stop
+ ensure
+ @critical.release
end
+
+ def interruptible
+ @critical.release
+ yield
+ ensure
+ @critical.acquire
end
def shutdown
- self.running = false
- Thread.pass while thread.alive?
+ @critical.acquire
+ # we have the critical permit, and so the listen thread must be
+ # safe to interrupt:
+ thread.raise(Stop)
+ @critical.release
+ thread.join
end
def add_channel(channel, on_success)
@@ -77,15 +104,7 @@ module ActionCable
private
attr_reader :event_loop, :thread
- attr_writer :running, :last_id
-
- def running?
- if defined?(@running)
- @running
- else
- self.running = true
- end
- end
+ attr_writer :last_id
def last_id
@last_id ||= ::SolidCable::Message.maximum(:id) || 0
@@ -96,14 +115,12 @@ module ActionCable
end
def broadcast_messages
- Rails.application.executor.wrap do
::SolidCable::Message.broadcastable(channels, last_id).
each do |message|
broadcast(message.channel, message.payload)
self.last_id = message.id
end
end
- end
def with_polling_volume
if ::SolidCable.silence_polling? && ActiveRecord::Base.logger |
Fixed via: #53 |
Hey @npezza93, We were still getting very sporadic hangs when using action cable with hotwire spark, even with the last version 3.0.5. Hotwire spark exacerbates the scenario where you combine classes reloading with new requests in a short period of time, but I was able to simulate these hangs even without Hotwire Spark installed by simulating many requests (by opening tons of tabs) and file modifications with a script at the same time. The good news is that the patch by @haileys fixes this for good. I can't reproduce with it in place anymore. @haileys would you be up to creating a PR here with the patch? I can do it and put you as co-author, but it's certainly your work, and you are the only author here. Thank you so much for the amazing work. |
ok glad to hear @haileys fix works! Happy to merge |
Oh great, I'm glad to hear this patch has been helpful. I'll put together a PR tomorrow. It adds an extra dep, concurrent-ruby, that isn't currently a direct dependency of solid_cable, but is already a dependency of Rails, so there will be a little bit of gemspec and perhaps test shuffling too. |
This patch was created by Hailey Somerville in rails#52 (comment). All the credit to her. Co-authored-by: Hailey Somerville <hailey@hails.org>
This patch was created by Hailey Somerville in rails#52 (comment). All the credit to her. Co-authored-by: Hailey Somerville <hailey@hails.org>
Tracked down a puma process spinning at 100% CPU to this line here.
Any reason why this can't be a
thread.join
rather than spinning?