Bug #11265
closed
deadlock on Solaris 10 since r50900
Added by ngoto (Naohisa Goto) over 9 years ago. Updated over 9 years ago.
Description
Solaris10にて、r50900 以降、
TestParallel::TestParallel#test_jobs_status
TestParallel::TestParallel#test_separate
のいずれか、または両方で、テストが停止状態となり次に進まなくなります。
スレッドのデッドロックが発生しているような感じです。
ところで、こういう場合の上手いデバッグ方法って何があるでしょうか？
Files
| test-solaris-fork-deadlock.c (2.9 KB) test-solaris-fork-deadlock.c | ngoto (Naohisa Goto), 06/25/2015 07:45 AM |
Updated by ngoto (Naohisa Goto) over 9 years ago
- Related to Bug #11237: サブスレッドがすべて終了するとメインスレッドが割り込まれる。 added
Updated by ngoto (Naohisa Goto) over 9 years ago
テストがストップしている場所は、
test/runner.rb の29行め
assert_empty(Process.waitall)
の行であることまではわかりました。
test/testunit/test_parallel.rb から spawn で新しく ruby を起動して test/testunit/tests_for_parallel/runner.rb を実行しています。
そして、そこから test/lib/test/unit.rb の IO.popen を使ってさらに新しく ruby を呼び出した時に、呼び出し元か呼び出し先のどちらかの ruby でデッドロックが発生しているようですが、どのrubyでどのように発生しているのかは突き止めることができませんでした。
Updated by kosaki (Motohiro KOSAKI) over 9 years ago
2015-06-16 12:37 GMT-04:00 ngotogenome@gmail.com:
Issue #11265 has been updated by Naohisa Goto.
テストがストップしている場所は、
test/runner.rb の29行め
assert_empty(Process.waitall)
の行であることまではわかりました。test/testunit/test_parallel.rb から spawn で新しく ruby を起動して test/testunit/tests_for_parallel/runner.rb を実行しています。
そして、そこから test/lib/test/unit.rb の IO.popen を使ってさらに新しく ruby を呼び出した時に、呼び出し元か呼び出し先のどちらかの ruby でデッドロックが発生しているようですが、どのrubyでどのように発生しているのかは突き止めることができませんでした。
r50900 は私なんだけど、ごめんなさい、お手上げ。
そういう副作用がでそうなパッチに見えません。
Updated by ngoto (Naohisa Goto) over 9 years ago
test/lib/test/unit.rb の _run_parallel メソッド内の 408-410行目にて、以下のタイミングで発生していることはわかりました。
- 408行目では start_watchdog を呼ぶ。
- start_watchdog メソッド内では、新スレッドを作成してすぐにリターンする。
- start_watchdog で作成したスレッド内では、Process.wait2 を呼んでいる。しかし、まだ子プロセスを作成する前なので、Errno::ECHILD 例外が発生し、せっかく作った新スレッドはあえなく終了する。（つまり、名前に反して watchdog を行うことは無い。これはバグだと思う。）
- 409行めは空行。410行目にて @options[:parallel].times {launch_worker} が実行される。 launch_worker は内部ですぐに Worker.launch を呼び、その中で IO.popen にて別プロセスのRubyを起動する。
この上記3の Process.wait2 に失敗してスレッドが終了するのと、上記4のIO.popenの実行がだいたい同時に発生したら、デッドロックが発生するようです。
ただし、上記3のうち、Process.wait2 と、スレッド終了のどちらが要因なのかは、同定できませんでした。
Updated by kosaki (Motohiro KOSAKI) over 9 years ago
2015-06-17 11:40 GMT-04:00 ngotogenome@gmail.com:
Issue #11265 has been updated by Naohisa Goto.
test/lib/test/unit.rb の _run_parallel メソッド内の 408-410行目にて、以下のタイミングで発生していることはわかりました。
- 408行目では start_watchdog を呼ぶ。
- start_watchdog メソッド内では、新スレッドを作成してすぐにリターンする。
- start_watchdog で作成したスレッド内では、Process.wait2 を呼んでいる。しかし、まだ子プロセスを作成する前なので、Errno::ECHILD 例外が発生し、せっかく作った新スレッドはあえなく終了する。（つまり、名前に反して watchdog を行うことは無い。これはバグだと思う。）
- 409行めは空行。410行目にて @options[:parallel].times {launch_worker} が実行される。 launch_worker は内部ですぐに Worker.launch を呼び、その中で IO.popen にて別プロセスのRubyを起動する。
この上記3の Process.wait2 に失敗してスレッドが終了するのと、上記4のIO.popenの実行がだいたい同時に発生したら、デッドロックが発生するようです。
ただし、上記3のうち、Process.wait2 と、スレッド終了のどちらが要因なのかは、同定できませんでした。
デッドロックしたときのCスタックトレースはとれますか？
特に IO.popen のほうがどこで刺さっているのか気になります。
Updated by ngoto (Naohisa Goto) over 9 years ago
IO.popen内で、retry_fork_async_signal_safeから呼んでいるvforkから帰ってこないようです。
なお、スタックトレースを取るためにデバッグ付き最適化無しでコンパイルしたら、再現確率が20-30回に1回と大幅に下がりました。タイミング依存が激しいようです。
IO.popen呼び出し側。vfork内で止まっているようです。
$ /opt/solarisstudio12.3/bin/dbx - 1582
For information about new features see `help changes'
To remove this message, put `dbxenv suppress_startup_message 7.9' in your .dbxrc
Reading ruby
Reading ld.so.1
Reading libpthread.so.1
Reading librt.so.1
Reading libgmp.so.10.1.3
Reading libsocket.so.1
Reading libdl.so.1
Reading libcrypt_d.so.1
Reading libm.so.2
Reading libc.so.1
Reading libaio.so.1
Reading libmd.so.1
Reading libnsl.so.1
Reading libgen.so.1
Reading libc_psr.so.1
Reading encdb.so
Reading libmp.so.2
Reading libscf.so.1
Reading libdoor.so.1
Reading libuutil.so.1
Reading transdb.so
Reading thread.so
Attached to process 1582 with 3 LWPs
t@1 (l@1) stopped in _vfork at 0x7fffffff7e8dd440
0x7fffffff7e8dd440: _vfork+0x0024: bcc,a,pt %icc,_vfork+0x4c ! 0x7fffffff7e8dd468
Current function is retry_fork_async_signal_safe
3529 pid = vfork();
(dbx) lwps
>l@1 running in _vfork()
l@2 LWP suspended in __pollsys()
l@5 LWP suspended in elf_find_sym()
(dbx) where
current thread: t@1
[1] _vfork(0x630, 0x0, 0xffff, 0x100577aa8, 0x50, 0x15), at 0x7fffffff7e8dd440
=>[2] retry_fork_async_signal_safe(status = 0xffffffff7fffc594, ep = 0xffffffff7fffc3fc, chfunc = 0x1001518c0 = &`ruby`io.c`popen_exec(void *pp, char *errmsg, size_t errmsg_len), charg = 0xffffffff7fffc518, errmsg = 0xffffffff7fffc544 "", errmsg_buflen = 80U), line 3529 in "process.c"
[3] rb_fork_async_signal_safe(status = 0xffffffff7fffc594, chfunc = 0x1001518c0 = &`ruby`io.c`popen_exec(void *pp, char *errmsg, size_t errmsg_len), charg = 0xffffffff7fffc518, fds = 4301789120U, errmsg = 0xffffffff7fffc544 "", errmsg_buflen = 80U), line 3571 in "process.c"
[4] pipe_open(execarg_obj = 4301789560U, modestr = 0x10044db18 "r+", fmode = 7, convconfig = 0xffffffff7fffc6e8), line 6006 in "io.c"
[5] rb_io_s_popen(argc = 2, argv = 0x10057ca28, klass = 4302377040U), line 6299 in "io.c"
[6] call_cfunc_m1(func = 0x1001523c0 = &`ruby`io.c`rb_io_s_popen(int argc, VALUE *argv, VALUE klass), recv = 4302377040U, argc = 2, argv = 0x10057ca28), line 1421 in "vm_insnhelper.c"
[7] vm_call_cfunc_with_frame(th = 0x100578240, reg_cfp = 0x10067c208, ci = 0x100868f88), line 1595 in "vm_insnhelper.c"
[8] vm_call_cfunc(th = 0x100578240, reg_cfp = 0x10067c208, ci = 0x100868f88), line 1690 in "vm_insnhelper.c"
[9] vm_call_method(th = 0x100578240, cfp = 0x10067c208, ci = 0x100868f88), line 1921 in "vm_insnhelper.c"
[10] vm_call_general(th = 0x100578240, reg_cfp = 0x10067c208, ci = 0x100868f88), line 2085 in "vm_insnhelper.c"
[11] vm_exec_core(th = 0x100578240, initial = 0), line 977 in "insns.def"
[12] vm_exec(th = 0x100578240), line 1486 in "vm.c"
[13] invoke_block_from_c(th = 0x100578240, block = 0x10067c348, self = 4305731800U, argc = 1, argv = 0xffffffff7fffd6d8, blockptr = (nil), cref = (nil), defined_class = 4305737000U, splattable = 1), line 857 in "vm.c"
[14] vm_yield(th = 0x100578240, argc = 1, argv = 0xffffffff7fffd6d8), line 898 in "vm.c"
[15] rb_yield_0(argc = 1, argv = 0xffffffff7fffd6d8), line 994 in "vm_eval.c"
[16] rb_yield(val = 1U), line 1004 in "vm_eval.c"
[17] int_dotimes(num = 3U), line 3951 in "numeric.c"
[18] call_cfunc_0(func = 0x1001a1440 = &`ruby`numeric.c`int_dotimes(VALUE num), recv = 3U, argc = 0, argv = 0x10057c9a8), line 1427 in "vm_insnhelper.c"
[19] vm_call_cfunc_with_frame(th = 0x100578240, reg_cfp = 0x10067c328, ci = 0x10089c378), line 1595 in "vm_insnhelper.c"
[20] vm_call_cfunc(th = 0x100578240, reg_cfp = 0x10067c328, ci = 0x10089c378), line 1690 in "vm_insnhelper.c"
[21] vm_call_method(th = 0x100578240, cfp = 0x10067c328, ci = 0x10089c378), line 1921 in "vm_insnhelper.c"
[22] vm_call_general(th = 0x100578240, reg_cfp = 0x10067c328, ci = 0x10089c378), line 2085 in "vm_insnhelper.c"
[23] vm_exec_core(th = 0x100578240, initial = 0), line 947 in "insns.def"
[24] vm_exec(th = 0x100578240), line 1486 in "vm.c"
[25] invoke_block_from_c(th = 0x100578240, block = 0x10067c540, self = 4305731800U, argc = 1, argv = 0xffffffff7fffe718, blockptr = (nil), cref = (nil), defined_class = 4305636240U, splattable = 1), line 857 in "vm.c"
[26] vm_yield(th = 0x100578240, argc = 1, argv = 0xffffffff7fffe718), line 898 in "vm.c"
[27] rb_yield_0(argc = 1, argv = 0xffffffff7fffe718), line 994 in "vm_eval.c"
[28] rb_yield(val = 4305221440U), line 1004 in "vm_eval.c"
[29] rb_ary_each(array = 4305221080U), line 1821 in "array.c"
[30] call_cfunc_0(func = 0x100042900 = &rb_ary_each(VALUE array), recv = 4305221080U, argc = 0, argv = 0x10057c858), line 1427 in "vm_insnhelper.c"
[31] vm_call_cfunc_with_frame(th = 0x100578240, reg_cfp = 0x10067c520, ci = 0x10092d448), line 1595 in "vm_insnhelper.c"
[32] vm_call_cfunc(th = 0x100578240, reg_cfp = 0x10067c520, ci = 0x10092d448), line 1690 in "vm_insnhelper.c"
[33] vm_call_method(th = 0x100578240, cfp = 0x10067c520, ci = 0x10092d448), line 1921 in "vm_insnhelper.c"
[34] vm_call_general(th = 0x100578240, reg_cfp = 0x10067c520, ci = 0x10092d448), line 2085 in "vm_insnhelper.c"
[35] vm_exec_core(th = 0x100578240, initial = 0), line 947 in "insns.def"
[36] vm_exec(th = 0x100578240), line 1486 in "vm.c"
[37] rb_iseq_eval_main(iseqval = 4302120600U), line 1733 in "vm.c"
[38] ruby_exec_internal(n = 0x1006d2698), line 257 in "eval.c"
[39] ruby_exec_node(n = 0x1006d2698), line 322 in "eval.c"
[40] ruby_run_node(n = 0x1006d2698), line 314 in "eval.c"
[41] main(argc = 7, argv = 0xffffffff7ffff848), line 36 in "main.c"
(dbx) list
3529 pid = vfork();
3530 else
3531 pid = fork();
3532 #else
3533 pid = fork();
3534 #endif
3535 if (pid == 0) {/* fork succeed, child process */
3536 int ret;
3537 close(ep[0]);
3538 ret = disable_child_handler_fork_child(&old, errmsg, errmsg_buflen); /* async-signal-safe */
(dbx) exit
detaching from process 1582
IO.popenから起動した新プロセス側。こちらは fcntl内で止まっている？
$ /opt/solarisstudio12.3/bin/dbx - 1584
For information about new features see `help changes'
To remove this message, put `dbxenv suppress_startup_message 7.9' in your .dbxrc
Reading ruby
Reading ld.so.1
Reading libpthread.so.1
Reading librt.so.1
Reading libgmp.so.10.1.3
Reading libsocket.so.1
Reading libdl.so.1
Reading libcrypt_d.so.1
Reading libm.so.2
Reading libc.so.1
Reading libaio.so.1
Reading libmd.so.1
Reading libnsl.so.1
Reading libgen.so.1
Reading libc_psr.so.1
Reading encdb.so
Reading libmp.so.2
Reading libscf.so.1
Reading libdoor.so.1
Reading libuutil.so.1
Reading transdb.so
Reading thread.so
Attached to process 1584
t@1 (l@1) stopped in ___lwp_mutex_timedlock at 0x7fffffff7fe33f24
0x7fffffff7fe33f24: ___lwp_mutex_timedlock+0x0008: ta %icc,0x0000000000000040
Current function is rb_close_before_exec
5870 ret = fcntl(fd, F_GETFD); /* async-signal-safe */
(dbx) lwps
>l@1 running in ___lwp_mutex_timedlock()
(dbx) where
current thread: t@1
[1] ___lwp_mutex_timedlock(0x7fffffff7ff416d8, 0x0, 0x0, 0x7fffffff7e8d6e6c, 0x1, 0x1), at 0x7fffffff7fe33f24
[2] enter(0x0, 0x7fffffff7ff3c210, 0x1000, 0x7fffffff7e82f294, 0x7fffffff7ff3cdf8, 0x7fffffff7ff3c638), at 0x7fffffff7fe1bf20
[3] elf_bndr(0x7fffffff7fd00848, 0x1580, 0x1001eb110, 0x14, 0x0, 0x7fffffff7ff3cdf8), at 0x7fffffff7fe28168
[4] elf_rtbndr(0x560000, 0x100567438, 0xfffffffffffffff7, 0x1001eb110, 0x1001f1080, 0xfffffffffffffff7), at 0x7fffffff7fe08394
=>[5] rb_close_before_exec(lowfd = 3, maxhint = 10, noclose_fds = 4301789120U), line 5870 in "io.c"
[6] proc_exec_cmd(prog = 0x100868980 "/XXXXX-trunk/bin/ruby", argv_str = 4301789280U, envp_str = 0), line 1269 in "process.c"
[7] rb_exec_async_signal_safe(eargp = 0x1009d3ea0, errmsg = 0xffffffff7fffc544 "", errmsg_buflen = 80U), line 3068 in "process.c"
[8] popen_exec(pp = 0xffffffff7fffc518, errmsg = 0xffffffff7fffc544 "", errmsg_len = 80U), line 5888 in "io.c"
[9] retry_fork_async_signal_safe(status = 0xffffffff7fffc594, ep = 0xffffffff7fffc3fc, chfunc = 0x1001518c0 = &`ruby`io.c`popen_exec(void *pp, char *errmsg, size_t errmsg_len), charg = 0xffffffff7fffc518, errmsg = 0xffffffff7fffc544 "", errmsg_buflen = 80U), line 3540 in "process.c"
[10] rb_fork_async_signal_safe(status = 0xffffffff7fffc594, chfunc = 0x1001518c0 = &`ruby`io.c`popen_exec(void *pp, char *errmsg, size_t errmsg_len), charg = 0xffffffff7fffc518, fds = 4301789120U, errmsg = 0xffffffff7fffc544 "", errmsg_buflen = 80U), line 3571 in "process.c"
[11] pipe_open(execarg_obj = 4301789560U, modestr = 0x10044db18 "r+", fmode = 7, convconfig = 0xffffffff7fffc6e8), line 6006 in "io.c"
[12] rb_io_s_popen(argc = 2, argv = 0x10057ca28, klass = 4302377040U), line 6299 in "io.c"
[13] call_cfunc_m1(func = 0x1001523c0 = &`ruby`io.c`rb_io_s_popen(int argc, VALUE *argv, VALUE klass), recv = 4302377040U, argc = 2, argv = 0x10057ca28), line 1421 in "vm_insnhelper.c"
[14] vm_call_cfunc_with_frame(th = 0x100578240, reg_cfp = 0x10067c208, ci = 0x100868f88), line 1595 in "vm_insnhelper.c"
[15] vm_call_cfunc(th = 0x100578240, reg_cfp = 0x10067c208, ci = 0x100868f88), line 1690 in "vm_insnhelper.c"
[16] vm_call_method(th = 0x100578240, cfp = 0x10067c208, ci = 0x100868f88), line 1921 in "vm_insnhelper.c"
[17] vm_call_general(th = 0x100578240, reg_cfp = 0x10067c208, ci = 0x100868f88), line 2085 in "vm_insnhelper.c"
[18] vm_exec_core(th = 0x100578240, initial = 0), line 977 in "insns.def"
[19] vm_exec(th = 0x100578240), line 1486 in "vm.c"
[20] invoke_block_from_c(th = 0x100578240, block = 0x10067c348, self = 4305731800U, argc = 1, argv = 0xffffffff7fffd6d8, blockptr = (nil), cref = (nil), defined_class = 4305737000U, splattable = 1), line 857 in "vm.c"
[21] vm_yield(th = 0x100578240, argc = 1, argv = 0xffffffff7fffd6d8), line 898 in "vm.c"
[22] rb_yield_0(argc = 1, argv = 0xffffffff7fffd6d8), line 994 in "vm_eval.c"
[23] rb_yield(val = 1U), line 1004 in "vm_eval.c"
[24] int_dotimes(num = 3U), line 3951 in "numeric.c"
[25] call_cfunc_0(func = 0x1001a1440 = &`ruby`numeric.c`int_dotimes(VALUE num), recv = 3U, argc = 0, argv = 0x10057c9a8), line 1427 in "vm_insnhelper.c"
[26] vm_call_cfunc_with_frame(th = 0x100578240, reg_cfp = 0x10067c328, ci = 0x10089c378), line 1595 in "vm_insnhelper.c"
[27] vm_call_cfunc(th = 0x100578240, reg_cfp = 0x10067c328, ci = 0x10089c378), line 1690 in "vm_insnhelper.c"
[28] vm_call_method(th = 0x100578240, cfp = 0x10067c328, ci = 0x10089c378), line 1921 in "vm_insnhelper.c"
[29] vm_call_general(th = 0x100578240, reg_cfp = 0x10067c328, ci = 0x10089c378), line 2085 in "vm_insnhelper.c"
[30] vm_exec_core(th = 0x100578240, initial = 0), line 947 in "insns.def"
[31] vm_exec(th = 0x100578240), line 1486 in "vm.c"
[32] invoke_block_from_c(th = 0x100578240, block = 0x10067c540, self = 4305731800U, argc = 1, argv = 0xffffffff7fffe718, blockptr = (nil), cref = (nil), defined_class = 4305636240U, splattable = 1), line 857 in "vm.c"
[33] vm_yield(th = 0x100578240, argc = 1, argv = 0xffffffff7fffe718), line 898 in "vm.c"
[34] rb_yield_0(argc = 1, argv = 0xffffffff7fffe718), line 994 in "vm_eval.c"
[35] rb_yield(val = 4305221440U), line 1004 in "vm_eval.c"
[36] rb_ary_each(array = 4305221080U), line 1821 in "array.c"
[37] call_cfunc_0(func = 0x100042900 = &rb_ary_each(VALUE array), recv = 4305221080U, argc = 0, argv = 0x10057c858), line 1427 in "vm_insnhelper.c"
[38] vm_call_cfunc_with_frame(th = 0x100578240, reg_cfp = 0x10067c520, ci = 0x10092d448), line 1595 in "vm_insnhelper.c"
[39] vm_call_cfunc(th = 0x100578240, reg_cfp = 0x10067c520, ci = 0x10092d448), line 1690 in "vm_insnhelper.c"
[40] vm_call_method(th = 0x100578240, cfp = 0x10067c520, ci = 0x10092d448), line 1921 in "vm_insnhelper.c"
[41] vm_call_general(th = 0x100578240, reg_cfp = 0x10067c520, ci = 0x10092d448), line 2085 in "vm_insnhelper.c"
[42] vm_exec_core(th = 0x100578240, initial = 0), line 947 in "insns.def"
[43] vm_exec(th = 0x100578240), line 1486 in "vm.c"
[44] rb_iseq_eval_main(iseqval = 4302120600U), line 1733 in "vm.c"
[45] ruby_exec_internal(n = 0x1006d2698), line 257 in "eval.c"
[46] ruby_exec_node(n = 0x1006d2698), line 322 in "eval.c"
[47] ruby_run_node(n = 0x1006d2698), line 314 in "eval.c"
[48] main(argc = 7, argv = 0xffffffff7ffff848), line 36 in "main.c"
(dbx) list
5870 ret = fcntl(fd, F_GETFD); /* async-signal-safe */
5871 if (ret != -1 && !(ret & FD_CLOEXEC)) {
5872 fcntl(fd, F_SETFD, ret|FD_CLOEXEC); /* async-signal-safe */
5873 }
5874 # define CONTIGUOUS_CLOSED_FDS 20
5875 if (ret != -1) {
5876 if (max < fd + CONTIGUOUS_CLOSED_FDS)
5877 max = fd + CONTIGUOUS_CLOSED_FDS;
5878 }
5879 }
(dbx)
(dbx) print fd
fd = 33
(dbx) print max
max = 32
(dbx) print lowfd
lowfd = 3
5870: ret = fcntl(fd, F_GETFD);
は、
5866: for (fd = lowfd; fd <= max; fd++) { ... }
の中でループしているから、fd が max を越えるはずはないはずなのに、
max = 32 にもかかわらず fd = 33 で fcntl(fd, F_GETFD) が呼ばれている？
Updated by ngoto (Naohisa Goto) over 9 years ago
vforkは "The parent process is suspended while the child is using its resources." （Solaris 10 の man vfork(2) より引用） なので、vfork で作成された子プロセス側の execv が完了する前に止まっているのが直接の原因のようです。
そして、子プロセス側の frame 6 で execv を呼び出しているはずなのに、なぜそこから frame 5 では rb_close_before_exec が呼び出されているのかは、私は理解できていません。
atfork 的な処理がどこかで登録されているのでしょうか？
下記は子プロセス側のdbxの抜粋です。
(dbx) frame 6
Current function is proc_exec_cmd
1269 execv(prog, argv); /* async-signal-safe */
(dbx) print prog
prog = 0x100868980 "/XXXXX-trunk/bin/ruby"
(dbx) print argv[0]
argv[0] = 0x10083ca40 "/XXXXX-trunk/bin/ruby"
(dbx) print argv[1]
argv[1] = 0x10083ca8a "/YYYYY/test/lib/test/unit/parallel.rb"
(dbx) print argv[2]
argv[2] = 0x10083cade "--ruby"
(dbx) print argv[3]
argv[3] = 0x10083cae5 "/XXXXX-trunk/bin/ruby"
(dbx) print argv[4]
argv[4] = 0x10083cb2f "-j"
(dbx) print argv[5]
argv[5] = 0x10083cb32 "t1"
(dbx) print argv[6]
argv[6] = 0x10083cb35 "--jobs-status"
(dbx) print argv[7]
argv[7] = (nil)
(dbx) frame 5
Current function is rb_close_before_exec
5870 ret = fcntl(fd, F_GETFD); /* async-signal-safe */
(dbx)
Updated by akr (Akira Tanaka) over 9 years ago
Solaris で vfork で deadlock というと、
https://web.archive.org/web/20120205202630/http://developers.sun.com/solaris/articles/subprocess/subprocess.html
に書いてあった、dynamic linker が、という話を思い出しますが、関係あるかなぁ。
Updated by ngoto (Naohisa Goto) over 9 years ago
に書いてあった、dynamic linker が、という話を思い出しますが、関係あるかなぁ。
関係ある気がしてきました。
popen呼び出し元のほうのスレッドは3つありますが、l@5 が dlsym などを呼んでいます。
以下は親のほうのdbxの抜粋です。
Attached to process 1582 with 3 LWPs
t@1 (l@1) stopped in _vfork at 0x7fffffff7e8dd440
0x7fffffff7e8dd440: _vfork+0x0024: bcc,a,pt %icc,_vfork+0x4c ! 0x7fffffff7e8dd468
Current function is retry_fork_async_signal_safe
3529 pid = vfork();
(dbx) lwps
>l@1 running in _vfork()
l@2 LWP suspended in __pollsys()
l@5 LWP suspended in elf_find_sym()
(dbx) lwp l@5
t@5 (l@5) stopped in elf_find_sym at 0x7fffffff7fe0ebc4
0x7fffffff7fe0ebc4: elf_find_sym+0x0100: bne,pn %icc,elf_find_sym+0x118 ! 0x7fffffff7fe0ebdc
(dbx) where
=>[1] elf_find_sym(0x7fffffff7d0ff9e0, 0x186338, 0x7fffffff7d0ffbe4, 0x7fffffff7de00030, 0x1000, 0x6c384a4), at 0x7fffffff7fe0ebc4
[2] core_lookup_sym(0x7fffffff7de00030, 0x7fffffff7d0ff9e0, 0x7fffffff7d0ffbe8, 0x7fffffff7d0ffbe4, 0x20, 0x7fffffff7d0ffcfc), at 0x7fffffff7fe0c534
[3] _lookup_sym(0x2200, 0x7fffffff7d0ffbe8, 0x7fffffff7d0ffbe4, 0x7fffffff7d0ffcfc, 0x200, 0x7fffffff7fd00848), at 0x7fffffff7fe0c96c
[4] lookup_sym(0x7fffffff7d0ffc00, 0x7fffffff7d0ffbe8, 0x7fffffff7d0ffbe4, 0x7fffffff7d0ffcfc, 0x6c384a4, 0x0), at 0x7fffffff7fe0cc38
[5] dlsym_core(0x200, 0x7fffffff7ff3c198, 0x7fffffff7f801188, 0x7fffffff7d0ffdb8, 0x7fffffff7d0ffcfc, 0x0), at 0x7fffffff7fe1eb68
[6] dlsym_intn(0xfffffffffffffffc, 0x7fffffff7e93c648, 0x7fffffff7f801188, 0x7fffffff7d0ffdb8, 0x0, 0x11e0f0), at 0x7fffffff7fe1edfc
[7] dlsym(0xfffffffffffffffc, 0x7fffffff7e93c648, 0x0, 0xffff, 0xffbffeff, 0x1), at 0x7fffffff7fe1ef6c
[8] _t_cancel(0x7fffffff7d0ff751, 0x7fffffff7e8ece0c, 0x0, 0x0, 0x7fffffff7ec01200, 0x7fffffff7ea3e000), at 0x7fffffff7e8dbaf4
[9] _thr_exit_common(0x0, 0x1c00, 0x0, 0x7fffffff7ec01200, 0x1003b8340, 0x7fffffff7ea3e000), at 0x7fffffff7e8d5088
(dbx)
l@5 はスレッド終了時の処理を行なっているようで、おそらく、start_watchdog 内で
Thread.new do
while stat = Process.wait2
にて作成されたスレッドの成れの果てだと思います。
Process.wait2 が中で rb_thread_call_without_gvl を使ってGVLを外しているのも、もしかしたら関係あるかもしれません。
Updated by akr (Akira Tanaka) over 9 years ago
本当に dynamic linker とかで使っている mutex が問題なら、ちょっと対応不能だと思うので、
Solaris 上では vfork はあきらめて fork で済ましておくことになりますかね。
Updated by ngoto (Naohisa Goto) over 9 years ago
process.c の1260行目付近に以下の記述があります。
envp = envp_str ? (char **)RSTRING_PTR(envp_str) : NULL;
if (envp_str)
execve(prog, argv, envp); /* async-signal-safe */
else
execv(prog, argv); /* async-signal-safe */
しかし、Solaris 10 の man exec(2) によると、execve は確かに async-signal-safe ですが、
コメント部分の記述に反して、execv は NOT async-signal-safe です。
そこで、以下のようにして popen を呼ぶ際に環境変数を与えて execve を呼ばせるようにすると、デッドロックは発生しなくなりました。
diff --git a/test/lib/test/unit.rb b/test/lib/test/unit.rb
index 9d9ff4b..6c527a8 100644
--- a/test/lib/test/unit.rb
+++ b/test/lib/test/unit.rb
@@ -148,7 +148,7 @@ module Test
class Worker
def self.launch(ruby,args=[])
- io = IO.popen([*ruby,
+ io = IO.popen({"DUMMY"=>"test"}, [*ruby,
"#{File.dirname(__FILE__)}/unit/parallel.rb",
*args], "rb+")
new(io, io.pid, :waiting)
単にenvpstr作成処理が間に入ったのでタイミングが微妙にずれて掬われただけの可能性も残ってはいますが、仮にそうであったとしても、async-signal-safe であるべき場所でそれが保証されない関数を呼ぶのは、やはり好ましくないと思います。
つまり、横着せずに必ず envp を自前で作成して execve を呼ぶ必要があるということになりますが、
それには、メモリ確保の必要があるので async-signal-safe が不要な場所で予め envpstr を作成した上で渡すことになり、API変更が必要になりそうです。
なお、execv が not async-signal-safe なのは Linux でも同様のようです。
Updated by ngoto (Naohisa Goto) over 9 years ago
訂正です。
なお、execv が not async-signal-safe なのは Linux でも同様のようです。
は、少なくとも最近のLinuxに関しては間違いでした。すみません。
execv は POSIX.1-2008 で async-signal-safe に追加されたため、
それ以前から存在する Solaris 10 が時代に取り残されているだけのようです。
Updated by akr (Akira Tanaka) over 9 years ago
おぉ、調べ直したところ、execv が async-signal-safe な関数としてされたのは SUSv4 からのようです。
http://pubs.opengroup.org/onlinepubs/9699919799/functions/V2_chap02.html
SUSv2, SUSv3 では async-signal-safe な関数のリストには載っていません。
たぶんそのコメントは SUSv4 を見て書いたのだと思います。
それはそれとして、現在の実装が async-signal-safe でないなら利用しないほうがいいのはそうなので、
envp_str を常に生成するようにすればいいんじゃないでしょうか。
たぶん rb_execarg_parent_start1 の中をちょっといじればいいんじゃないかな。
Updated by ngoto (Naohisa Goto) over 9 years ago
- Status changed from Open to Closed
Applied in changeset r50977.
-
process.c (rb_execarg_parent_start1): new macro ALWAYS_NEED_ENVP
to generate envp_str anytime on Solaris 10 (or earlier version
of Solaris) to avoid calling execv() which is async-signal unsafe
on Solaris 10. [Bug #11265] [ruby-dev:49089] -
process.c (exec_with_sh, proc_exec_cmd): On Solaris 10,
because ALWAYS_NEED_ENVP is 1 and envp_str is always generated,
execv() in exec_with_sh() and proc_exec_cmd() are never called.
To guarantee this, execv() is replaced by a macro to print
out error message on Solaris 10. -
process.c (proc_exec_sh): Because proc_exec_sh() may be called
by rb_proc_exec() with envp_str = Qfalse, execl() is replaced
by a macro that calls execle() with "extern char **environ"
traditional global variable on Solaris 10.
TODO: This may be unsafe and sholud be changed
in the future.
Although rb_proc_exec() is not used from inside current version
of ruby, it may be called by third-party extensions.
Updated by ngoto (Naohisa Goto) over 9 years ago
- Status changed from Closed to Assigned
- Assignee set to ngoto (Naohisa Goto)
r50977 で発生率は下がりましたがゼロではないようなので、再オープンしておきます。
Updated by ngoto (Naohisa Goto) over 9 years ago
- Related to Bug #11288: start_watchdog in test/lib/test/unit.rb is meaningless added
Updated by ngoto (Naohisa Goto) over 9 years ago
親プロセス側のスレッド l@5 内で呼ばれている dlsym() で要求しているシンボルは _ex_unwind であるのがわかりました。
（下記のdbxの出力は、上記とは別の実行時になりますが、おおむね同じです。）
t@1 (l@1) stopped in _vfork at 0x7fffffff7e8dd440
0x7fffffff7e8dd440: _vfork+0x0024: bcc,a,pt %icc,_vfork+0x4c ! 0x7fffffff7e8dd468
Current function is retry_fork_async_signal_safe
3529 pid = vfork();
(dbx) lwps
>l@1 running in _vfork()
l@2 LWP suspended in __pollsys()
l@5 LWP suspended in elf_find_sym()
(dbx) lwp l@5
t@5 (l@5) stopped in elf_find_sym at 0x7fffffff7fe0eb74
0x7fffffff7fe0eb74: elf_find_sym+0x00b0: ld [%o5], %o4
(dbx) where
=>[1] elf_find_sym(0x7fffffff7d0ff9e0, 0x7fffffff7d0ffbe8, 0x7fffffff7d0ffbe4, 0x7fffffff7e101510, 0x1000, 0x6c384a4), at 0x7fffffff7fe0eb74
[2] core_lookup_sym(0x7fffffff7e101510, 0x7fffffff7d0ff9e0, 0x7fffffff7d0ffbe8, 0x7fffffff7d0ffbe4, 0x20, 0x7fffffff7d0ffcfc), at 0x7fffffff7fe0c534
[3] _lookup_sym(0x2200, 0x7fffffff7d0ffbe8, 0x7fffffff7d0ffbe4, 0x7fffffff7d0ffcfc, 0x200, 0x7fffffff7fd00848), at 0x7fffffff7fe0c96c
[4] lookup_sym(0x7fffffff7d0ffc00, 0x7fffffff7d0ffbe8, 0x7fffffff7d0ffbe4, 0x7fffffff7d0ffcfc, 0x6c384a4, 0x0), at 0x7fffffff7fe0cc38
[5] dlsym_core(0x200, 0x7fffffff7ff3c198, 0x7fffffff7f801188, 0x7fffffff7d0ffdb8, 0x7fffffff7d0ffcfc, 0x0), at 0x7fffffff7fe1eb68
[6] dlsym_intn(0xfffffffffffffffc, 0x7fffffff7e93c648, 0x7fffffff7f801188, 0x7fffffff7d0ffdb8, 0x0, 0x11e0f0), at 0x7fffffff7fe1edfc
[7] dlsym(0xfffffffffffffffc, 0x7fffffff7e93c648, 0x0, 0xffff, 0xffbffeff, 0x1), at 0x7fffffff7fe1ef6c
[8] _t_cancel(0x7fffffff7d0ff751, 0x7fffffff7e8ece0c, 0x0, 0x0, 0x7fffffff7ec01200, 0x7fffffff7ea3e000), at 0x7fffffff7e8dbaf4
[9] _thr_exit_common(0x0, 0x1c00, 0x0, 0x7fffffff7ec01200, 0x1003b8340, 0x7fffffff7ea3e000), at 0x7fffffff7e8d5088
(dbx) frame 7
0x7fffffff7fe1ef6c: dlsym+0x0030: call dlsym_check ! 0x7fffffff7fe1eeac
(dbx) print (const char *)0x7fffffff7e93c648
dbx: warning: unknown language, 'c' assumed
(const char *) 9223372034683422280 = 0x7fffffff7e93c648 "_ex_unwind"
(dbx)
_ex_unwind() は libc の関数かもしれないため、_t_cancel() 内部で dlsym() を呼んでいるようです。
Illumos（旧OpenSolaris）の _t_cancel のソースでも確認できます。
https://github.com/illumos/illumos-gate/blob/09f79f7c66b85f056db11f58210dc6182c9b1aef/usr/src/lib/libc/port/unwind/unwind.c#L51
そして、運悪く dlsym() がロックを確保したまま vfork() が呼ばれると、
子プロセスの run-time link editor も同じロックを確保しようとしてデッドロックになるようです。
ロックを取っている場所は enter() 関数のようです。
Illumos (旧OpenSolaris）では以下のソースになっています。
結論として、akrさんの記憶のとおり、
http://www.oracle.com/technetwork/server-storage/solaris10/subprocess-136439.html
（Oracleになって移動後の文章。内容は同一。）
に記載されている vfork(2) と multi-threading の ld.so の deadlock の現象が原因と見てよさそうです。
そうなると、r50977 は、タイミングがずれて発生しにくくなっただけで本質ではなく、やはり fork() にするのが根本的解決になりそうです。
ただし、r50977 以後、何百回と繰り返していますが、1回しか再現できていません。
また、r50994 のパッチを r50976 以前に当てると、テストが停止することはなくなります。
Updated by akr (Akira Tanaka) over 9 years ago
ふと、fork にすると本当に解決するのだろうか、という疑問が浮かびました。
vfork でデッドロックになるのは、
(Solaris では親プロセスでvforkを呼び出したスレッドだけでなく、他のスレッドも停止するため)
ロックを持っているスレッドが動かないからだと思うのですが、
fork だと、fork 時に運悪くロックが確保されていて子プロセスにそのロックがそのままコピーされると、
子プロセスにはロックを持っているスレッドが存在しないため、
やはりロックは解除されないんじゃないかという気がするのですが。
Updated by ngoto (Naohisa Goto) over 9 years ago
fork だと、fork 時に運悪くロックが確保されていて子プロセスにそのロックがそのままコピーされると、
子プロセスにはロックを持っているスレッドが存在しないため、
やはりロックは解除されないんじゃないかという気がするのですが。
それは確かに心配なので、簡易な実験をしてみました。
添付の、別スレッドで dlsym をループして呼び続けながら、メインスレッドで fork または vfork を呼ぶプログラムを何回も実行したところ、
vfork の場合は、3%程度の割合でデッドロックに陥り親子とも停止しましたが、
fork の場合は、1000回以上実行しても1回もデッドロックせず100%正常終了しました。
Solaris の fork(2) は manページに MT-Level: Async-Signal-Safe と記述されているだけあって、システム内のロックに対する何らかの配慮があるようです。
（一方 vfork は MT-Level: Unsafe と記述されている。）
結論: Solarisでは必ずforkを呼ぶようにします。
（なお、上記は、システムがシステム内部に暗黙に持っているロックの話で、
ユーザーランド内のロックはforkが勝手に解除することは無いため、
「子プロセスにはロックを持っているスレッドが存在しないため、やはりロックは解除されない」
に常に注意が必要なのは変わりません。）
Updated by ngoto (Naohisa Goto) over 9 years ago
- Status changed from Assigned to Closed
Applied in changeset r51029.
- configure.in: not to use vfork on Solaris to avoid deadlock
occurred in vfork(2) with multi-threading and dynamic linker
on Solaris. [Bug #11265] [ruby-dev:49089]
Updated by usa (Usaku NAKAMURA) over 9 years ago
- Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN to 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: REQUIRED