Bug #11265: deadlock on Solaris 10 since r50900

• Status: Closed
• Assignee: ngoto (Naohisa Goto)
• Target version: -
• ruby -v: -
• Backport: 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: REQUIRED

[ngoto (Naohisa Goto)]

Solaris10にて、r50900 以降、
TestParallel::TestParallel#test_jobs_status
TestParallel::TestParallel#test_separate
のいずれか、または両方で、テストが停止状態となり次に進まなくなります。
スレッドのデッドロックが発生しているような感じです。

ところで、こういう場合の上手いデバッグ方法って何があるでしょうか？

[ngoto (Naohisa Goto)]

• Related to Bug #11237: サブスレッドがすべて終了するとメインスレッドが割り込まれる。 added

[ngoto (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でどのように発生しているのかは突き止めることができませんでした。

[kosaki (Motohiro KOSAKI)]

2015-06-16 12:37 GMT-04:00 [e-mail]:

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

[ngoto (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 と、スレッド終了のどちらが要因なのかは、同定できませんでした。

[kosaki (Motohiro KOSAKI)]

2015-06-17 11:40 GMT-04:00 [e-mail]:

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 のほうがどこで刺さっているのか気になります。

[ngoto (Naohisa Goto)]

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

[ngoto (Naohisa Goto)]

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) 

[akr (Akira Tanaka)]

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

[ngoto (Naohisa Goto)]

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

[akr (Akira Tanaka)]

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

[ngoto (Naohisa Goto)]

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

[ngoto (Naohisa Goto)]

訂正です。

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

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

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

[akr (Akira Tanaka)]

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

[ngoto (Naohisa Goto)]

• 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.

[ngoto (Naohisa Goto)]

• Status changed from Closed to Assigned
• Assignee set to ngoto (Naohisa Goto)

r50977 で発生率は下がりましたがゼロではないようなので、再オープンしておきます。

[ngoto (Naohisa Goto)]

• Related to Bug #11288: start_watchdog in test/lib/test/unit.rb is meaningless added

[ngoto (Naohisa Goto)]

親プロセス側のスレッド 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 以前に当てると、テストが停止することはなくなります。

[akr (Akira Tanaka)]

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

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

[ngoto (Naohisa Goto)]

• File test-solaris-fork-deadlock.c test-solaris-fork-deadlock.c added

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が勝手に解除することは無いため、
「子プロセスにはロックを持っているスレッドが存在しないため、やはりロックは解除されない」
に常に注意が必要なのは変わりません。）

[ngoto (Naohisa Goto)]

• 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]

[usa (Usaku NAKAMURA)]

• Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN to 2.0.0: DONTNEED, 2.1: DONTNEED, 2.2: REQUIRED