Rails reload! (both in console and using the reloader.reload!) hangs with multi-threaded applications

[mensfeld]

Steps to reproduce

rails new testme
cd testme
bundle exec rails generate scaffold User
bundle exec rake db:create
bundle exec rake db:migrate
bundle exec rails console
# in the console:
require 'benchmark'
Thread.new { User.create!; sleep(100) }
# wait for 1 second and run reload - it will hang for around 10 seconds
puts Benchmark.measure { reload! }
# 0.019528   0.000312   0.019840 ( 10.028938)

Expected behavior

Since the thread is sleeping after user creation and does nothing, I would expect not to hang for such a long time.

Actual behavior

It hangs for 10 seconds. Same happens when reloading from within a process that includes Rails. It hangs for 10 seconds despite the fact that the thread is sleeping more. Even if thread is sleeping shorted period of time (lets say 5s), the reload takes 10.

This is in particular problematic for processes running with Rails in a dev mode, where threads are long living (worker polls for example) and blocked on a Queue#pop.

I confirmed this problem affects sqlite as well as pg.

System configuration

Rails & Ruby version:

About your application's environment
Rails version             7.0.1
Ruby version              ruby 3.0.3p157 (2021-11-24 revision 3fb7d2cadc) [x86_64-linux]
RubyGems version          3.2.32
Rack version              2.2.3
Middleware                ActionDispatch::HostAuthorization, Rack::Sendfile, ActionDispatch::Static, ActionDispatch::Executor, ActionDispatch::ServerTiming, ActiveSupport::Cache::Strategy::LocalCache::Middleware, Rack::Runtime, Rack::MethodOverride, ActionDispatch::RequestId, ActionDispatch::RemoteIp, Sprockets::Rails::QuietAssets, Rails::Rack::Logger, ActionDispatch::ShowExceptions, WebConsole::Middleware, ActionDispatch::DebugExceptions, ActionDispatch::ActionableExceptions, ActionDispatch::Reloader, ActionDispatch::Callbacks, ActiveRecord::Migration::CheckPending, ActionDispatch::Cookies, ActionDispatch::Session::CookieStore, ActionDispatch::Flash, ActionDispatch::ContentSecurityPolicy::Middleware, ActionDispatch::PermissionsPolicy::Middleware, Rack::Head, Rack::ConditionalGet, Rack::ETag, Rack::TempfileReaper
Application root          /home/mencio/Software/testme
Environment               development
Database adapter          sqlite3
Database schema version   20220116201051

[rails-bot[bot]]

This issue has been automatically marked as stale because it has not been commented on for at least three months. The resources of the Rails team are limited, and so we are asking for your help. If you can still reproduce this error on the 7-0-stable branch or on main, please reply with all of the information you have about it in order to keep the issue open. Thank you for all your contributions.

[mensfeld]

The problem still persists with 7.0. Nothing changed.

[rails-bot[bot]]

This issue has been automatically marked as stale because it has not been commented on for at least three months. The resources of the Rails team are limited, and so we are asking for your help. If you can still reproduce this error on the 7-0-stable branch or on main, please reply with all of the information you have about it in order to keep the issue open. Thank you for all your contributions.

[mensfeld]

The problem still persists with 7.0. Nothing changed.

[fxn]

I missed this one.

If we replace reload! with a direct call to Rails.autoloaders.main.reload, the reload happens promptly. You cannot do that because reloading is not thread-safe, but that result suggests the 10s might come from the reload synchronization in the framework itself.

This script:

Thread.new {
  p User.create!
  sleep(100)
}

sleep(1)

puts Benchmark.measure {
   puts "About to reload"
   Rails.application.reloader.reload!
}

can be executed with bin/rails runner and simplifies reproduction. You'll see "about to reload" is printed soon, and then reload! takes time.

Let me /cc @matthewd, who is more familiar with synchronization.

[jonathanhefner]

I think this is the same issue as #39431, which was not completely resolved.

[fxn]

@jonathanhefner great yak shaving in that ticket!

[mensfeld]

Not rushing anyone, but maybe there is a way to at least bypass that? :sweat:

I guess I could stop all the background jobs work, run Rails.autoloaders.main.reload and start again, but the complexity of this in my case would be at least... decent.

[mensfeld]

Also @fxn Rails.autoloaders.main.reload does not solve the issue entirely. It seems to reload code but then some of the threads seem to "keep" the lock for the 10 seconds anyhow.

[mensfeld]

Last comment for today. If I wrap my threads that run ActiveRecord code with:

ActiveRecord::Base.connection_pool.with_connection do
  # my code
end

and threads are released back, there is no problem. I may add #release_connection to the end when in rails and AR ~detected but that sounds kinda "hacky"~ and the problem will be gone.

[rails-bot[bot]]

This issue has been automatically marked as stale because it has not been commented on for at least three months. The resources of the Rails team are limited, and so we are asking for your help. If you can still reproduce this error on the 7-0-stable branch or on main, please reply with all of the information you have about it in order to keep the issue open. Thank you for all your contributions.

[kaspergrubbe]

This is still reproducable in 7-0 https://github.com/rails/rails/issues/44183#issuecomment-1186436046

[mensfeld]

Just for the record using the ActiveRecord::Base.clear_active_connections! also makes the issue go away as the connections are released back. Maybe there could be a way to release this upon reload.

[rails-bot[bot]]

This issue has been automatically marked as stale because it has not been commented on for at least three months. The resources of the Rails team are limited, and so we are asking for your help. If you can still reproduce this error on the 7-0-stable branch or on main, please reply with all of the information you have about it in order to keep the issue open. Thank you for all your contributions.

[kaspergrubbe]

This is still reproducable in 7-0, I just tested it with Rails 7.0.4.2:

irb(main):004:0> puts Benchmark.measure { reload! }
Reloading...
  0.046544   0.138857   0.185401 ( 10.186940)
=> ni