Actions
Bug #11510
closed
exit waits for the block form of IO.popen's child
ruby -v:
ruby 2.2.3p173 (2015-08-18) [x86_64-linux-gnu]
Description
The block form of IO.popen waits for the child process to finish before quitting. If the parent process exits during this wait, the wait is interrupted and the exit proceeds promptly. There's a difference in behavior, however, if the exit is initiated before IO.popen gets to the wait. Whatever the parent is doing is interrupted, but IO.popen then waits, potentially holding off the exit indefinitely. I think the intention is that it should exit promptly. This is a change in behavior, albeit not a recent one:
martind@paris:~$ for ruby in /usr/bin/ruby*.*; do $ruby --version; time $ruby -we 'Thread.new() { IO.popen("sleep 3", "r") { sleep(2); }; }; sleep(1)'; done
ruby 1.8.7 (2012-02-08 patchlevel 358) [x86_64-linux]
real 0m1.006s
user 0m0.008s
sys 0m0.000s
ruby 1.9.3p194 (2012-04-20 revision 35410) [x86_64-linux]
real 0m3.057s
user 0m0.912s
sys 0m1.100s
ruby 2.1.5p273 (2014-11-13) [x86_64-linux-gnu]
real 0m3.024s
user 0m0.016s
sys 0m0.004s
ruby 2.2.3p173 (2015-08-18) [x86_64-linux-gnu]
real 0m3.062s
user 0m0.060s
sys 0m0.000s
martind@paris:~$
The remainder of this report is just my inconclusive attempt to understand where in the Ruby source the problem might lie. It will probably just confuse the issue.
This script correctly terminates in 1s:
time ruby -we 'Thread.new() { io = IO.popen("sleep 3", "r"); io.close(); }; sleep(1)'
That surprises me because io.close() makes what I think is the same rb_syswait call, from rb_io_close, to wait for the child, so that this correctly takes 3s:
time ruby -we 'io = IO.popen("sleep 3", "r"); io.close()'
The C stack trace of the dubiously waiting thread from the reproducer:
(gdb) bt
#0 0x00007ffff77524c9 in __libc_waitpid (pid=5819, stat_loc=0x7ffff60c903c, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:40
#1 0x00007ffff7a43bc2 in rb_waitpid_blocking (data=<optimized out>) at process.c:786
#2 0x00007ffff7afc5cf in call_without_gvl (func=func@entry=0x7ffff7a43bb0 <rb_waitpid_blocking at process.c:777>, data1=data1@entry=0x7ffff60c8ff0, ubf=<optimized out>, ubf@entry=0xffffffffffffffff, data2=<optimized out>, data2@entry=0x0, fail_if_interrupted=fail_if_interrupted@entry=0) at thread.c:1274
#3 0x00007ffff7afc788 in rb_thread_call_without_gvl (func=func@entry=0x7ffff7a43bb0 <rb_waitpid_blocking at process.c:777>, data1=data1@entry=0x7ffff60c8ff0, ubf=ubf@entry=0xffffffffffffffff, data2=data2@entry=0x0) at thread.c:1384
#4 0x00007ffff7a47e37 in rb_waitpid (pid=5819, st=st@entry=0x7ffff60c903c, flags=flags@entry=0) at process.c:805
#5 0x00007ffff7a4b340 in rb_syswait (pid=<optimized out>) at process.c:3867
#6 0x00007ffff79fe755 in rb_io_close (io=io@entry=10582360) at io.c:4399
#7 0x00007ffff79fe855 in rb_io_close_m (io=10582360) at io.c:4424
#8 0x00007ffff7ae74a6 in vm_call0_cfunc_with_frame (argv=0x0, ci=0x7ffff60c90a0, th=0xa19b50) at vm_eval.c:127
#9 vm_call0_cfunc (argv=0x0, ci=0x7ffff60c90a0, th=0xa19b50) at vm_eval.c:144
#10 vm_call0_body (th=th@entry=0xa19b50, ci=ci@entry=0x7ffff60c9170, argv=argv@entry=0x0) at vm_eval.c:184
#11 0x00007ffff7ae7fbd in vm_call0 (defined_class=<optimized out>, me=<optimized out>, argv=0x0, argc=0, id=15761, recv=10582360, th=0xa19b50) at vm_eval.c:59
#12 rb_check_funcall (recv=recv@entry=10582360, mid=15761, argc=argc@entry=0, argv=argv@entry=0x0) at vm_eval.c:450
#13 0x00007ffff79f73e7 in io_call_close (io=io@entry=10582360) at io.c:4431
#14 0x00007ffff79d418e in rb_rescue2 (b_proc=b_proc@entry=0x7ffff79f73b0 <io_call_close at io.c:4431>, data1=data1@entry=10582360, r_proc=r_proc@entry=0x7ffff79f73f0 <ignore_closed_stream at io.c:4437>, data2=data2@entry=10582360) at eval.c:808
#15 0x00007ffff79f8612 in io_close (io=10582360) at io.c:4453
#16 0x00007ffff79d4633 in rb_ensure (b_proc=0x7ffff7aec070 <rb_yield at vm_eval.c:997>, data1=data1@entry=10582360, e_proc=e_proc@entry=0x7ffff79f85c0 <io_close at io.c:4451>, data2=data2@entry=10582360) at eval.c:912
#17 0x00007ffff7a0444e in rb_io_s_popen (argc=<optimized out>, argv=<optimized out>, klass=6677560) at io.c:6303
#18 0x00007ffff7adca46 in vm_call_cfunc_with_frame (ci=0xa19b50, reg_cfp=0x7ffff61caf70, th=0xa19b50) at vm_insnhelper.c:1380
#19 vm_call_cfunc (th=th@entry=0xa19b50, reg_cfp=reg_cfp@entry=0x7ffff61caf70, ci=ci@entry=0x814e30) at vm_insnhelper.c:1473
#20 0x00007ffff7aecc1e in vm_call_method (th=0xa19b50, cfp=0x7ffff61caf70, ci=0x814e30) at vm_insnhelper.c:1689
#21 0x00007ffff7ae0527 in vm_exec_core (th=th@entry=0xa19b50, initial=initial@entry=0) at insns.def:1024
#22 0x00007ffff7ae5cb0 in vm_exec (th=th@entry=0xa19b50) at vm.c:1429
#23 0x00007ffff7aeaf5d in invoke_block_from_c (th=th@entry=0xa19b50, block=block@entry=0xa1e080, self=self@entry=6724720, argc=argc@entry=0, argv=argv@entry=0xa17e40, blockptr=blockptr@entry=0x0, cref=0x0, defined_class=8, splattable=0) at vm.c:813
#24 0x00007ffff7aeb460 in vm_invoke_proc (th=th@entry=0xa19b50, proc=proc@entry=0xa1e080, self=6724720, defined_class=8, argc=0, argv=0xa17e40, blockptr=0x0) at vm.c:878
#25 0x00007ffff7aeb558 in rb_vm_invoke_proc (th=th@entry=0xa19b50, proc=proc@entry=0xa1e080, argc=<optimized out>, argv=<optimized out>, blockptr=blockptr@entry=0x0) at vm.c:897
#26 0x00007ffff7afb2cd in thread_start_func_2 (th=th@entry=0xa19b50, stack_start=<optimized out>) at thread.c:577
#27 0x00007ffff7afb4d0 in thread_start_func_1 (th_ptr=0xa19b50) at thread_pthread.c:852
#28 0x00007ffff774b0a4 in start_thread (arg=0x7ffff60ca700) at pthread_create.c:309
#29 0x00007ffff6ac104d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
(gdb)
The main thread:
(gdb) bt
#0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007ffff7af7aa9 in native_cond_wait (cond=<optimized out>, mutex=mutex@entry=0x603718) at thread_pthread.c:338
#2 0x00007ffff7af8eca in native_sleep (th=th@entry=0x6035f0, timeout_tv=timeout_tv@entry=0x0) at thread_pthread.c:1110
#3 0x00007ffff7afd500 in rb_thread_terminate_all () at thread.c:489
#4 0x00007ffff79d578f in ruby_cleanup (ex=0) at eval.c:187
#5 0x00007ffff79d5b35 in ruby_run_node (n=0x6187f8) at eval.c:309
#6 0x00000000004008ab in ?? ()
#7 0x00007ffff69fcb45 in __libc_start_main (main=0x400860, argc=3, argv=0x7fffffffc268, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffc258) at libc-start.c:287
#8 0x00000000004008d9 in _start ()
(gdb)
Updated by nobu (Nobuyoshi Nakada) about 9 years ago
- Description updated (diff)
- Backport changed from 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN to 2.0.0: REQUIRED, 2.1: REQUIRED, 2.2: REQUIRED
Updated by nobu (Nobuyoshi Nakada) about 9 years ago
- Status changed from Open to Closed
Applied in changeset r51798.
io.c: no wait when killed
- io.c (rb_io_s_popen): do not wait the child process during being
killed. [ruby-core:70671] [Bug #11510]
Updated by usa (Usaku NAKAMURA) about 9 years ago
- Status changed from Closed to Assigned
- Assignee set to nobu (Nobuyoshi Nakada)
npbu, your change introduced a test error on mswin.
Fix it, please.
Updated by jeremyevans0 (Jeremy Evans) over 5 years ago
- Status changed from Assigned to Closed
Actions
Like0
Like0Like0Like0Like0