Avoid allocation withing RESUMED hook#34
Conversation
Stack trace from a reproduction script that caused a deadlock on 4.1.0dev using the "async" gem (fiber scheduler): ``` thread Shopify#11, name = 'repro.rb:72' frame #0: 0x000000018fafd9c8 libsystem_kernel.dylib`__psynch_mutexwait + 8 frame Shopify#1: 0x000000018fb3ae3c libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_wait + 84 frame Shopify#2: 0x000000018fb38868 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_slow + 220 frame Shopify#3: 0x0000000100c39b58 ruby`rb_native_mutex_lock(lock=0x0000000100f18200) at thread_pthread.c:125:14 [inlined] frame Shopify#4: 0x0000000100c39b50 ruby`thread_sched_lock_(sched=0x0000000100f18200, th=<unavailable>, file=<unavailable>, line=991) at thread_pthread.c:403:5 [inlined] frame Shopify#5: 0x0000000100c39b50 ruby`thread_sched_to_running(sched=0x0000000100f18200, th=0x0000000766d3ad00) at thread_pthread.c:991:5 frame Shopify#6: 0x0000000100c2feb8 ruby`blocking_region_end(th=0x0000000766d3ad00, region=0x000000016fdf5a04) at thread.c:1554:5 frame Shopify#7: 0x0000000100c305a8 ruby`rb_thread_call_with_gvl(func=(ruby`gc_with_gvl at default.c:6980), data1=0x000000016fdf57f8) at thread.c:2089:5 frame Shopify#8: 0x0000000100ae8470 ruby`garbage_collect_with_gvl(objspace=0x0000000767008000, reason=512) at default.c:7001:15 frame Shopify#9: 0x0000000100ae83ec ruby`objspace_malloc_increase_body(objspace=0x0000000767008000, mem=<unavailable>, new_size=<unavailable>, old_size=<unavailable>, type=<unavailable>, gc_allowed=<unavailable>) at default.c:8358:13 frame Shopify#10: 0x0000000100ad2d74 ruby`objspace_malloc_fixup(objspace=0x0000000767008000, mem=0x0000000767892010, size=40, gc_allowed=true) at default.c:8436:5 [inlined] frame Shopify#11: 0x0000000100ad2d5c ruby`rb_gc_impl_calloc(objspace_ptr=0x0000000767008000, size=40, gc_allowed=true) at default.c:8562:12 [inlined] frame Shopify#12: 0x0000000100ad2ce0 ruby`ruby_xcalloc_body(n=<unavailable>, size=<unavailable>) at gc.c:5467:12 [inlined] frame Shopify#13: 0x0000000100ad2c80 ruby`ruby_xcalloc(n=<unavailable>, size=<unavailable>) at gc.c:5461:34 frame Shopify#14: 0x0000000100ad2bd0 ruby`rb_data_typed_object_zalloc(klass=<unavailable>, size=40, type=0x0000000101184010) at gc.c:1198:21 frame Shopify#15: 0x0000000101180e30 instrumentation.bundle`GT_LOCAL_STATE + 84 frame Shopify#16: 0x0000000101180d18 instrumentation.bundle`gt_thread_callback + 204 frame Shopify#17: 0x0000000100c29aa0 ruby`rb_thread_execute_hooks(event=4, th=0x0000000766d3ad00) at thread_pthread.c:3556:17 frame Shopify#18: 0x0000000100c29d24 ruby`thread_sched_wait_running_turn(sched=<unavailable>, th=<unavailable>, can_direct_transfer=<unavailable>) at thread_pthread.c:949:5 [artificial] frame Shopify#19: 0x0000000100c39c70 ruby`thread_sched_to_running_common(sched=0x0000000100f18200, th=0x0000000766d3ad00) at thread_pthread.c:972:5 [inlined] frame Shopify#20: 0x0000000100c39b5c ruby`thread_sched_to_running(sched=0x0000000100f18200, th=0x0000000766d3ad00) at thread_pthread.c:993:9 frame Shopify#21: 0x0000000100c2feb8 ruby`blocking_region_end(th=0x0000000766d3ad00, region=0x000000016fdf5a04) at thread.c:1554:5 frame Shopify#22: 0x0000000100c2fa68 ruby`rb_nogvl(func=<unavailable>, data1=<unavailable>, ubf=<unavailable>, data2=<unavailable>, flags=<unavailable>) at thread.c:1629:5 frame Shopify#23: 0x0000000120302364 IO_Event.bundle`IO_Event_Selector_KQueue_select + 520 ``` Even if it did run with the GVL, it's problematic because the thread scheduler lock is still held. For a fix, don't allocate during the `RESUMED` event. Instead, rely on `STARTED` event to create the object for new threads. For old threads, create their thread-local object when enabling the LocalTimer.
|
I think this is more of an issue on This fix would only enable the local timer for the current Ractor, so maybe not the best fix. I mainly wanted to bring it to your attention, as we may change the docs for the |
|
I would argue it's a CRuby bug if the |
|
I can see your point, but it's a little more subtle. The GVL is sort of acquired (no other Ruby threads are running and this thread is about to run), but in this specific event hook you can't allocate with xmalloc, create Ruby objects or call into Ruby. The datadog gem you referenced doesn't do that, so it's fine. I created a Ruby ticket, so maybe we should continue the convo there. |
Stack trace from a reproduction script that caused a deadlock on 4.1.0dev using the "async" gem (fiber scheduler):
Even if it did run with the GVL, it's problematic because the thread scheduler lock is still held.
For a fix, don't allocate during the
RESUMEDevent. Instead, rely onSTARTEDevent to create the object for new threads. For old threads, create their thread-local object when enabling the LocalTimer.