[ruby-core:86288] [Ruby trunk Bug#14577] CPU 100% in custom backtrace method with IO.readlines

Issue #14577 has been updated by 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.

----------------------------------------
Bug #14577: CPU 100% in custom backtrace method with IO.readlines
https://bugs.ruby-lang.org/issues/14577#change-71201

* Author: francois (Fran巽ois Jacques)
* Status: Closed
* Priority: Normal
* 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
----------------------------------------
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.



---Files--------------------------------
backtrace_bug.rb (267 Bytes)


-- 
https://bugs.ruby-lang.org/

Unsubscribe: <mailto:[e-mail]?subject=unsubscribe>
<http://lists.ruby-lang.org/cgi-bin/mailman/options/ruby-core>