@ledsun blog

無味の味は佳境に入らざればすなわち知れず

Ruby on Railsの開発環境でマルチスレッドでクラス定義を探索すると刺さるが再現できなかった話

Ruby 技 Rails

現象

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

を指定すると、このエラーは起きなくなります。

やはり、「定数の自動読み込み」と関係がありそうです。

残る謎

  • マルチスレッドであれば起きるはずなのに、Rails consoleで次のソースコードを実行しても発生しない
1000.times { Thread.new { Answer } }
  • 元の現象では固まるのに、再現コードではエラーが発生する

暫定の結論

元のソースコードの、クラス探索で固まる現象もeager_loadを有効にすると発生しなくなります。 これ以上調査時間が取れないので、この記事で供養して完了とします。

*1:発生したソースコードと完全には一致していません。

*2:GILがあるから並列に動かないし衝突しないはず・・・と思ったら、ファイルからクラスを読み込む処理なので並列に動くようです。