[ruby-core:71672] [Ruby trunk - Bug #11549] Object allocation during garbage collection phase terminates the Ruby process

[charlez.leu@gmail.com]

Issue #11549 has been updated by Charles Leu.

File ruby_bug_redis_connection.txt added

Here is some follow-up information:

> RE: file ruby_bug_redis_connection.txt

* This is a typical stack trace for the described problem/bug.
* The Ruby app uses the Redis gem (version 3.2.1) that performs I/O on the client app's behalf.
* The Redis gem makes use of read_nonblock to read data available from a Socket.
* Per the C level backtrace information (and my potentially flawed interpretation) it appears that a string is being allocated and gc is being invoked within the context of io_getpartial:

~~~
-- C level backtrace information -------------------------------------------
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(rb_vm_bugreport+0x5b8) [0x7ff99a88a688] vm_dump.c:693
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(rb_bug+0xd5) [0x7ff99a739585] error.c:409
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(newobj_of+0x5aa) [0x7ff99a75e7ea] gc.c:1635
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(str_new0+0x39) [0x7ff99a8157f9] string.c:552
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(rb_str_new_static+0xbf) [0x7ff99a81a14f] string.c:598
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(io_getpartial+0x309) [0x7ff99a770429] io.c:2347
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(io_read_nonblock+0x99) [0x7ff99a770659] io.c:2681
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(vm_call_cfunc_with_frame+0x11a) [0x7ff99a87042a] vm_insnhelper.c:1380
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(vm_exec_core+0x30f5) [0x7ff99a879ed5] insns.def:1054
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(vm_exec+0x7b) [0x7ff99a87f4fb] vm.c:1429
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(invoke_block_from_c+0x2f4) [0x7ff99a880334] vm.c:813
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(rb_yield+0x75) [0x7ff99a8812a5] vm.c:853
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(int_dotimes+0x42) [0x7ff99a78ea42] numeric.c:3868
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(vm_call_cfunc_with_frame+0x11a) [0x7ff99a87042a] vm_insnhelper.c:1380
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(vm_exec_core+0x14e8) [0x7ff99a8782c8] insns.def:1024
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(vm_exec+0x7b) [0x7ff99a87f4fb] vm.c:1429
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(invoke_block_from_c+0x2f4) [0x7ff99a880334] vm.c:813
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(loop_i+0x5c) [0x7ff99a88100c] vm.c:853
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(rb_rescue2+0xdf) [0x7ff99a73d55f] eval.c:808
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(rb_f_loop+0x2e) [0x7ff99a86b9ee] vm_eval.c:1097
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(vm_call_cfunc_with_frame+0x11a) [0x7ff99a87042a] vm_insnhelper.c:1380
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(vm_call_method+0x4d8) [0x7ff99a887df8] vm_insnhelper.c:1473
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(vm_exec_core+0x14e8) [0x7ff99a8782c8] insns.def:1024
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(vm_exec+0x7b) [0x7ff99a87f4fb] vm.c:1429
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(invoke_block_from_c+0x2f4) [0x7ff99a880334] vm.c:813
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(vm_invoke_proc+0xe8) [0x7ff99a880828] vm.c:878
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(rb_vm_invoke_proc+0x1a) [0x7ff99a880a0a] vm.c:897
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2 [0x7ff99a894e76]
/usr/local/rvm/rubies/ruby-2.2.3/lib/libruby.so.2.2(thread_start_func_1+0x71) [0x7ff99a8950f1] thread_pthread.c:852
/lib64/libpthread.so.0(start_thread+0xd1) [0x7ff99a4afa51]
/lib64/libc.so.6(__clone+0x6d) [0x7ff99992893d]
~~~

* Examination of the Control Frame Information, Ruby level backtrace information, and C level backtrace information lead me to believe the logic of the Ruby App and Redis gem are as desired.  What, if anything, do you conclude from the supplied information to suggest there is something awry within the Ruby App and/or Redis gem?  


----------------------------------------
Bug #11549: Object allocation during garbage collection phase terminates the Ruby process
https://bugs.ruby-lang.org/issues/11549#change-55075

* Author: Charles Leu
* Status: Feedback
* Priority: Normal
* Assignee: Koichi Sasada
* ruby -v: ruby 2.2.3p173 (2015-08-18 revision 51636) [x86_64-linux]
* Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN
----------------------------------------
Multi-Threaded Ruby apps are often problematic; especially so when utilizing thread pools, and scheduling work to worker threads.

RE: attached file ruby_2.2.3_obj_alloc_gc_bug.txt

Following is the section of sap_consumer_control.rb that is presented by the Ruby interpreter as being the current execution context when the problem occurs.

408: loop do
409:   @worker_threads.schedule(@work_queue.pop, &@consumer)
410:   @sap_packets_consumed += 1
411: end

Notes:
* @work_queue is a Ruby Queue (allocated within the main thread) into which a producer thread places work requests.
* @worker_threads is a thread pool (allocated within the main thread).
* @worker_threads schedule method simply puts a work request into the thread pool's internal work queue.  One of the worker threads within the thread pool will consume/effect the work request, by executing the specified consumer Proc.
* The main program thread simply loops forever scheduling work to thread pool threads.
* It appears that an object is being allocated by virtue of the @work_queue.pop

Questions:
* Does Ruby garbage collection potentially run within each thread context?
* If answer to prior question is 'Yes', then how can object allocation be prevented when a sibling thread is attempting garbage collection?
* How does one write multi-threaded Ruby apps on multi-core systems that permit multiple-concurrent execution contexts that don't employ a mutex to effectively single thread the entire app? 

---Files--------------------------------
ruby_2.2.3_obj_alloc_gc_bug.txt (49.1 KB)
ruby_bug_redis_connection.txt (53.3 KB)


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