Actions
Bug #14577
closedCPU 100% in custom backtrace method with IO.readlines
Status:
Closed
Assignee:
-
Target version:
-
ruby -v:
ruby 2.5.0p0 (2017-12-25 revision 61468) [x86_64-darwin16]
Backport:
Description
Hello,
First bug reported in ruby redmine; I'll do my best to make it easy to diagnose. Please, let me know more information is needed.
- It's possible, with a very small script, to have ruby CPU usage goes to 100% and locking the interpreter;
- Such process can only be terminated forcefully (SIGKILL);
- It cannot be reproduced prior with ruby 2.3.0 and 2.3.1;
- Validated with ruby 2.3.2 and 2.5 (was unable to build ruby-trunk).
Sample use case:
- runtime error raised during rhtml file rendering with older version of Rails (2.1) is transformed into an ActionView::TemplateError, which calls IO.readline
https://github.com/rails/rails/blob/2-1-stable/actionpack/lib/action_view/template_error.rb#L33 - After a few successful executions, the interpreter eventually enters in busy waiting.
Related bugs:
Related commits:
Callstack when attaching to process:
(lldb) process attach --pid 4485
Process 4485 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
frame #0: 0x0000000103d66a37 ruby`rb_threadptr_execute_interrupts(th=0x00007fd79250ab50, blocking_timing=0) at thread.c:2062
2059
2060 void
2061 rb_threadptr_execute_interrupts(rb_thread_t *th, int blocking_timing)
-> 2062 {
2063 rb_atomic_t interrupt;
2064 int postponed_job_interrupt = 0;
2065
Target 0: (ruby) stopped.
Executable module set to "/Users/francois/.rubies/ruby-trunk/bin/ruby".
Architecture set to: x86_64h-apple-macosx.
(lldb) bt all
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
* frame #0: 0x0000000103d66a37 ruby`rb_threadptr_execute_interrupts(th=0x00007fd79250ab50, blocking_timing=0) at thread.c:2062
frame #1: 0x0000000103d6650c ruby`blocking_region_begin [inlined] rb_vm_check_ints(ec=<unavailable>) at vm_core.h:1693
frame #2: 0x0000000103d66505 ruby`blocking_region_begin [inlined] unblock_function_set(th=0x00007fd79250ab50, fail_if_interrupted=<unavailable>) at thread.c:391
frame #3: 0x0000000103d6649b ruby`blocking_region_begin(th=0x00007fd79250ab50, region=0x00007fff5c02ffb0, ubf=(ruby`ubf_select at thread_pthread.c:1198), arg=0x00007fd79250ab50, fail_if_interrupted=<unavailable>) at thread.c:1312
frame #4: 0x0000000103d663a3 ruby`rb_thread_io_blocking_region(func=(ruby`internal_read_func at io.c:935), data1=0x00007fff5c030010, fd=<unavailable>) at thread.c:1481
frame #5: 0x0000000103c70050 ruby`io_fillbuf [inlined] rb_read_internal(fd=<unavailable>, count=<unavailable>) at io.c:971
frame #6: 0x0000000103c70035 ruby`io_fillbuf(fptr=0x00007fd7927150c0) at io.c:1966
frame #7: 0x0000000103c70f89 ruby`rb_io_getline_0 [inlined] rb_io_getline_fast(fptr=0x00007fd7927150c0, chomp=0) at io.c:3241
frame #8: 0x0000000103c70df9 ruby`rb_io_getline_0(rs=<unavailable>, limit=<unavailable>, chomp=<unavailable>, fptr=<unavailable>) at io.c:3356
frame #9: 0x0000000103c84162 ruby`io_s_readlines [inlined] rb_io_getline_1(io=<unavailable>) at io.c:3452
frame #10: 0x0000000103c84156 ruby`io_s_readlines [inlined] io_readlines(arg=0x00007fff5c0302a0, io=140563852871920) at io.c:3657
frame #11: 0x0000000103c84050 ruby`io_s_readlines(arg=0x00007fff5c0302a0) at io.c:10255
frame #12: 0x0000000103c49fa1 ruby`rb_ensure(b_proc=(ruby`io_s_readlines at io.c:10254), data1=140734737089184, e_proc=<unavailable>, data2=<unavailable>) at eval.c:1037
frame #13: 0x0000000103c77077 ruby`rb_io_s_readlines(argc=<unavailable>, argv=0x0000000103fbd098, io=<unavailable>) at io.c:10301
frame #14: 0x0000000103dabf4e ruby`vm_call_cfunc [inlined] vm_call_cfunc_with_frame at vm_insnhelper.c:1918
frame #15: 0x0000000103dabe87 ruby`vm_call_cfunc(ec=0x00007fd79250afb8, reg_cfp=0x00000001040bcf10, calling=<unavailable>, ci=0x00007fd7927621f0, cc=<unavailable>) at vm_insnhelper.c:1934
frame #16: 0x0000000103d956b4 ruby`vm_exec_core(ec=<unavailable>, initial=<unavailable>) at insns.def:915
frame #17: 0x0000000103da681e ruby`vm_exec(ec=0x00007fd79250afb8) at vm.c:1778
frame #18: 0x0000000103db3d88 ruby`rb_call0 [inlined] vm_call0(ec=0x00007fd79250afb8, recv=140563852871960, id=7809, argv=0x0000000000000000, me=<unavailable>) at vm_eval.c:58
frame #19: 0x0000000103db3d56 ruby`rb_call0(ec=0x00007fd79250afb8, recv=140563852871960, mid=7809, argc=0, argv=0x0000000000000000, scope=<unavailable>, self=140563853435600) at vm_eval.c:296
frame #20: 0x0000000103d9f061 ruby`rb_funcallv [inlined] rb_call(recv=<unavailable>, mid=<unavailable>, argc=<unavailable>, argv=<unavailable>, scope=CALL_FCALL) at vm_eval.c:589
frame #21: 0x0000000103d9f043 ruby`rb_funcallv(recv=<unavailable>, mid=<unavailable>, argc=<unavailable>, argv=<unavailable>) at vm_eval.c:815
frame #22: 0x0000000103c4bda4 ruby`setup_exception(ec=0x00007fd79250afb8, tag=6, mesg=<unavailable>, cause=8) at eval.c:513
frame #23: 0x0000000103c496e3 ruby`rb_longjmp(ec=0x00007fd79250afb8, tag=6, mesg=<unavailable>, cause=8) at eval.c:600
frame #24: 0x0000000103c499bc ruby`rb_raise_jump(mesg=<unavailable>, cause=<unavailable>) at eval.c:809
frame #25: 0x0000000103c4ad53 ruby`rb_f_raise(argc=1, argv=0x0000000103fbd078) at eval.c:714
frame #26: 0x0000000103dabf4e ruby`vm_call_cfunc [inlined] vm_call_cfunc_with_frame at vm_insnhelper.c:1918
frame #27: 0x0000000103dabe87 ruby`vm_call_cfunc(ec=0x00007fd79250afb8, reg_cfp=0x00000001040bcf40, calling=<unavailable>, ci=0x00007fd792768d90, cc=<unavailable>) at vm_insnhelper.c:1934
frame #28: 0x0000000103d956b4 ruby`vm_exec_core(ec=<unavailable>, initial=<unavailable>) at insns.def:915
frame #29: 0x0000000103da681e ruby`vm_exec(ec=0x00007fd79250afb8) at vm.c:1778
frame #30: 0x0000000103db3f44 ruby`invoke_block_from_c_bh(ec=0x00007fd79250afb8, block_handler=<unavailable>, argc=0, argv=0x0000000000000000, passed_block_handler=0, cref=<unavailable>, is_lambda=<unavailable>, force_blockarg=0) at vm.c:1049
frame #31: 0x0000000103db4fb3 ruby`loop_i [inlined] vm_yield(ec=<unavailable>, argc=0, argv=<unavailable>) at vm.c:1094
frame #32: 0x0000000103db4fa0 ruby`loop_i [inlined] rb_yield_0(argc=0) at vm_eval.c:970
frame #33: 0x0000000103db4fa0 ruby`loop_i at vm_eval.c:1049
frame #34: 0x0000000103c49bb7 ruby`rb_rescue2(b_proc=(ruby`loop_i at vm_eval.c:1047), data1=0, r_proc=(ruby`loop_stop at vm_eval.c:1056), data2=0) at eval.c:896
frame #35: 0x0000000103dabf4e ruby`vm_call_cfunc [inlined] vm_call_cfunc_with_frame at vm_insnhelper.c:1918
frame #36: 0x0000000103dabe87 ruby`vm_call_cfunc(ec=0x00007fd79250afb8, reg_cfp=0x00000001040bcfa0, calling=<unavailable>, ci=0x00007fd7927161e0, cc=<unavailable>) at vm_insnhelper.c:1934
frame #37: 0x0000000103d94c14 ruby`vm_exec_core(ec=<unavailable>, initial=<unavailable>) at insns.def:850
frame #38: 0x0000000103da681e ruby`vm_exec(ec=0x00007fd79250afb8) at vm.c:1778
frame #39: 0x0000000103c493e1 ruby`ruby_exec_internal(n=0x00007fd79307c5e8) at eval.c:246
frame #40: 0x0000000103c492d8 ruby`ruby_run_node [inlined] ruby_exec_node(n=<unavailable>) at eval.c:310
frame #41: 0x0000000103c492ca ruby`ruby_run_node(n=<unavailable>) at eval.c:302
frame #42: 0x0000000103bceb2f ruby`main(argc=<unavailable>, argv=<unavailable>) at main.c:42
frame #43: 0x00007fffe6d82235 libdyld.dylib`start + 1
frame #44: 0x00007fffe6d82235 libdyld.dylib`start + 1
thread #2, name = 'ruby-timer-thr'
frame #0: 0x00007fffe6eb219e libsystem_kernel.dylib`poll + 10
frame #1: 0x0000000103d6c5c3 ruby`thread_timer [inlined] timer_thread_sleep(gvl=<unavailable>) at thread_pthread.c:0
frame #2: 0x0000000103d6c566 ruby`thread_timer(p=0x00007fd79250a768) at thread_pthread.c:1577
frame #3: 0x00007fffe6f9b93b libsystem_pthread.dylib`_pthread_body + 180
frame #4: 0x00007fffe6f9b887 libsystem_pthread.dylib`_pthread_start + 286
frame #5: 0x00007fffe6f9b08d libsystem_pthread.dylib`thread_start + 13
Script:
class Crash < RuntimeError
def backtrace
IO.readlines($0)
end
end
puts 'Wait for it. Starting in 0.5 sec. Once the dots stop, kill the process with SIGKILL.'
sleep 0.5
loop do
begin
raise Crash.new 'boo!'
rescue => e
putc '.'
ensure
end
end
Output (it stopped at the last dot, and can only be stopped through kill -9):
~/.rubies/ruby-trunk/bin/ruby ~/backtrace_bug.rb
Wait for it. Starting in 0.5 sec. Once the dots stop, kill the process with SIGKILL.
.....................
It seems like it needs to be backported all the way to Ruby 2.2.
Files
Actions
Like0
Like0Like0Like0Like0Like0Like0Like0