こんにちは。id:Pocke です。最近は並列処理の実装に頭を悩ませています。
この記事では並列処理の実装の中で得た学びについて共有しようと思います。
なお特にことわりがない限り、Rubyのバージョンは記事執筆時点で最新の3.4.1を使用します。
問題
Threadをふんだんに使ったプログラムをデバッグしていると、デッドロックが起きたときに、その原因となったスレッドがどこで停止しているのかを知りたくなることがあります。
例えば以下のようなケースを考えてみます。
# わざとトレースを深くするメソッド呼び出し def f(q) = g q def g(q) = h q def h(q) = q.pop def main q = Thread::Queue.new # `q` にはエンキューされないので、これらのスレッドは停止する th1 = Thread.new { f q } th2 = Thread.new { f q } # ここでメインスレッドも停止するため、デッドロックする th1.join th2.join end main
このプログラムはデッドロックします。th1, th2はどちらもThread::Queue#popで停止し、メインスレッドもth1.joinでth1を待とうとして停止するためです。図に表すと以下のようになります。
さて、このコードを実行すると次の出力が得られます。
$ ruby -v test.rb ruby 3.4.1 (2024-12-25 revision 48d4efcb85) +PRISM [arm64-darwin24] test.rb:14:in 'Thread#join': No live threads left. Deadlock? (fatal) 3 threads, 3 sleeps current:0x0000000140ea9e00 main thread:0x0000000140e0eb40 * #<Thread:0x000000010465af90 sleep_forever> rb_thread_t:0x0000000140e0eb40 native:0x00000001e9d93240 int:0 * #<Thread:0x0000000104909480 test.rb:10 sleep_forever> rb_thread_t:0x0000000140e97c70 native:0x000000016bab7000 int:0 depended by: tb_thread_id:0x0000000140e0eb40 * #<Thread:0x0000000104909340 test.rb:11 sleep_forever> rb_thread_t:0x0000000140ea9e00 native:0x000000016bbc3000 int:0 from test.rb:14:in 'Object#main' from test.rb:18:in '<main>'
この結果からは以下のことがわかります。
- 出力の先頭より、14行目の
Thread#joinでデッドロックが発生していること - 出力の中程のリストより、3つのスレッドが存在し、すべてが停止していること
- 出力の最後の2行より、
Object#mainメソッドから続くバックトレースがエラーが起きた場所であること
今回のような簡単なプログラムであれば、この出力をもとに、問題となる箇所をすぐ見つけられるでしょう。
ですがより複雑なプログラムだとどうでしょうか？ この出力からは各スレッドが生成された箇所はわかりますが、それぞれのスレッドがどこで停止しているのかはわかりません。Thread::Queue#popのようなスレッドが停止する可能性のあるメソッドを呼び出す箇所が複数ある場合、この情報だけでは問題を特定するのは難しいでしょう。
ではデッドロック時に各スレッドのバックトレースが表示されていたらどうでしょうか？ それならば各スレッドが停止している位置がトレースとして表示されるため、問題の特定が圧倒的に楽になりそうです。それを実装する方法を考えてみましょう。
解決策 その1
デッドロック時に発生する例外をrescueして、各スレッドのバックトレースを表示すれば、目的を達成できそうです。
これは次のように実装できます。
# f, g, h, main の定義は先の例と同じなので省略 begin main rescue Exception Thread.list.each do |t| $stderr.puts "Thread: #{t.inspect}" $stderr.puts t.backtrace.join("\n") $stderr.puts end raise end
このコードを実行すると、以下の出力が得られます。
$ ruby -v test.rb
ruby 3.4.1 (2024-12-25 revision 48d4efcb85) +PRISM [arm64-darwin24]
Thread: #<Thread:0x0000000100d8af80 run>
test.rb:23:in 'Thread#backtrace'
test.rb:23:in 'block in <main>'
test.rb:21:in 'Array#each'
test.rb:21:in '<main>'
Thread: #<Thread:0x000000011bf59260 test.rb:10 sleep_forever>
<internal:thread_sync>:18:in 'Thread::Queue#pop'
test.rb:4:in 'Object#h'
test.rb:3:in 'Object#g'
test.rb:2:in 'Object#f'
test.rb:10:in 'block in Object#main'
Thread: #<Thread:0x000000011bf59120 test.rb:11 sleep_forever>
<internal:thread_sync>:18:in 'Thread::Queue#pop'
test.rb:4:in 'Object#h'
test.rb:3:in 'Object#g'
test.rb:2:in 'Object#f'
test.rb:11:in 'block in Object#main'
test.rb:14:in 'Thread#join': No live threads left. Deadlock? (fatal)
3 threads, 3 sleeps current:0x000000012a70e040 main thread:0x000000012a60eb40
* #<Thread:0x0000000100d8af80 sleep_forever>
rb_thread_t:0x000000012a60eb40 native:0x00000001e9d93240 int:0
* #<Thread:0x000000011bf59260 test.rb:10 sleep_forever>
rb_thread_t:0x000000012a712b40 native:0x000000016f38b000 int:0
depended by: tb_thread_id:0x000000012a60eb40
* #<Thread:0x000000011bf59120 test.rb:11 sleep_forever>
rb_thread_t:0x000000012a70e040 native:0x000000016f497000 int:0
from test.rb:14:in 'Object#main'
from test.rb:19:in '<main>'
エラーメッセージの前に、各スレッドのバックトレースが表示されました。これならばth1, th2が停止している箇所が、hメソッド内のThread::Queue#popの呼び出しであることが分かりますね！
問題点
しかし、この方法にもいくつか問題があります。
まず、デッドロックが発生したスレッドに対するバックトレースは、デッドロックが発生した位置ではなく、rescue節内の$stderr.puts t.backtrace.join("\n")しているところのバックトレースが表示されてしまっています。
今回の例ではメインスレッドがこれに当たります。メインスレッドはThread#joinメソッドの呼び出しで停止しデッドロックになりますが、Thread#joinメソッドの呼び出し位置ではなく、rescue節内の位置が表示されています。
またこの方法ではデッドロックが起きた際に毎回rescue節以下のコードを追加する必要があります。並列処理の実装は不確実性が高いケースも多く、エラーが起きてから追加するのでは嬉しくないことも多いでしょう。
1つ目の問題については、エラー出力の最後の部分、つまりこの例外自体のバックトレースにデッドロックが起きた位置が表示されています。 とはいえ不正確な位置が表示されてしまっていること、そして2つ目の問題もあることから、この方法は100点の解決策とは言えないでしょう。
解決策 その2
より良い解決策がないかこの問題にしばらく思いを馳せていると、ふと、デッドロック時にバックトレースが表示されている光景を見たことがある気がしてきました。幻でしょうか？ もしこの記憶が正しければ、オプションなどでバックトレースの表示がオフになってしまっているのではないかと考えました。 もともと問題となっていたデッドロック自体は先の方法ですでに解決していたのですが、この解決策に納得できていなかったこともあり、調査をすることにしました。
まずThreadクラスのドキュメントを読んだのですが特に記載がなかったため、Rubyのソースコードを眺めることにしました。
このエラー出力を作っているところを探すには、エラーメッセージで検索するのが簡単そうです。No live threads left. Deadlockで検索すると、thread.cのrb_check_deadlock関数がヒットしました。
https://github.com/ruby/ruby/blob/v3_4_1/thread.c#L5604-L5644
static void rb_check_deadlock(rb_ractor_t *r) { // (略) if (!found) { VALUE argv[2]; argv[0] = rb_eFatal; argv[1] = rb_str_new2("No live threads left. Deadlock?"); debug_deadlock_check(r, argv[1]); rb_ractor_sleeper_threads_dec(GET_RACTOR()); rb_threadptr_raise(r->threads.main, 2, argv); } }
どうやらスレッド一覧を表示している部分の組み立ては、ここから呼ばれているdebug_deadlock_check関数で行っていそうです。そちらも見てみましょう。
https://github.com/ruby/ruby/blob/v3_4_1/thread.c#L5570-L5602
static void debug_deadlock_check(rb_ractor_t *r, VALUE msg) { rb_thread_t *th = 0; VALUE sep = rb_str_new_cstr("\n "); rb_str_catf(msg, "\n%d threads, %d sleeps current:%p main thread:%p\n", rb_ractor_living_thread_num(r), rb_ractor_sleeper_thread_num(r), (void *)GET_THREAD(), (void *)r->threads.main); ccan_list_for_each(&r->threads.set, th, lt_node) { rb_str_catf(msg, "* %+"PRIsVALUE"\n rb_thread_t:%p " "native:%p int:%u", th->self, (void *)th, th->nt ? thread_id_str(th) : "N/A", th->ec->interrupt_flag); if (th->locking_mutex) { rb_mutex_t *mutex = mutex_ptr(th->locking_mutex); rb_str_catf(msg, " mutex:%p cond:%"PRIuSIZE, (void *)mutex->fiber, rb_mutex_num_waiting(mutex)); } { struct rb_waiting_list *list = th->join_list; while (list) { rb_str_catf(msg, "\n depended by: tb_thread_id:%p", (void *)list->thread); list = list->next; } } rb_str_catf(msg, "\n "); rb_str_concat(msg, rb_ary_join(rb_ec_backtrace_str_ary(th->ec, 0, 0), sep)); rb_str_catf(msg, "\n"); } }
この関数の最後の部分に注目します。rb_ec_backtrace_str_ary(th->ec, 0, 0)がバックトレースを取得していることがわかります。そしてこの戻り値が出力されれば、デッドロック時に各スレッドのバックトレースが表示されるはずです。
ですがコードを読む限り、rb_ec_backtrace_str_ary関数はオプションなどで制御されてはおらず、常に呼ばれているように見えます。それなのにバックトレースが表示されないのは不思議ですね。
そこでrb_ec_backtrace_str_ary関数の使い方に問題があるのではないかと思い、この関数の定義と他の使用箇所を見ることにしました。
この関数はvm_backtrace.cで定義されています。
https://github.com/ruby/ruby/blob/v3_4_1/vm_backtrace.c#L967-L971
VALUE rb_ec_backtrace_str_ary(const rb_execution_context_t *ec, long lev, long n) { return rb_backtrace_to_str_ary(rb_ec_partial_backtrace_object(ec, lev, n, NULL, FALSE, FALSE)); }
そしてこのファイル内の別の箇所でこの関数が次のように呼ばれています。
VALUE rb_make_backtrace(void) { return rb_ec_backtrace_str_ary(GET_EC(), BACKTRACE_START, ALL_BACKTRACE_LINES); }
第2引数と第3引数に、それぞれBACKTRACE_STARTとALL_BACKTRACE_LINESが渡されています。名前からして、バックトレースの先頭からすべての行を取得するための定数のようです。デッドロック時にもこれらの定数が渡されていると良さそうです。
ではこれらの値の定義を見てみましょう。これらはマクロとしてvm_backtrace.cに定義されています。
https://github.com/ruby/ruby/blob/v3_4_1/vm_backtrace.c#L34-L35
#define BACKTRACE_START 0 #define ALL_BACKTRACE_LINES -1
ここで注目したいのはALL_BACKTRACE_LINESが-1と定義されていることです。vm_backtrace.cとデッドロック時のrb_ec_backtrace_str_ary関数の呼び出しを並べて見ると、次のようになっています。
// vm_backtrace.c rb_ec_backtrace_str_ary(GET_EC(), BACKTRACE_START, ALL_BACKTRACE_LINES) // デッドロック時 rb_ec_backtrace_str_ary(th->ec, 0, 0)
デッドロック時には第3引数に0が渡されていますが、vm_backtrace.cではALL_BACKTRACE_LINESとして-1が渡されています。
であるならばデッドロック時にも-1を渡せばバックトレースが表示されるのではないでしょうか？ 次のパッチを試してみましょう。
diff --git a/thread.c b/thread.c index 961e604856..ebd5425bee 100644 --- a/thread.c +++ b/thread.c @@ -5596,7 +5596,7 @@ debug_deadlock_check(rb_ractor_t *r, VALUE msg) } } rb_str_catf(msg, "\n "); - rb_str_concat(msg, rb_ary_join(rb_ec_backtrace_str_ary(th->ec, 0, 0), sep)); + rb_str_concat(msg, rb_ary_join(rb_ec_backtrace_str_ary(th->ec, 0, -1), sep)); rb_str_catf(msg, "\n"); } }
このパッチを適用したうえで記事の冒頭のプログラムを実行すると、次の出力が得られます。
$ ruby -v test.rb ruby 3.4.1 (2024-12-25 revision 48d4efcb85) +PRISM [arm64-darwin24] test.rb:14:in 'Thread#join': No live threads left. Deadlock? (fatal) 3 threads, 3 sleeps current:0x0000000122e6fd70 main thread:0x0000000122e0eb40 * #<Thread:0x000000011a69afa8 sleep_forever> rb_thread_t:0x0000000122e0eb40 native:0x00000001e9d93240 int:0 test.rb:14:in 'Thread#join' test.rb:14:in 'Object#main' test.rb:18:in '<main>' * #<Thread:0x000000011d579d60 test.rb:10 sleep_forever> rb_thread_t:0x0000000122e2d090 native:0x000000016f30f000 int:0 depended by: tb_thread_id:0x0000000122e0eb40 <internal:thread_sync>:18:in 'Thread::Queue#pop' test.rb:4:in 'Object#h' test.rb:3:in 'Object#g' test.rb:2:in 'Object#f' test.rb:10:in 'block in Object#main' * #<Thread:0x000000011d579c20 test.rb:11 sleep_forever> rb_thread_t:0x0000000122e6fd70 native:0x000000016f41b000 int:0 <internal:thread_sync>:18:in 'Thread::Queue#pop' test.rb:4:in 'Object#h' test.rb:3:in 'Object#g' test.rb:2:in 'Object#f' test.rb:11:in 'block in Object#main' from test.rb:14:in 'Object#main' from test.rb:18:in '<main>'
期待通りバックトレースが表示されました！これでデッドロック時の調査が楽にできますね。先に挙げた解決策のように、不正確な位置が表示されることも、rescue節を毎回追加する必要もなくなりました。
原因を探る
今回修正した箇所は、渡される引数が誤っていることでバックトレースが表示されないようになってしまっていたようです。ということは、過去には正しくバックトレースが出ていたことが伺えます。
どのバージョンから発生しているのかを調査する
まず、いつからバックトレースが表示されなくなってしまっていたのかを調査しました。
この調査にはall-rubyというツールを使いました。このツールを使うと、リリースされたすべてのRubyのバージョンでコードを実行できます。 Dockerイメージが提供されているため、それを使うと手軽に試すことができます。
次のコマンドでRuby 2.0以降のデッドロック時の出力を確認しました(古いRubyでも動くよう、実行コードを少し変更しています)。
$ docker run -it --rm rubylang/all-ruby env ALL_RUBY_SINCE=2.0 ./all-ruby -e 'require "thread" def f(q) g(q) end def g(q) h(q) end def h(q) q.pop end q = Thread::Queue.new th1 = Thread.new { f q } th2 = Thread.new { f q } th1.join th2.join' (略) ruby-2.7.8 -e:11:in `join': No live threads left. Deadlock? (fatal) 3 threads, 3 sleeps current:0x000000400066a8c0 main thread:0x000000400035da50 * #<Thread:0x000000400038ad70 sleep_forever> rb_thread_t:0x000000400035da50 native:0x0000004002fb7740 int:0 -e:11:in `join' -e:11:in `<main>' * #<Thread:0x00000040004fa318 -e:8 sleep_forever> rb_thread_t:0x0000004000451860 native:0x00000040067ae700 int:0 depended by: tb_thread_id:0x000000400035da50 -e:5:in `pop' -e:5:in `h' -e:4:in `g' -e:3:in `f' -e:8:in `block in <main>' * #<Thread:0x00000040004fa200 -e:9 sleep_forever> rb_thread_t:0x000000400066a8c0 native:0x000000400e9af700 int:0 -e:5:in `pop' -e:5:in `h' -e:4:in `g' -e:3:in `f' -e:9:in `block in <main>' from -e:11:in `<main>' exit 1 ruby-3.0.0-preview1 -e:11:in `join': No live threads left. Deadlock? (fatal) 3 threads, 3 sleeps current:0x00000040007585b0 main thread:0x00000040003eca30 * #<Thread:0x000000400045b498 sleep_forever> rb_thread_t:0x00000040003eca30 native:0x0000004003046740 int:0 * #<Thread:0x00000040007361e0 -e:8 sleep_forever> rb_thread_t:0x0000004000758300 native:0x000000400683d700 int:0 depended by: tb_thread_id:0x00000040003eca30 * #<Thread:0x00000040007360c8 -e:9 sleep_forever> rb_thread_t:0x00000040007585b0 native:0x000000400ea3e700 int:0 from -e:11:in `<main>' exit 1 (略)
すると、Ruby 2.7系ではバックトレースが表示されているのに対し、Ruby 3.0系からはバックトレースが表示されなくなっていることが分かりました。 デッドロック時のバックトレースを見たことがある記憶は幻ではなく本物だったようです。
どのコミットから発生しているのかを調査する
Ruby 3.0は2020年の年末にリリースされました。ということは、2020年ごろのコミットに原因がありそうです。
まずデッドロック時の処理が実装されているthread.cのコミット履歴を眺めたのですが、この期間に気になる変更はありませんででした。
そこでrb_ec_backtrace_str_ary関数の仕様が変更された可能性を考え、vm_backtrace.cのコミット履歴を見てみることにしました。
すると気になるコミットが見つかりました。
このコミットではKernel.#caller_locationsメソッドなどの高速化のために、vm_backtrace.cを修正しています。そして問題のALL_BACKTRACE_LINESマクロの定義もこのコミットで追加されています。
このコミットの変更を見ていくと、rb_ec_backtrace_str_ary関数の使用箇所で、0を渡していたものがALL_BACKTRACE_LINESを渡すように変更している箇所も見つけられました。1
ということでこのコミットが原因で間違いないでしょう。
念の為rubyfarm 2 というツールでも、このコミット前後でデッドロック時の出力が変わっていることを確認しました。
問題を修正する
原因の調査も完了したので、Ruby本体の修正を行うことにしました。
該当のコミットやRuby 3.0のリリースノートを読んでも、バックトレースが表示されないことは言及されていません。実際のコードから見ても、この変更は意図しないものでありバグである可能性が高いでしょう。 であれば手元での修正に留めるのではなく、Ruby本体を修正したほうが良いでしょう。ということで以下のバグチケットとパッチを作成しました。
パッチではマクロの使用やテストの追加などを行いましたが、基本的な方針はこの記事に書いたものと同じです。
この修正はすでにマージされており、Ruby 3.5からはデッドロック時にバックトレースが表示されるようになります。またRuby 3.4など現行のバージョンにもバックポートされるかもしれません。
まとめ
この記事では、ちょっとしたデバッグのつまずきがRubyのバグ修正につながった話を紹介しました。
デバッグ時にとても困りそうなものなのに、4年以上もバグが気づかれずにいたのはなかなか意外でした。 実際私はここ最近何度もバックトレースが表示されずに困っていたので、この変更でデバッグしやすくなることはとても嬉しいです。
- 変更前のコードの902行目 https://github.com/ruby/ruby/commit/3b24b7914c16930bfadc89d6aff6326a51c54295#diff-cf27dccd423ca45138f1278ea6ce04558360203e869cc1fb1608047c606f29d0L902↩
- 2017年頃からのRubyのすべてのコミットがビルドされたdockerイメージ群です。コミット間の挙動の比較を簡単に行えます。↩
