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
Rails5, concurrency in action method, deadlock, docs needed including for executor/reloader #26847
Comments
Briefly for now, because I'm about to get on a plane: 1 No it's not a bug, but it is indeed unfortunate. The good news is that doesn't need to make you sad: you can wrap your The one-line description for when to use 2 The short answer is no. There's some relevant discussion in #24028. The problem is that we don't know the other thread is blocked (and not just legitimately doing some work). 5.0.1 will have #25344, which helps explain what/where/why you're getting stuck... but you still need to recognise that's what's happening, and seek it out. 😕 3 Yes, we need docs 😀 |
Thanks @matthewd, I'll spend some time with your links. But yes, docs, docs, please please please.
I'm confused. As far as I can tell, I only have the deadlock (?) issue with user-defined constants -- I thought the problem was triggering an autoload of an autoloadable constant. (By "user-defined", you mean "autoloadable", right?) If you give me a solution, but it only works if the wrapped code doesn't reference any autoloadable constants... that seems to be a solution to a problem I'm not having? Or are you saying even without referencing autoloadable constants I'd have problems I just haven't noticed yet? Alas, in my case, I'm not sure it's possible to guarantee avoiding autoloadable constants. it's very hard to keep track for sure of whether you are accessing autoloadable constants or not, of course -- normally, whether a particular constant is autoloadable is pretty much an invisible abstraction, you don't need to care about it at all. Having to care about and make sure a certain block of code (and all code it calls directly or indirectly) does not reference any autoloadable constants... I'm not sure how feasible it is really. Although if the danger of messing up is just a rails4-style exception... that seems potentially tolerable, at least no worse than rails4! I'll play around with it. But yeah, I never would have found Docs are really needed, maybe even a "concurrency guide" or something. Unfortunately, I think there are probably currently very few people who understand what's up enough to write such a guide -- you may even be the only one? Which is both why good docs are neccesary (so other people can develop the needed understanding)... and why it seems to be not happening. |
Oops, I missed the rather critical words "on that thread". The value/wait call you're doing can't itself trigger an autoload, and is thus perfectly safe. I will be writing docs.. just have to get the much-overdue 5.0.1 out first. |
Aha, So... how do I get the appropriate instance of an Also, is it also still wise to wrap my Future(/Thread) body in a Also, regarding the annoying failure mode of hanging forever -- what if there was an optional configurable 'max wait' value, for waiting on the autoload lock? And it was by default in development (which is the only place this ordinarily matters, right?) set to 4 or 5 seconds or something. And if maxwait was reached, it would raise an exception "Couldn't get autoload lock, for more info see (url to hypothetically future existing docs on this)"? A developer could always raise the maxwait or disable it completely when running into this, but it would be a hint for the newcomer that at least it's got something to do with autoload and concurrency and locks, instead of just a mysterious deadlock. |
Okay, I think I figured it out by spelunking through Rails source: a) I get the appropriate interlock with b) I do need to put the future body in a But when I do those things, it does seem to work! Sweet! Thanks for designing the internals so well. |
Deleted my last comment about apparent serialization, that wasn't going on, mistake in my own instrumentation. Indeed all seems to be well as above. Sorry for the noise, concurrency is hard! |
But crap! First load works fine even in dev-mode settings with recommended use of But if I change the autoloaded source file on disk, and request again... it seems to still deadlock. Darnit. Okay, enough of this for the night, I'll wait for some feedback. |
Getting this stuff onto the same 'level' of API is tricky. Technically, you could achieve what you want just with the interlock, using (You don't actually want to use Ideally, we might arrange a mechanism to hook c-r's wait, so we can automatically/always do it for you. Ah, you probably want to wrap with the executor, not the reloader. The reloader... reloads, which isn't necessary or desirable here. You want the reload to occur on the next request, not at the start of one of your futures. That's my fault for not noticing which one you were using earlier -- and something that'll be made very clear by the future docs: wanting the reloader is rare, and only applies to things handling "top level" actions -- like Action Controller, and Sidekiq. (The problem you're hitting is that when a reloader decides to reload, it has to wait for all in-flight executor work to complete, and unlike an autoload, it can't take advantage of |
Okay, sweet! So I do want Here's what I have now, which seems to be working! I've left in my basic instrumentation that demonstrates the futures are really executing concurrently, just to copy-and-paste to make sure I don't make any errors in pasting in. Can you kindly confirm that this code looks right? This seems to be exactly what I need, which is awesome. def example
s_time = Time.now
futures = 3.times.collect do |i|
Concurrent::Future.execute do
ActiveSupport::Dependencies.interlock.running do
puts "Thread #{i} starting in #{Time.now - s_time}"
sleep 3
SomeWorker.new.value
end
end
end
ActiveSupport::Dependencies.interlock.permit_concurrent_loads do
@example_values = futures.collect(&:value)
end
@t_time = Time.now - s_time
end |
(I'm not sure what ruby weirdness is going on that |
You're probably better off with Interlock is an ordinary class, so I'd expect it to inspect with its name. The reloader and executor are trickier -- they're anonymous subclasses of the real thing. But we could at least override |
Okay, awesome, so I want
Can you say more about this? I'm used to having to wrap anything that might use AR in a created thread in a And all this stuff (wrapping in |
Yes. That's where the high-level vs low-level API issue comes in. I agree it feels weird to use different things on each 'side'... but the executor doesn't know anything about load locks.
Yes. Active Record registers a 'complete' hook on the executor to return outstanding connections to the pool. (As of 4.2, AR was already able to reclaim connections from threads that had died/completed... but that doesn't apply here, because your futures are running on long-lived c-r pool threads.) This sort of thing is why the executor is intended to be a higher level API: it's not about load locks, or connection pools, or anything else. It's about "I'm going to do stuff now" -- allowing us (and more generally, any other library that wants to register a handler) to abstract away those details, in a similar way to the middleware stack on a web request.
True. At least, it's certainly supposed to be: the executor doesn't even get told about the lock... and while permit_concurrent_loads will still [needlessly] do its thing, that's just a couple of low-contention lock acquisitions. |
Awesome. I really like the design of this, and the tricky implementation seems solid. I agree that an "I'm going to do stuff now, please let me do it concurrency-safely" public API was totally needed, thanks for providing one with the executor, that's totally nice. I do think it would be better if you figured out a way to structure the API so you didn't need to access two different objects to get the I think perhaps you initially thought So, just to make sure I have it right before I put it in my code, blog about it, and tell everyone about it, can you sign off on this implementation as a correct, as-intended, use of the new executor stuff? I really appreciate the hints @matthewd . def example
futures = 3.times.collect do |i|
Concurrent::Future.execute do
Rails.application.executor.wrap do
SomeWorker.new.value
end
end
end
ActiveSupport::Dependencies.interlock.permit_concurrent_loads do
@example_values = futures.collect(&:value)
end
end |
(And I do still suggest, if there was some easy way to make the wait-for-autoload-lock have a configurable max-wait timeout value that resulted in an exception saying "it's got to do with the autoload lock, friend!", it would be a really good solution to the problem of impenetrability of deadlock-as-failure-mode. I'm less enthused by the rack middleware attempt, by the time you realize you need it, I'm not sure how much additional value it will give you, the hardest part is knowing you need it in the first place, although there perhaps could be some situations where you still need the middleware's help in figuring out exactly what's up). |
👌🏻
Yeah, that does sound feasible -- especially if it just produced a warning. I'll add it to the list.
It helps a lot when you know the autoload lock is involved (e.g., you recognise the symptoms, or have received the above warning), but didn't just add a
Thanks! 😊 And thank you for exploring it, and asking lots of questions along the way; the above discussion will help a lot while I'm framing these things from the API consumer's perspective. |
Thanks! So one more question, or really two parts:
|
See rails/rails#26847 thanks @matthewd. Prob needs a controller test to test that we're doing Rails5 concurrency okay.
And, if I call |
Yes.
Right. But you needn't go out of your way to avoid it, because:
Yes...ish. As currently written, when the wrapped block completes, if there is a thread currently holding the exclusive load lock (i.e., doing an autoload right now), permit_concurrent_loads will wait for it to finish, without realising that [because it didn't have a lock in the first place] it doesn't actually conflict. |
Cool, that seems like no big deal probably. It will only happen in development configuration, and even then actually doing an autoload doesn't happen all the time. And (I think?) shouldn't take very long until the lock is released -- if the lock is only held for the actual autoload (rather than until the end of the entire |
And one last time, wow, nice job! I don't understand how you've implemented it, but when I was thinking of how it might be possible to get this stuff to work under concurrency in Rails... I kept thinking, yeah, that's just not feasible, I don't see how you'd do that. Thanks! Looking forward to docs, including what the executor.run might take care of for you in addition to autoloading safety and obviating the need for |
I have a similar issue with Rails 5 and concurrent-ruby when trying to asynchronously write to an event stream, which Rails.application.executor.wrap does not seem to fix. When in development (config.eager_load = false and config.cache_classes = false) rails will hang and no futures will complete, it works fine when those options are both true. I have reproduced the issue here but here is the controller action:
I tried with the various other Rails helper wrappers in this thread but nothing seemed to fix it. Any ideas? |
@patrickbrownsync wrap the |
Well thanks, that does solve the issue in my example, but not in my actual use case. The sleep was a replacement for blocking on a Redis subscription and forwarding those messages along. Can you give me some more details on why I needed to wrap sleep with permit_concurrent_loads? |
@patrickbrownsync does #27494 help? |
I think so, it makes more sense now. I've got some digging to do though. Thanks! |
This issue has been automatically marked as stale because it has not been commented on for at least three months. |
I experience deadlocks constantly. A bit of digging/readings and local tests led me to a simple app that hangs easily since first start of sidekiq. https://github.com/jughead/sidekiq-deadlock-example Looks like if you have blocking actions in another system (postgres locks in the current case) everything will hang. P.S.: Not sure, but it might be the case with ordinal concurrent web requests (to Puma) as well, but there we have Rack::Lock that we can live with. |
So the lock happens in the following way:
|
Corresponding result of sending TTIN signal to sidekiq: Sidekiq log
2018-02-14T16:04:15.453Z 35029 TID-ox3u4uddp FirstWorker JID-73e3981768c4b179ab0195bb INFO: start
2018-02-14T16:04:15.511Z 35029 TID-ox3u4udjh SecondWorker JID-6ae290a11473d072dd2f8c8b INFO: start
2018-02-14T16:05:29.463Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3tmlvgd
2018-02-14T16:05:29.463Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/cli.rb:162:in `backtrace'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/cli.rb:162:in `block (2 levels) in '
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/cli.rb:159:in `each'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/cli.rb:159:in `block in '
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/cli.rb:174:in `handle_signal'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/cli.rb:109:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/bin/sidekiq:12:in `'
/Users/alex/.rbenv/versions/2.4.0/bin/sidekiq:22:in `load'
/Users/alex/.rbenv/versions/2.4.0/bin/sidekiq:22:in `'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/lib/bundler/cli/exec.rb:75:in `load'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/lib/bundler/cli/exec.rb:75:in `kernel_load'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/lib/bundler/cli/exec.rb:28:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/lib/bundler/cli.rb:424:in `exec'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/lib/bundler/cli.rb:27:in `dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/lib/bundler/cli.rb:18:in `start'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/exe/bundle:30:in `block in '
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/lib/bundler/friendly_errors.rb:122:in `with_friendly_errors'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/bundler-1.16.1/exe/bundle:22:in `'
/Users/alex/.rbenv/versions/2.4.0/bin/bundle:22:in `load'
/Users/alex/.rbenv/versions/2.4.0/bin/bundle:22:in `'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3tpirh9
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `select'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68:in `_run_worker'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:52:in `_run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/base.rb:78:in `block in start'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3tpintl
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/config.rb:19:in `sleep'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/config.rb:19:in `sleep'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/processor.rb:59:in `_sleep'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/processor.rb:84:in `_wait_until_events'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/processor.rb:16:in `block in loop_for'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/processor.rb:15:in `loop'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/processor.rb:15:in `loop_for'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/loop.rb:84:in `_wait_for_changes'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/loop.rb:42:in `block in setup'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u5alad
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `select'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68:in `_run_worker'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:52:in `_run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/base.rb:78:in `block in start'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u5al69
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/config.rb:19:in `sleep'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/config.rb:19:in `sleep'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/processor.rb:59:in `_sleep'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/processor.rb:84:in `_wait_until_events'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/processor.rb:16:in `block in loop_for'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/processor.rb:15:in `loop'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/processor.rb:15:in `loop_for'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/loop.rb:84:in `_wait_for_changes'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/event/loop.rb:42:in `block in setup'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u57no5
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `select'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68:in `_run_worker'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:77:in `block (2 levels) in _run_workers_in_background'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u57qnh
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `select'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68:in `_run_worker'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:77:in `block (2 levels) in _run_workers_in_background'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u57qdl
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `select'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68:in `_run_worker'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:77:in `block (2 levels) in _run_workers_in_background'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u57q7t
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `select'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68:in `_run_worker'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:77:in `block (2 levels) in _run_workers_in_background'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u57pxh
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `select'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68:in `_run_worker'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:77:in `block (2 levels) in _run_workers_in_background'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u57prp
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `select'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68:in `_run_worker'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:77:in `block (2 levels) in _run_workers_in_background'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u57plt
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `select'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68:in `_run_worker'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:77:in `block (2 levels) in _run_workers_in_background'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u57p89
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `select'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68:in `_run_worker'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:77:in `block (2 levels) in _run_workers_in_background'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u57o7d
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `select'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68:in `_run_worker'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:77:in `block (2 levels) in _run_workers_in_background'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u57fix
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `select'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:44:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68:in `_run_worker'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:77:in `block (2 levels) in _run_workers_in_background'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6:in `block in add'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u4ueat heartbeat
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/launcher.rb:124:in `sleep'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/launcher.rb:124:in `start_heartbeat'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/util.rb:16:in `watchdog'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/util.rb:25:in `block in safe_thread'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u4ue35 scheduler
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/connection_pool-2.2.1/lib/connection_pool/timed_stack.rb:87:in `sleep'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/connection_pool-2.2.1/lib/connection_pool/timed_stack.rb:87:in `wait'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/connection_pool-2.2.1/lib/connection_pool/timed_stack.rb:87:in `block (2 levels) in pop'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/connection_pool-2.2.1/lib/connection_pool/timed_stack.rb:78:in `loop'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/connection_pool-2.2.1/lib/connection_pool/timed_stack.rb:78:in `block in pop'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/connection_pool-2.2.1/lib/connection_pool/timed_stack.rb:77:in `synchronize'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/connection_pool-2.2.1/lib/connection_pool/timed_stack.rb:77:in `pop'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/scheduled.rb:89:in `wait'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/scheduled.rb:69:in `block in start'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/util.rb:16:in `watchdog'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/util.rb:25:in `block in safe_thread'
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u4udjh processor
2018-02-14T16:05:29.464Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/2.4.0/monitor.rb:111:in `sleep'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/2.4.0/monitor.rb:111:in `wait'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/2.4.0/monitor.rb:111:in `wait'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/2.4.0/monitor.rb:123:in `wait_while'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/concurrency/share_lock.rb:220:in `wait_for'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/concurrency/share_lock.rb:82:in `block (2 levels) in start_exclusive'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/concurrency/share_lock.rb:186:in `yield_shares'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/concurrency/share_lock.rb:81:in `block in start_exclusive'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/concurrency/share_lock.rb:76:in `start_exclusive'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/concurrency/share_lock.rb:148:in `exclusive'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/dependencies/interlock.rb:11:in `loading'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/dependencies.rb:37:in `load_interlock'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/dependencies.rb:358:in `require_or_load'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/dependencies.rb:511:in `load_missing_constant'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/dependencies.rb:203:in `const_missing'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/dependencies.rb:543:in `load_missing_constant'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/dependencies.rb:203:in `const_missing'
/Users/alex/github/sidekiq-deadlock-example/app/workers/second_worker.rb:8:in `block in perform'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `block in transaction'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/transaction.rb:189:in `within_new_transaction'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `transaction'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/transactions.rb:211:in `transaction'
/Users/alex/github/sidekiq-deadlock-example/app/workers/second_worker.rb:5:in `perform'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:187:in `execute_job'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:169:in `block (2 levels) in process'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/query_cache.rb:56:in `cache'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/query_cache.rb:9:in `cache'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/middleware/server/active_record_cache.rb:6:in `call'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/middleware/chain.rb:133:in `invoke'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:168:in `block in process'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:139:in `block (6 levels) in dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/job_retry.rb:97:in `local'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:138:in `block (5 levels) in dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/rails.rb:47:in `block in call'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/execution_wrapper.rb:85:in `wrap'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/reloader.rb:68:in `block in wrap'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/execution_wrapper.rb:85:in `wrap'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/reloader.rb:67:in `wrap'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/rails.rb:46:in `call'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:134:in `block (4 levels) in dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:199:in `stats'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:129:in `block (3 levels) in dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/job_logger.rb:7:in `call'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:128:in `block (2 levels) in dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/job_retry.rb:72:in `global'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:127:in `block in dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/logging.rb:48:in `with_context'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:126:in `dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:167:in `process'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:85:in `process_one'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:73:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/util.rb:16:in `watchdog'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/util.rb:25:in `block in safe_thread'
2018-02-14T16:05:29.465Z 35029 TID-ox3tmlvgd WARN: Thread TID-ox3u4uddp processor
2018-02-14T16:05:29.465Z 35029 TID-ox3tmlvgd WARN: /Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql_adapter.rb:598:in `async_exec'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql_adapter.rb:598:in `block in exec_no_cache'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract_adapter.rb:590:in `block in log'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract_adapter.rb:583:in `log'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql_adapter.rb:598:in `exec_no_cache'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql_adapter.rb:587:in `execute_and_clear'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/database_statements.rb:116:in `exec_delete'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:133:in `update'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/query_cache.rb:17:in `update'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/relation.rb:89:in `_update_record'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/persistence.rb:559:in `_update_record'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/locking/optimistic.rb:79:in `_update_record'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/attribute_methods/dirty.rb:119:in `_update_record'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/callbacks.rb:306:in `block in _update_record'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/callbacks.rb:97:in `__run_callbacks__'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/callbacks.rb:750:in `_run_update_callbacks'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/callbacks.rb:306:in `_update_record'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/timestamp.rb:81:in `_update_record'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/persistence.rb:548:in `create_or_update'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/callbacks.rb:298:in `block in create_or_update'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/callbacks.rb:97:in `__run_callbacks__'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/callbacks.rb:750:in `_run_save_callbacks'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/callbacks.rb:298:in `create_or_update'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/persistence.rb:160:in `save!'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/validations.rb:50:in `save!'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/attribute_methods/dirty.rb:30:in `save!'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/transactions.rb:324:in `block in save!'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/transactions.rb:395:in `block in with_transaction_returning_status'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:230:in `transaction'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/transactions.rb:211:in `transaction'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/transactions.rb:392:in `with_transaction_returning_status'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/transactions.rb:324:in `save!'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/suppressor.rb:45:in `save!'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/persistence.rb:288:in `block in update!'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/transactions.rb:395:in `block in with_transaction_returning_status'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:230:in `transaction'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/transactions.rb:211:in `transaction'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/transactions.rb:392:in `with_transaction_returning_status'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/persistence.rb:286:in `update!'
/Users/alex/github/sidekiq-deadlock-example/app/workers/first_worker.rb:7:in `block in perform'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `block in transaction'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/transaction.rb:189:in `within_new_transaction'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `transaction'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/transactions.rb:211:in `transaction'
/Users/alex/github/sidekiq-deadlock-example/app/workers/first_worker.rb:5:in `perform'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:187:in `execute_job'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:169:in `block (2 levels) in process'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activerecord-5.0.6/lib/active_record/query_cache.rb:11:in `cache'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/middleware/server/active_record_cache.rb:6:in `call'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/middleware/chain.rb:133:in `invoke'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:168:in `block in process'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:139:in `block (6 levels) in dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/job_retry.rb:97:in `local'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:138:in `block (5 levels) in dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/rails.rb:47:in `block in call'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/execution_wrapper.rb:85:in `wrap'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/reloader.rb:68:in `block in wrap'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/execution_wrapper.rb:85:in `wrap'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/activesupport-5.0.6/lib/active_support/reloader.rb:67:in `wrap'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/rails.rb:46:in `call'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:134:in `block (4 levels) in dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:199:in `stats'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:129:in `block (3 levels) in dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/job_logger.rb:7:in `call'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:128:in `block (2 levels) in dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/job_retry.rb:72:in `global'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:127:in `block in dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/logging.rb:48:in `with_context'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:126:in `dispatch'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:167:in `process'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:85:in `process_one'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/processor.rb:73:in `run'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/util.rb:16:in `watchdog'
/Users/alex/.rbenv/versions/2.4.0/lib/ruby/gems/2.4.0/gems/sidekiq-5.1.1/lib/sidekiq/util.rb:25:in `block in safe_thread'
|
I've also added web example ☝️ @matthewd could you or somebody else help? I don't think wrapping any transaction update with |
@jughead FYI |
@jmgarnier I was happy seeing the reply in my mailbox thinking there is somebody helping 😂 Thank you, I've hidden the log |
See rails/rails#26847. Signed-off-by: Pierre-Alexandre Meyer <pierre@mouraf.org>
I sometimes need/want to use some basic threaded concurrency inside a rails action --
execute some things concurrently, wait for them all to complete before returning
the response.
Here is a basic isolated fake example, as used in this demo app:
This is a useful thing to do you really do need to wait for those "SomeWorker"
results to return a response, but they are a bit slow, and can be performed
concurrently/in parallel. (Even with MRI GIL this is effective when they are
slow because of IO).
In Rails 4.x, under default configuration in an app, in development mode,
this would mostly work fine, but would occasionally raise a weird
exception involving "class definition has changed" or something, I'm afraid I
forget the exact exception class/message and can't find it.
In Rails 4.x, if you correct set up the under-documented and inter-related
relevant config keys --
config.eager_load
,config.auto_load
andconfig.cache_classes
-- you could make it work entirely correctly, probablyby giving up development-mode class reloading though.
In Rails 4.x, it works fine under default production configuration, and as
far as I know does in Rails 5 too.
But in development mode, tn Rails 5.0, due to new autoloading logic, the "failure mode" has changed --
if you don't configure things correct, instead of (Rails 4) getting mostly working
but occasionally weird exception -- you get (Rails 5) the worker thread hanging
forever (presumably a deadlock).
My reproduction/demonstration app has
config/development.rb
set up to use ENV varsto make testing under various config combinations more convenient.
Findings:
Under default generated app config
Rails worker thread hangs forever on first request.
CONF_EAGER_LOAD=false CONF_CACHE_CLASSES=true
Same, hangs forever on first request.
CONF_EAGER_LOAD=true CONF_CACHE_CLASSES=false rails serve
Works fine on initial requests. However, if you change
the source of a file on disk, that gets referenced in
one of the child threads, on next request the worker
thread will hang forever.
CONF_EAGER_LOAD=true CONF_CACHE_CLASSES=true
This is the magic configuration that makes it work, at the cost of
giving up on development-mode class reloading, you need to restart
the app to pick up any changes.
Additional irrelevant config or logic:
The setting for
config.auto_load
is irrelevant. In each of the above 4 cases,whether
config.auto_load
was set to true, false, or unset (use default) madeno difference,
config.eager_load
andconfig.cache_classes
were the onlysettings that seemed to matter for this behavior.
I was aware of
Rails.application.reloader
from seeing it used in asidekiq change. Without really
understanding it, I tried wrapping my child threads like so:
That made no difference either, all observed behavior was the same in
above 4 configuration combinations, with or without this
wrap
. I don'tknow if there's a more useful way to use the
reloader
for this use case,or if it's just irrelevant.
Issues for Rails team:
Is this a bug?
I suspect the answer will be "no" -- it is no longer supported to use
threads like this without turning off development-mode class reloading
entirely.
This is a bit annoying, as I much preferred having it mostly working
with occasional exceptions that made me restart the app, instead of
needing to turn off dev-mode reloading to get it to work at all, and
always having to restart the app to pick up changes.
However, it may be that's just how it is, as sad as it makes me. Nevertheless:
Can failure mode be better?
The "failure mode" for doing it wrong of hanging forever/deadlocking
is pretty annoying and confusing. It can take someone quite a while
to figure out what's going on, and that it's even related to auto-loading
at all. Especially with concurrency getting easier to use for less
experienced developers (hooray ruby-concurrent), I can see people
getting really stuck here they accidentally do it 'wrong' and get a
mysterious deadlock.
Is there any way to get a better failure mode, an actual quick fail with
an exception with a useful class/message, instead of a hang forever/deadlock?
Whether this is considered a 'bug' or a 'new feature' has to do with the
intentions of whoever wrote the new autoloading stuff, I guess. I couldn't
say.
Documentation.
All of these things need better documentation -- which has been
true pre-Rails5 too, but with changes those of us who kind of
sort of figured it out in Rails <5 could use it too.
Save others the several hours I spent debugging my deadlock, investigating
the issue, resulting in this here you are reading.
I can't submit a doc PR myself, because I really don't understand
well enough what's actually going on, or the intended behavior/configuration.
Some suggested doc needs:
config.eager_load
,config.cache_classes
andconfig.auto_load
havealways been poorly-doc'd, especially their interactions with each other,
and their defaults, which seem to depend on how others of them are set.
Not only poorly doc'd, but fairly high 'churn' changing from Rails version
to version.
For my use case, I only avoided deadlock with
eager_load
andcache_classes
both true. Is there any reason at all to haveone true and the other false? In what circumstances might
this make sense, and what does it do?
Does
config.auto_load
do anything at all in Rails5, or has itbecome a no-op? It didn't seem to have an effect on my problem
case, but maybe it does in other cases? Or is it gone?
If it's true that you need to turn off dev-mode reloading in
order to use threads inside a Rails action method (inside the request loop),
and it's true that you do that with
eager_loading
andcache_classes
both set to true, then some documentation to that effect would be
welcome, and would save people some confusing debugging time.
If i havne't actually figured out the right/best/only way to do this,
and there are other options -- I'm prob not the only one who would
appreciate some docs!
Is there anyway to turn off class reloading, to be concurrency-safe
for the auto-loader, but still have view template (erb) reloading? I remember
there was in an old Rails version (3?), but the config seems to have
disappeared.
test enviornments. Default generated Rails5 test env
is
cache_classes==true
,eager_load==false
. Rails 4had some generated comments in
config/test.rb
about
eager_load
: " If you are using a tool thatpreloads Rails for running tests, you may have to set it to true."
A bit confusing and in my experience not entirely reliable advice in Rails 4.
I believe a "tool that preloads rails for running tests" basically
means "Capybara". Rails5 no longer generates this hint, but still defaults
eager_load
to false. Is this going to cause problems with capybara?Concurrency problems with capybara are super frustrating to debug
and figure out how to deal with them, so some instructions
here would be much appreciated. Especially since the default setting
is one that under my use case above still caused deadlocks.
Rails.application.reloader
The only reason I knew this even existed, or anything at all about how to use
it, is from the sidekiq pr.
The only reason it's in a sidekiq PR is because someone from Rails core
team gave sidekiq hints/code, it would be unlikely for anyone who doesn't
already know the code to have known that it should be used, and the correct
way to use it.
It may be that
Rails.application.reloader
is entirely irrelevant tomy use case -- some docs explaining what it is and how it use it could
have saved me some time in figuring that out myself by experimenting.
But clearly there are some appropriate use cases for it in non-Rails-core code,
like in sidekiq. some docs are needed so people not on Rails core team know when to use it,
and how.
Tagging @matthewd , because he suggested in the sidekiq PR that I open
a Rails issue on documentation of the "executor/reloader API", and I'm
hoping he has some input on the general reloading/concurrency issues
above, since they look pretty intimately related to the executor/reloader
in Rails5.
The text was updated successfully, but these errors were encountered: