Skip to content

Avoid allocation withing RESUMED hook#34

Merged
jhawthorn merged 3 commits into
Shopify:masterfrom
luke-gruber:fix_localtimer_resumed_callback
Jun 15, 2026
Merged

Avoid allocation withing RESUMED hook#34
jhawthorn merged 3 commits into
Shopify:masterfrom
luke-gruber:fix_localtimer_resumed_callback

Conversation

@luke-gruber

Copy link
Copy Markdown
Contributor

Stack trace from a reproduction script that caused a deadlock on 4.1.0dev using the "async" gem (fiber scheduler):

thread #11, name = 'repro.rb:72'
  frame #0: 0x000000018fafd9c8 libsystem_kernel.dylib`__psynch_mutexwait + 8
  frame #1: 0x000000018fb3ae3c libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_wait + 84
  frame #2: 0x000000018fb38868 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_slow + 220
  frame #3: 0x0000000100c39b58 ruby`rb_native_mutex_lock(lock=0x0000000100f18200) at thread_pthread.c:125:14 [inlined]
  frame #4: 0x0000000100c39b50 ruby`thread_sched_lock_(sched=0x0000000100f18200, th=<unavailable>, file=<unavailable>, line=991) at thread_pthread.c:403:5 [inlined]
  frame #5: 0x0000000100c39b50 ruby`thread_sched_to_running(sched=0x0000000100f18200, th=0x0000000766d3ad00) at thread_pthread.c:991:5
  frame #6: 0x0000000100c2feb8 ruby`blocking_region_end(th=0x0000000766d3ad00, region=0x000000016fdf5a04) at thread.c:1554:5
  frame #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 #8: 0x0000000100ae8470 ruby`garbage_collect_with_gvl(objspace=0x0000000767008000, reason=512) at default.c:7001:15
  frame #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 #10: 0x0000000100ad2d74 ruby`objspace_malloc_fixup(objspace=0x0000000767008000, mem=0x0000000767892010, size=40, gc_allowed=true) at default.c:8436:5 [inlined]
  frame #11: 0x0000000100ad2d5c ruby`rb_gc_impl_calloc(objspace_ptr=0x0000000767008000, size=40, gc_allowed=true) at default.c:8562:12 [inlined]
  frame #12: 0x0000000100ad2ce0 ruby`ruby_xcalloc_body(n=<unavailable>, size=<unavailable>) at gc.c:5467:12 [inlined]
  frame #13: 0x0000000100ad2c80 ruby`ruby_xcalloc(n=<unavailable>, size=<unavailable>) at gc.c:5461:34
  frame #14: 0x0000000100ad2bd0 ruby`rb_data_typed_object_zalloc(klass=<unavailable>, size=40, type=0x0000000101184010) at gc.c:1198:21
  frame #15: 0x0000000101180e30 instrumentation.bundle`GT_LOCAL_STATE + 84
  frame #16: 0x0000000101180d18 instrumentation.bundle`gt_thread_callback + 204
  frame #17: 0x0000000100c29aa0 ruby`rb_thread_execute_hooks(event=4, th=0x0000000766d3ad00) at thread_pthread.c:3556:17
  frame #18: 0x0000000100c29d24 ruby`thread_sched_wait_running_turn(sched=<unavailable>, th=<unavailable>, can_direct_transfer=<unavailable>) at thread_pthread.c:949:5 [artificial]
  frame #19: 0x0000000100c39c70 ruby`thread_sched_to_running_common(sched=0x0000000100f18200, th=0x0000000766d3ad00) at thread_pthread.c:972:5 [inlined]
  frame #20: 0x0000000100c39b5c ruby`thread_sched_to_running(sched=0x0000000100f18200, th=0x0000000766d3ad00) at thread_pthread.c:993:9
  frame #21: 0x0000000100c2feb8 ruby`blocking_region_end(th=0x0000000766d3ad00, region=0x000000016fdf5a04) at thread.c:1554:5
  frame #22: 0x0000000100c2fa68 ruby`rb_nogvl(func=<unavailable>, data1=<unavailable>, ubf=<unavailable>, data2=<unavailable>, flags=<unavailable>) at thread.c:1629:5
  frame #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.

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.
@luke-gruber

luke-gruber commented Jun 9, 2026

Copy link
Copy Markdown
Contributor Author

I think this is more of an issue on 4.1.0 because it has the "hot thread" optimization, but I'm not sure.

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 RESUMED callback to mention it doesn't hold the GVL.

@eregon

eregon commented Jun 10, 2026

Copy link
Copy Markdown

I would argue it's a CRuby bug if the RESUMED event, which notifies a Thread acquired the GVL isn't called on that Thread and with the GVL (if the thread got the GVL it can run now, so why call that event on another thread?).
I suspect other users of the RESUMED rely on that and notably the datadog gem does.

@luke-gruber

luke-gruber commented Jun 10, 2026

Copy link
Copy Markdown
Contributor Author

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.

@jhawthorn jhawthorn marked this pull request as ready for review June 11, 2026 19:30
@jhawthorn jhawthorn changed the title RESUMED shouldn't cause GC because it doesn't run with GVL Avoid allocation withing RESUMED hook Jun 15, 2026
@jhawthorn jhawthorn merged commit 87acb2f into Shopify:master Jun 15, 2026
4 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants