Bug #4027: Signal.trap で busy loop に陥る

• Status: Rejected
• Assignee: -
• Target version: -
• ruby -v: ruby 1.9.3dev (2010-10-29 trunk 29626) [i686-linux]

[nagachika (Tomoyuki Chikanaga)]

=begin
Signal.trap のシグナルハンドラ内で Mutex(Monitor) を用いる調査をしていて
稀にインタプリタが CPU を占有して busy loop 状態になることがありました。

あまり小さく絞れていませんが再現させたスクリプトを添付します。
元々はこれで時々 ThreadError: deadlock; recursive locking になるのを
避ける方法を考えるために実験していたのですが、ごく稀にインタプリタが止まり、
gdb attach すると下記のスタックトレースを得ました。

環境は
Red Hat Enterprise Linux ES release 3 (Taroon Update 8)
Linux 2.4.21-47.ELsmp #1 SMP Wed Jul 5 20:38:41 EDT 2006 i686 i686 i386 GNU/Linux
です。

また signal_buff という変数の内容がおかしいと思い表示させてみると

(gdb) p signal_buff
$1 = {cnt = {0 <repeats 65 times>}, size = -1}

のように signal_buff.size がアンダーフローしているようです。
sighandler() で signal_buff.cnt[sig] と signal_buff.size を increment しているところを
rb_disable_interrupt() で保護しないといけないのでしょうか？
そのようなパッチを当てて追試してみて今のところ再現していませんが、
元々なかなか起きていなかったので直ったのかははっきりしません。

(gdb) where
#0 0x00cb3007 in sched_yield () from /lib/tls/libc.so.6
#1 0x081524fc in rb_threadptr_execute_interrupts_rec (th=0x83da590, sched_depth=0) at thread.c:1253
#2 0x081526d7 in rb_threadptr_execute_interrupts (th=0x83da590) at thread.c:1318
#3 0x0814819c in vm_call0 (th=0x83da590, recv=0, id=792, argc=0, argv=0x0, me=0x84140a8) at vm_eval.c:146
#4 0x08148f19 in rb_call0 (recv=0, mid=792, argc=0, argv=0x0, scope=CALL_FCALL, self=6) at vm_eval.c:235
#5 0x08148e6c in rb_call (recv=0, mid=792, argc=0, argv=0x0, scope=CALL_FCALL) at vm_eval.c:438
#6 0x08148fb8 in rb_funcall (recv=0, mid=792, n=0) at vm_eval.c:637
#7 0x0808c997 in rb_obj_inspect (obj=0) at object.c:442
#8 0x08144949 in call_cfunc (func=0x808c83d <rb_obj_inspect>, recv=0, len=0, argc=0, argv=0x0) at vm_insnhelper.c:319
#9 0x08147e8a in vm_call0 (th=0x83da590, recv=0, id=800, argc=0, argv=0x0, me=0x8410700) at vm_eval.c:79
#10 0x08148f19 in rb_call0 (recv=0, mid=800, argc=0, argv=0x0, scope=CALL_FCALL, self=6) at vm_eval.c:235
#11 0x08148e6c in rb_call (recv=0, mid=800, argc=0, argv=0x0, scope=CALL_FCALL) at vm_eval.c:438
#12 0x08148fb8 in rb_funcall (recv=0, mid=800, n=0) at vm_eval.c:637
#13 0x0808c5cf in rb_inspect (obj=0) at object.c:356
#14 0x0807811d in rb_p (obj=0) at io.c:6196
#15 0x08078279 in rb_f_p (argc=1, argv=0xb7282028, self=138456320) at io.c:6234
#16 0x08144936 in call_cfunc (func=0x8078245 <rb_f_p>, recv=138456320, len=-1, argc=1, argv=0xb7282028) at vm_insnhelper.c:316
#17 0x08144821 in vm_call_cfunc (th=0x83da590, reg_cfp=0xb7301f84, num=1, recv=138456320, blockptr=0x0, me=0x84461f0) at vm_insnhelper.c:403
#18 0x08143f49 in vm_call_method (th=0x83da590, cfp=0xb7301f84, num=1, blockptr=0x0, flag=8, id=6160, me=0x84461f0, recv=138456320) at vm_insnhelper.c:525
#19 0x0814122d in vm_exec_core (th=0x83da590, initial=0) at insns.def:1006
#20 0x0814d1f4 in vm_exec (th=0x83da590) at vm.c:1142
#21 0x0814db49 in rb_iseq_eval_main (iseqval=138364160) at vm.c:1383
#22 0x0805c74d in ruby_exec_internal (n=0x83f4500) at eval.c:214
#23 0x0805c858 in ruby_exec_node (n=0x83f4500) at eval.c:261
#24 0x0805c82c in ruby_run_node (n=0x83f4500) at eval.c:254
#25 0x0805b190 in main (argc=2, argv=0xbfffa164) at main.c:35
=end

[nagachika (Tomoyuki Chikanaga)]

=begin
残念ながら signal_buff を increment しているところを rb_disable_interrupt()/rb_enable_interrupt() でくくってみた実行体でも再現しました。
ただ今回は signal_buff.size = -1 ではなくて 1 で逆に余分に increment されたようです。

(gdb) p signal_buff
$1 = {cnt = {0 <repeats 65 times>}, size = 1}

=end

[ko1 (Koichi Sasada)]

=begin
(2010/11/05 12:49), Tomoyuki Chikanaga wrote:

チケット #4027 が更新されました。 (by Tomoyuki Chikanaga)

残念ながら signal_buff を increment しているところを rb_disable_interrupt()/rb_enable_interrupt() でくくってみた実行体でも再現しました。
ただ今回は signal_buff.size = -1 ではなくて 1 で逆に余分に increment されたようです。

(gdb) p signal_buff
$1 = {cnt = {0 <repeats 65 times>}, size = 1}

　ちょっと、状況を見ないで返信しますが、シグナルハンドラ側で何かする必要
は無くて、rb_get_next_signal() 側で rb_disable_interrupt する必要があり
ます。... が、もうなってますね。なぜ、こういう事象が起こるんだろう。

　というか、rb_get_next_signal() で rb_enable_interrpt() して、シグナル
マスクを全部外しているのは、とてもまずいような。というか、メインスレッド
のシグナルマスクが外れているのはこれが理由か...？

--
// SASADA Koichi at atdot dot net
=end

[ko1 (Koichi Sasada)]

=begin
(2010/11/05 12:49), Tomoyuki Chikanaga wrote:

チケット #4027 が更新されました。 (by Tomoyuki Chikanaga)

残念ながら signal_buff を increment しているところを rb_disable_interrupt()/rb_enable_interrupt() でくくってみた実行体でも再現しました。
ただ今回は signal_buff.size = -1 ではなくて 1 で逆に余分に increment されたようです。

(gdb) p signal_buff
$1 = {cnt = {0 <repeats 65 times>}, size = 1}

　ちょっと、状況を見ないで返信しますが、シグナルハンドラ側で何かする必要
は無くて、rb_get_next_signal() 側で rb_disable_interrupt する必要があり
ます。... が、もうなってますね。なぜ、こういう事象が起こるんだろう。

　というか、rb_get_next_signal() で rb_enable_interrpt() して、シグナル
マスクを全部外しているのは、とてもまずいような。というか、メインスレッド
のシグナルマスクが外れているのはこれが理由か...？

--
// SASADA Koichi at atdot dot net

=end

[nagachika (Tomoyuki Chikanaga)]

=begin

というか、rb_get_next_signal() で rb_enable_interrpt() して、シグナル
マスクを全部外しているのは、とてもまずいような。というか、メインスレッド
のシグナルマスクが外れているのはこれが理由か...？
たしかに rb_enable_interrupt() では問答無用で全てのシグナルマスクを外していますね。
直前のものに復旧したほうがいいでしょうか。
また rb_disable_interrupt() では SIGSEGV と SIGVTALRM はマスクしていないですが、ブロックするような処理をしているわけでもないので SIGVTALRM はマスクしていいのではないでしょうか。

今は問題の環境を触れないので、月曜日になったらこのあたり変更して再度やってみます。

=end

[nagachika (Tomoyuki Chikanaga)]

• File sigmask.patch sigmask.patch added

=begin
元々の signal_buff の数が合わなくないのはまだ原因がわかりませんが、
シグナルマスクの処理について調べていて間違っていそうなところをみつけました。

まずささださんが指摘されていた rb_get_next_signal() で rb_enable_interrupt() でシグナルマスクを
外している点ですが、rb_get_next_signal() はタイマースレッドからのみ呼ばれるのでこれは問題なさそうです。

しかしメインスレッドその他の Thread に対応するスレッドのシグナルマスクは SIGSEGV と SIGVTALRM のみ
外されているはずなのに、全て外されていました。
このため sighandler() がタイマースレッドでなくメインスレッドで実行されています。
これは以下のような流れでおきています。

• init_sigchld で初期状態(空マスク)の sigmask が trap_last_sigmask に保存される
• タイマースレッドの起動(rb_thread_create_timer_thread)でメインスレッドはマスクがセットされる
• その後ファイルロード中に例外が生成された時に rb_trap_restore_mask() が呼ばれて trap_last_sigmask に
  保存された空マスクがセットされるためシグナルマスクが外れる

また、Signal.trap でハンドラをセットした時に、そのシグナルのシグナルマスクが外されています。
sigaction によるシグナルハンドラの実行はタイマースレッドにまかせているはずなのでこれは不要だと思います。
また例外発生時に rb_trap_restore_mask を読んでいるのも、trap() で例外が発生しても trap_ensure() で
シグナルマスクを戻す処理は行なわれているので不要なような気がします。元々どういう理由で呼ばれているのか
わからなかったので自信ないですけど。

というわけで添付のようなパッチを作成してみました。

ところがこれを当てると make test-all で Failure が 2つ増えます。
いずれも ruby のプロセスをシグナルで止めた時に終了ステータスが $?.signaled? == true でなく
$?.exited? == true になるためです。
これはどう直せばいいのかわかりません。

1. Failure:
   test_should_propagate_signaled(TestBeginEndBlock) [/Users/nagachika/opt/ruby-trunk/src/ruby-trunk/test/ruby/test_beginendblock.rb:108]:
   Expected 0 to be nil.

2. Failure:
   test_status_kill(TestProcess) [/Users/nagachika/opt/ruby-trunk/src/ruby-trunk/test/ruby/test_process.rb:1073]:
   [s.exited?, s.signaled?, s.stopped?].
   <[false, true, false]> expected but was
   <[true, false, false]>.

また、sighandler() がメインスレッドから呼ばれるのは Process.spawn を実行するとまだおきてしまいます。
process.c の before_fork/after_fork で fork の時に一時的にタイマースレッドを止めてシグナルマスクを外すためです。
こちらもどうしていいものかわからないです。
fork してそのまま動き続けるようなものはどうしようもないような気がしますが、spawn するものは
fork 後に sigprogmask で外すようにするなどでなんとかならないものでしょうか。
あーでもタイマースレッドの再起動で結局一時的に外してしまいますね……

なお、このせいで sighandler にメインスレッドとタイマースレッドで同時に実行してしまって
signal_buff のカウンタがおかしくなったのかも、とも思ったのですが、ATOMIC_INC 部分を disassemble してみると
それぞれ incl の1命令で実行されているので、仮に並列に実行されても加算もれすることはなさそうです。
プロセッサによってはダメだったりするんでしょうか。

=end

[nagachika (Tomoyuki Chikanaga)]

=begin

なお、このせいで sighandler にメインスレッドとタイマースレッドで同時に実行してしまって
signal_buff のカウンタがおかしくなったのかも、とも思ったのですが、ATOMIC_INC 部分を disassemble してみると
それぞれ incl の1命令で実行されているので、仮に並列に実行されても加算もれすることはなさそうです。
これは勘違いしていて、lock prefix がついていないので複数コアで並列に実行されると問題かもしれません。
そして r29589 で gcc-4 の builtin function を使う修正が入っていたのを思い出したので
CC=gcc-4.4 にしてコンパイルしなおしたら ATOMIC_INC は

80e1b93: f0 80 00 01 lock addb $0x1,(%eax)
80e1b97: f0 80 05 81 ef 1f 08 lock addb $0x1,0x81fef81

のように lock prefix 付きになったので、これで大丈夫だと思います。
=end

[ko1 (Koichi Sasada)]

=begin
　ささだです。

　シグナルに関しての調査、ありがとうございます。近いうちに反映させます。

(2010/11/11 10:47), Tomoyuki Chikanaga wrote:

これは勘違いしていて、lock prefix がついていないので複数コアで並列に実行されると問題かもしれません。
そして r29589 で gcc-4 の builtin function を使う修正が入っていたのを思い出したので
CC=gcc-4.4 にしてコンパイルしなおしたら ATOMIC_INC は

80e1b93: f0 80 00 01 lock addb $0x1,(%eax)
80e1b97: f0 80 05 81 ef 1f 08 lock addb $0x1,0x81fef81

　ちなみに、以前はどのコンパイラを利用されていたでしょうか。

--
// SASADA Koichi at atdot dot net

=end

[nagachika (Tomoyuki Chikanaga)]

=begin

ちなみに、以前はどのコンパイラを利用されていたでしょうか。
gcc 3.4.6 でした。 gcc -v を貼ります。

$ gcc -v
/usr/local/lib/gcc/i686-pc-linux-gnu/3.4.6/specs から spec を読み込み中
コンフィグオプション: ./configure --program-suffix=-3.4.6 --disable-shared --disable-ada --disable-java --disable-objc : (reconfigured) ./configure --program-suffix=-3.4.6 --disable-shared --enable-languages=c,c++,fortran : (reconfigured) ./configure --program-suffix=-3.4.6 --disable-shared --enable-languages=c,c++,fortran : (reconfigured) ./configure --program-suffix=-3.4.6 --disable-shared --enable-languages=c,c++,f77
スレッドモデル: posix
gcc version 3.4.6

=end

[nagachika (Tomoyuki Chikanaga)]

• Status changed from Open to Rejected

シグナルマスクに関しては #4765 に分離されました。
signal_buff の競合状態は、新しめの gcc や Windows だと ATOMIC_INC/ATOMIC_DEC がロックつきになることと、
#4765 でシグナルハンドラの実行がタイマースレッドに限定されれば発生しなくなるはずなのでこちらは閉じます。