Bug #17855: [BUG] object allocation during garbage collection phase

• Status: Closed
• Assignee: -
• Target version: -
• ruby -v: 2.7.2
• Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN

[Tikroz (Tikroz .)]

Steps to reproduce

It happened sometimes when I'm navigating in my application, I don't really know the cause

Expected behavior

Normal navigation

Actual behavior

The application crashed while printing thousand of lines and also

[Webpacker] Everything s up-to-date. Nothing to do
  Rendered layout layouts/application.html.erb (Duration: 163.2ms | Allocations: 27170)
Completed 200 OK in 171ms (Views: 160.0ms | ActiveRecord: 5.1ms | Allocations: 28113)


C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/file_update_checker.rb:104: [BUG] object allocation during garbage collection phase
ruby 2.7.2p137 (2020-10-01 revision 5445e04352) [x64-mingw32]

-- Control frame information -----------------------------------------------
c:0038 p:---- s:0256 e:000255 CFUNC  :[]
c:0037 p:0037 s:0251 e:000249 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/file_update_checker.rb:104
c:0036 p:0003 s:0245 e:000244 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/file_update_checker.rb:62
c:0035 p:0003 s:0239 e:000238 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/file_update_checker.rb:91
c:0034 p:0056 s:0235 e:000234 BLOCK  C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionview-6.1.3.2/lib/action_view/cache_expiry.rb:34 [FINISH]
c:0033 p:---- s:0231 e:000230 CFUNC  :synchronize
c:0032 p:0006 s:0227 e:000226 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionview-6.1.3.2/lib/action_view/cache_expiry.rb:23
c:0031 p:0005 s:0223 e:000222 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionview-6.1.3.2/lib/action_view/cache_expiry.rb:11
c:0030 p:0034 s:0218 e:000217 BLOCK  C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:427
c:0029 p:0010 s:0210 e:000209 BLOCK  C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:198
c:0028 p:0005 s:0207 e:000206 BLOCK  C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:604 [FINISH]
c:0027 p:---- s:0204 e:000203 CFUNC  :catch
c:0026 p:0011 s:0199 e:000198 BLOCK  C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:603
c:0025 p:0040 s:0193 E:001d88 BLOCK  C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:199
c:0024 p:0007 s:0184 e:000183 BLOCK  C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:512 [FINISH]
c:0023 p:---- s:0180 e:000179 CFUNC  :each
c:0022 p:0006 s:0176 e:000175 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:512
c:0021 p:0066 s:0171 e:000170 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:105
c:0020 p:0026 s:0162 e:000161 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/execution_wrapper.rb:111
c:0019 p:0008 s:0158 e:000157 BLOCK  C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/execution_wrapper.rb:73 [FINISH]
c:0018 p:---- s:0153 e:000152 CFUNC  :tap
c:0017 p:0021 s:0149 e:000148 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/execution_wrapper.rb:70
c:0016 p:0005 s:0145 e:000144 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionpack-6.1.3.2/lib/action_dispatch/middleware/executor.rb:12
c:0015 p:0018 s:0137 E:000558 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionpack-6.1.3.2/lib/action_dispatch/middleware/static.rb:24
c:0014 p:0007 s:0132 E:0006f0 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110
c:0013 p:0057 s:0120 E:000e60 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionpack-6.1.3.2/lib/action_dispatch/middleware/host_authorization.rb:98
c:0012 p:1165 s:0114 E:0001f0 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/rack-mini-profiler-2.3.2/lib/mini_profiler/profiler.rb:384
c:0011 p:0151 s:0082 E:000a98 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/webpacker-5.3.0/lib/webpacker/dev_server_proxy.rb:25
c:0010 p:0009 s:0077 E:000f18 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/rack-proxy-0.6.5/lib/rack/proxy.rb:57
c:0009 p:0016 s:0071 E:000560 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/railties-6.1.3.2/lib/rails/engine.rb:539
c:0008 p:0028 s:0065 E:000bb8 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/puma-5.2.2/lib/puma/configuration.rb:248
c:0007 p:0008 s:0060 E:000730 BLOCK  C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/puma-5.2.2/lib/puma/request.rb:76
c:0006 p:0023 s:0057 E:000ac8 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/puma-5.2.2/lib/puma/thread_pool.rb:337
c:0005 p:0274 s:0052 E:0018b0 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/puma-5.2.2/lib/puma/request.rb:75
c:0004 p:0123 s:0032 E:000d40 METHOD C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/puma-5.2.2/lib/puma/server.rb:431 [FINISH]
c:0003 p:---- s:0020 E:000f60 IFUNC
c:0002 p:0094 s:0017 E:000e28 BLOCK  C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/puma-5.2.2/lib/puma/thread_pool.rb:145 [FINISH]
c:0001 p:---- s:0003 e:000002 (none) [FINISH]

-- Ruby level backtrace information ----------------------------------------
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/puma-5.2.2/lib/puma/thread_pool.rb:145:in `block in spawn_thread'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/puma-5.2.2/lib/puma/server.rb:431:in `process_client'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/puma-5.2.2/lib/puma/request.rb:75:in `handle_request'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/puma-5.2.2/lib/puma/thread_pool.rb:337:in `with_force_shutdown'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/puma-5.2.2/lib/puma/request.rb:76:in `block in handle_request'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/puma-5.2.2/lib/puma/configuration.rb:248:in `call'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/railties-6.1.3.2/lib/rails/engine.rb:539:in `call'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/rack-proxy-0.6.5/lib/rack/proxy.rb:57:in `call'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/webpacker-5.3.0/lib/webpacker/dev_server_proxy.rb:25:in `perform_request'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/rack-mini-profiler-2.3.2/lib/mini_profiler/profiler.rb:384:in `call'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionpack-6.1.3.2/lib/action_dispatch/middleware/host_authorization.rb:98:in `call'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionpack-6.1.3.2/lib/action_dispatch/middleware/static.rb:24:in `call'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionpack-6.1.3.2/lib/action_dispatch/middleware/executor.rb:12:in `call'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/execution_wrapper.rb:70:in `run!'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/execution_wrapper.rb:70:in `tap'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/execution_wrapper.rb:73:in `block in run!'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/execution_wrapper.rb:111:in `run!'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:105:in `run_callbacks'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:512:in `invoke_before'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:512:in `each'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:512:in `block in invoke_before'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:199:in `block in halting'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:603:in `block in default_terminator'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:603:in `catch'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:604:in `block (2 levels) in default_terminator'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:198:in `block (2 levels) in halting'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/callbacks.rb:427:in `block in make_lambda'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionview-6.1.3.2/lib/action_view/cache_expiry.rb:11:in `before'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionview-6.1.3.2/lib/action_view/cache_expiry.rb:23:in `clear_cache_if_necessary'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionview-6.1.3.2/lib/action_view/cache_expiry.rb:23:in `synchronize'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/actionview-6.1.3.2/lib/action_view/cache_expiry.rb:34:in `block in clear_cache_if_necessary'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/file_update_checker.rb:91:in `execute_if_updated'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/file_update_checker.rb:62:in `updated?'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/file_update_checker.rb:104:in `watched'
C:/Ruby27-x64/lib/ruby/gems/2.7.0/gems/activesupport-6.1.3.2/lib/active_support/file_update_checker.rb:104:in `[]'

-- C level backtrace information -------------------------------------------
C:\WINDOWS\SYSTEM32\ntdll.dll(ZwWaitForSingleObject+0x14) [0x00007ffd82d2cda4]
C:\WINDOWS\System32\KERNELBASE.dll(WaitForSingleObjectEx+0x8e) [0x00007ffd806d165e]
C:\Ruby27-x64\bin\x64-msvcrt-ruby270.dll(rb_vm_bugreport+0x34b) [0x00000000653c657b]
C:\Ruby27-x64\bin\x64-msvcrt-ruby270.dll(rb_bug+0x7c) [0x00000000653f1fec]
C:\Ruby27-x64\bin\x64-msvcrt-ruby270.dll(rb_memerror+0x428) [0x00000000653f2828]
C:\Ruby27-x64\bin\x64-msvcrt-ruby270.dll(rb_wb_protected_newobj_of+0xbc) [0x0000000065208fdc]
C:\Ruby27-x64\bin\x64-msvcrt-ruby270.dll(rb_utf8_str_new_cstr+0x3a) [0x000000006533bb3a]
C:\Ruby27-x64\bin\x64-msvcrt-ruby270.dll(ruby_debug_counter_show_at_exit+0x17d4) [0x00000000651b5534]
C:\Ruby27-x64\bin\x64-msvcrt-ruby270.dll(ruby_debug_counter_show_at_exit+0x35) [0x00000000651b3d95]
C:\Ruby27-x64\bin\x64-msvcrt-ruby270.dll(rb_protect+0x1c4) [0x00000000651e9a44]
C:\Ruby27-x64\bin\x64-msvcrt-ruby270.dll(ruby_debug_counter_show_at_exit+0x8bb) [0x00000000651b461b]
C:\Ruby27-x64\bin\x64-msvcrt-ruby270.dll(ruby_debug_counter_show_at_exit+0x4b15) [0x00000000651b8875]

-- Other runtime information -----------------------------------------------

* Loaded script: bin/rails

* Loaded features:

    0 enumerator.so
    1 thread.rb
    ...

It happenned an other time with this beginning of error :

C;/Ruby27-x64/lib/ruby/gems/2.7.0/action-pack-6.1.3/lib/action_dispatch/middleware/static.rb:140: [BUG] object allocation during garbage collection phase

System configuration

Rails version:
6.1.3
Ruby version:
2.7.2

[jeremyevans0 (Jeremy Evans)]

• Status changed from Open to Feedback

There's not much that we can do to debug this without a reproducible example. The most common cause is a C extension trying to allocate an object while garbage collection is running. From the backtrace, the rb_utf8_str_new_cstr function is being called to allocate a string. The only internal callers of that method are during directory globbing and when setting the program name, so it seems likely an external C extension is calling the method.

Unfortunately, the backtrace is too limited to see which C extension is calling this. It also looks like some memory corruption has occurred, considering that ruby_debug_counter_show_at_exit is shown four times in the backtrace, but that function does not call any functions. It is possible that rb_utf8_str_new_cstr is not actually the function called, but rb_utf8_str_new_cstr does call rb_wb_protected_newobj_of through a whole chain of function calls that may be optimized out, so it seems likely that is the function called.

Can you provide a reproducible example for this issue?

[Tikroz (Tikroz .)]

I don't really have a reproducible example for this issue, it just happenned sometimes in my application, is there any logging thing I can add to my project to give more informations about this ? Thank you.

[xtkoba (Tee KOBAYASHI)]

As for C level backtrace, I believe that the most reliable way to obtain one is to attach a debugger such as GDB or LLDB. For debugging purposes it is preferable that you turn off any compiler optimizations (./configure optflags=-O0).

[jeremyevans0 (Jeremy Evans)]

• Status changed from Feedback to Closed