現象
Ruby on Railsの、ActiveJob内で起動したスレッドで非同期にDBに書き込もうとすると、ActiveRercordのクラス探索で無限に待って固まります。
わかっている条件
- ActiveJobで起きる
- ActiveJobのQueueAdapterにはAsync adapterを使っている
- DBへの接続以前のActiveRercordのクラス探索で固まる
例えば
Thread.start do executor = Lodqa::OneByOneExecutor.new dataset, query, debug: false # Bind events to colletc answers collected_answers = [] executor.on(:answer) do |_, val| Answer end end
このような処理*1をApplicationJobクラスで実行すると、Answerの探索で固まり、無限に待ちます。
Thread.startでスレッドを開始するほか、executor内でEventMachine#deferを使って更に複数スレッドで処理を行っています。
再現の努力
そこで、再現する最小のソースコードを書いてみます。
class CircularDependencyDetectedJob < ApplicationJob queue_as :default rescue_from(StandardError) do |exception| logger.fatal exception end def perform(*_args) Thread.new { EventMachine.run } 1.times do Thread.new do 2.times do EM.defer do Answer p 'Goal!!!' end end end end end end
エラーが発生
これを実行すると、固まりはしませんが、次のようなエラーが発生します。
/usr/src/myapp # rails c
Loading development environment (Rails 5.2.0)
irb(main):001:0> CircularDependencyDetectedJob.perform_later
Enqueued CircularDependencyDetectedJob (Job ID: 9676f7ff-5c23-411c-84e3-33aca66c5eae) to Async(default)
=> #<CircularDependencyDetectedJob:0x0000562444702420 @arguments=[], @job_id="9676f7ff-5c23-411c-84e3-33aca66c5eae", @queue_name="default", @priority=nil, @executions=0, @provider_job_id="39bf3d7d-051f-4915-a752-17686211c958">
irb(main):002:0> Performing CircularDependencyDetectedJob (Job ID: 9676f7ff-5c23-411c-84e3-33aca66c5eae) from Async(default)
Performed CircularDependencyDetectedJob (Job ID: 9676f7ff-5c23-411c-84e3-33aca66c5eae) from Async(default) in 62.71ms
#<Thread:0x000056244503a970@/usr/local/bundle/gems/eventmachine-1.2.7/lib/eventmachine.rb:1067 run> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
7: from /usr/local/bundle/gems/eventmachine-1.2.7/lib/eventmachine.rb:1077:in `block in spawn_threadpool'
6: from /usr/src/myapp/app/jobs/circular_dependency_detected_job.rb:16:in `block (4 levels) in perform'
5: from /usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:193:in `const_missing'
4: from /usr/local/bundle/gems/bootsnap-1.3.0/lib/bootsnap/load_path_cache/core_ext/active_support.rb:43:in `load_missing_constant'
3: from /usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:534:in `load_missing_constant'
2: from /usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:193:in `const_missing'
1: from /usr/local/bundle/gems/bootsnap-1.3.0/lib/bootsnap/load_path_cache/core_ext/active_support.rb:43:in `load_missing_constant'
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:500:in `load_missing_constant': Circular dependency detected while autoloading constant Answer (RuntimeError)
#<Thread:0x00005624446907f8@/usr/src/myapp/app/jobs/circular_dependency_detected_job.rb:9 aborting> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
7: from /usr/local/bundle/gems/eventmachine-1.2.7/lib/eventmachine.rb:1077:in `block in spawn_threadpool'
6: from /usr/src/myapp/app/jobs/circular_dependency_detected_job.rb:16:in `block (4 levels) in perform'
5: from /usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:193:in `const_missing'
4: from /usr/local/bundle/gems/bootsnap-1.3.0/lib/bootsnap/load_path_cache/core_ext/active_support.rb:43:in `load_missing_constant'
3: from /usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:534:in `load_missing_constant'
2: from /usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:193:in `const_missing'
1: from /usr/local/bundle/gems/bootsnap-1.3.0/lib/bootsnap/load_path_cache/core_ext/active_support.rb:43:in `load_missing_constant'
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:500:in `load_missing_constant': Circular dependency detected while autoloading constant Answer (RuntimeError)
Traceback (most recent call last):
7: from /usr/local/bundle/gems/eventmachine-1.2.7/lib/eventmachine.rb:1077:in `block in spawn_threadpool'
6: from /usr/src/myapp/app/jobs/circular_dependency_detected_job.rb:16:in `block (4 levels) in perform'
5: from /usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:193:in `const_missing'
4: from /usr/local/bundle/gems/bootsnap-1.3.0/lib/bootsnap/load_path_cache/core_ext/active_support.rb:43:in `load_missing_constant'
3: from /usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:534:in `load_missing_constant'
2: from /usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:193:in `const_missing'
1: from /usr/local/bundle/gems/bootsnap-1.3.0/lib/bootsnap/load_path_cache/core_ext/active_support.rb:43:in `load_missing_constant'
/usr/local/bundle/gems/activesupport-5.2.0/lib/active_support/dependencies.rb:500:in `load_missing_constant': Circular dependency detected while autoloading constant Answer (RuntimeError)
エラーの原因
該当のソースコードを読むと
if loading.include?(expanded) raise "Circular dependency detected while autoloading constant #{qualified_name}" else
loadingに自身が含まれていたら、循環依存で読み込みをやめる処理です。
マルチスレッドで読み込むと、循環依存していなくても、このチェックをするタイミングで他スレッドで自クラスを読み込んでいることがあるので、発生しているようです*2。
対応
この処理は定数の自動読み込みと再読み込み | Rails ガイドのための処理です。 自動読み込みを停止してみましょう。
Rails アプリケーションを設定する - Railsガイド
config.eager_loadをtrueにすると、config.eager_load_namespacesに登録された事前一括読み込み(eager loading)用の名前空間をすべて読み込みます。ここにはアプリケーション、エンジン、Railsフレームワークを含むあらゆる登録済み名前空間が含まれます。
config/environments/development.rbで
config.eager_load = true
を指定すると、このエラーは起きなくなります。
やはり、「定数の自動読み込み」と関係がありそうです。
残る謎
1000.times { Thread.new { Answer } }
- 元の現象では固まるのに、再現コードではエラーが発生する
暫定の結論
元のソースコードの、クラス探索で固まる現象もeager_loadを有効にすると発生しなくなります。
これ以上調査時間が取れないので、この記事で供養して完了とします。
