Ruby

テストがストップしている場所は、
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でどのように発生しているのかは突き止めることができませんでした。

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 は私なんだけど、ごめんなさい、お手上げ。
そういう副作用がでそうなパッチに見えません。

test/lib/test/unit.rb の _run_parallel メソッド内の 408-410行目にて、以下のタイミングで発生していることはわかりました。

1. 408行目では start_watchdog を呼ぶ。
2. start_watchdog メソッド内では、新スレッドを作成してすぐにリターンする。
3. start_watchdog で作成したスレッド内では、Process.wait2 を呼んでいる。しかし、まだ子プロセスを作成する前なので、Errno::ECHILD 例外が発生し、せっかく作った新スレッドはあえなく終了する。（つまり、名前に反して watchdog を行うことは無い。これはバグだと思う。）
4. 409行めは空行。410行目にて @options[:parallel].times {launch_worker} が実行される。 launch_worker は内部ですぐに Worker.launch を呼び、その中で IO.popen にて別プロセスのRubyを起動する。

この上記3の Process.wait2 に失敗してスレッドが終了するのと、上記4のIO.popenの実行がだいたい同時に発生したら、デッドロックが発生するようです。

ただし、上記3のうち、Process.wait2 と、スレッド終了のどちらが要因なのかは、同定できませんでした。

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行目にて、以下のタイミングで発生していることはわかりました。

1. 408行目では start_watchdog を呼ぶ。
2. start_watchdog メソッド内では、新スレッドを作成してすぐにリターンする。
3. start_watchdog で作成したスレッド内では、Process.wait2 を呼んでいる。しかし、まだ子プロセスを作成する前なので、Errno::ECHILD 例外が発生し、せっかく作った新スレッドはあえなく終了する。（つまり、名前に反して watchdog を行うことは無い。これはバグだと思う。）
4. 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 のほうがどこで刺さっているのか気になります。

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) が呼ばれている？

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) 

Solaris で vfork で deadlock というと、
https://web.archive.org/web/20120205202630/http://developers.sun.com/solaris/articles/subprocess/subprocess.html
に書いてあった、dynamic linker が、という話を思い出しますが、関係あるかなぁ。

に書いてあった、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を外しているのも、もしかしたら関係あるかもしれません。

本当に dynamic linker とかで使っている mutex が問題なら、ちょっと対応不能だと思うので、
Solaris 上では vfork はあきらめて fork で済ましておくことになりますかね。

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 でも同様のようです。

訂正です。

なお、execv が not async-signal-safe なのは Linux でも同様のようです。

は、少なくとも最近のLinuxに関しては間違いでした。すみません。

execv は POSIX.1-2008 で async-signal-safe に追加されたため、
それ以前から存在する Solaris 10 が時代に取り残されているだけのようです。

おぉ、調べ直したところ、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 の中をちょっといじればいいんじゃないかな。

親プロセス側のスレッド 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）では以下のソースになっています。

https://github.com/illumos/illumos-gate/blob/09f79f7c66b85f056db11f58210dc6182c9b1aef/usr/src/cmd/sgs/rtld/common/util.c#L3188

結論として、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 以前に当てると、テストが停止することはなくなります。

ふと、fork にすると本当に解決するのだろうか、という疑問が浮かびました。

vfork でデッドロックになるのは、
(Solaris では親プロセスでvforkを呼び出したスレッドだけでなく、他のスレッドも停止するため)
ロックを持っているスレッドが動かないからだと思うのですが、
fork だと、fork 時に運悪くロックが確保されていて子プロセスにそのロックがそのままコピーされると、
子プロセスにはロックを持っているスレッドが存在しないため、
やはりロックは解除されないんじゃないかという気がするのですが。