Bug #14577: CPU 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: 2.3: REQUIRED, 2.4: DONE, 2.5: DONE

[francois (François Jacques)]

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:

• https://bugs.ruby-lang.org/issues/12925

Related commits:

• https://github.com/ruby/ruby/commit/61b9d4a288361bd055df346cdde4bb970c7406a3

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.

[francois (François Jacques)]

Forgot to mention, this is repro on darwin (10.12.6) and linux (CentOS 6.9).

[nobu (Nobuyoshi Nakada)]

• Status changed from Open to Closed

Applied in changeset trunk|r62673.

---

thread.c: deadlock in backtrace

• thread.c (unblock_function_set): check interrupts just once
  during raising exceptions, as they are deferred since r16651.
  [ruby-core:85939] [Bug #14577]

[nobu (Nobuyoshi Nakada)]

• Backport changed from 2.3: UNKNOWN, 2.4: UNKNOWN, 2.5: UNKNOWN to 2.3: REQUIRED, 2.4: REQUIRED, 2.5: REQUIRED

[francois (François Jacques)]

Thank you nobu! I'll retry to build ruby-trunk today and give it a try!

[francois (François Jacques)]

Rebuilt ruby-trunk. Issue is fixed!

[naruse (Yui NARUSE)]

• Backport changed from 2.3: REQUIRED, 2.4: REQUIRED, 2.5: REQUIRED to 2.3: REQUIRED, 2.4: REQUIRED, 2.5: DONE

ruby_2_5 r62854 merged revision(s) 62673.

[nagachika (Tomoyuki Chikanaga)]

• Backport changed from 2.3: REQUIRED, 2.4: REQUIRED, 2.5: DONE to 2.3: REQUIRED, 2.4: DONE, 2.5: DONE

ruby_2_4 r62917 merged revision(s) 62673.