Project

General

Profile

Actions

Bug #22396

closed

Using rb_postponed_job_trigger causes YJIT/ZJIT compiled methods side exits

Bug #22396: Using rb_postponed_job_trigger causes YJIT/ZJIT compiled methods side exits

Added by ivoanjo (Ivo Anjo) 23 days ago. Updated 3 days ago.

Status:
Closed
Assignee:
Target version:
-
ruby -v:
ruby 4.0.6 (2026-07-14 revision 03b6d3f889) +YJIT +PRISM [x86_64-linux] / ruby 4.1.0dev (2026-09-28T09:36:41Z master d939272e7d) +YJIT +PRISM [x86_64-linux]
[ruby-core:126892]

Description

Hey 👋. So at Datadog, while working on the datadog ruby profiler we've uncovered something that may-or-may-not be a bug, but really surprised us so I wanted to open up a ticket to discuss.

Our profiler uses a design where we interrupt Ruby using a SIGPROF signal, collect frames from inside the signal handler (using our homegrown copy of rb_profile_frames) and then use rb_postponed_job_trigger to get to a safepoint where we can process the data.

Unfortunately, we weren't aware of rb_postponed_job_trigger causing JIT side exits! For small methods this is hard to measure, but with a reasonably long-running loop, this becomes measurable.

I've built (with AI friend) a reproducer for this. Out of curiosity I also added support for stackprof and rperf which also use a similar design (vernier doesn't! :D) to discard it being something else in the Datadog profiler design.

Here's how it looks with just interpreter:

$ PROFILER=datadog be ruby  --disable-yjit --disable-zjit profiling_jit.rb
Profiler: datadog

ruby 4.0.6 (2026-07-14 revision 03b6d3f889) +PRISM [x86_64-linux]
Calculating -------------------------------------
              Warmup     21.511 (± 4.6%) i/s   (46.49 ms/i) -    108.000 in   5.020785s
Calculating -------------------------------------
        Profiler off     21.974 (± 4.6%) i/s   (45.51 ms/i) -    110.000 in   5.005813s
Calculating -------------------------------------
         Profiler on     20.865 (± 4.8%) i/s   (47.93 ms/i) -    105.000 in   5.032376s
Calculating -------------------------------------
  Profiler off again     21.455 (± 9.3%) i/s   (46.61 ms/i) -    108.000 in   5.033813s

Comparison:
      Profiler off:       22.0 i/s
Profiler off again:       21.5 i/s - same-ish: difference falls within error
       Profiler on:       20.9 i/s - same-ish: difference falls within error

Here's how it looks with YJIT (ZJIT shows similar results):

$ PROFILER=datadog bundle exec ruby --yjit --yjit-call-threshold=1 profiling_jit.rb
Profiler: datadog

ruby 4.0.6 (2026-07-14 revision 03b6d3f889) +YJIT +PRISM [x86_64-linux]
Calculating -------------------------------------
              Warmup    192.433 (± 5.7%) i/s    (5.20 ms/i) -    963.000 in   5.004347s
Calculating -------------------------------------
        Profiler off    192.959 (± 5.2%) i/s    (5.18 ms/i) -    965.000 in   5.001050s
Calculating -------------------------------------
         Profiler on     50.250 (± Inf%) i/s   (19.90 ms/i) -    253.000 in   5.034844s
Calculating -------------------------------------
  Profiler off again    192.072 (± 6.2%) i/s    (5.21 ms/i) -    961.000 in   5.003330s

Comparison:
      Profiler off:      193.0 i/s
Profiler off again:      192.1 i/s - same-ish: difference falls within error
       Profiler on:       50.2 i/s - 3.84x  slower

...and here's with YJIT stats to show the side exits count going up:

$ PROFILER=datadog bundle exec ruby --yjit --yjit-call-threshold=1 --yjit-stats=quiet profiling_jit.rb
Profiler: datadog

ruby 4.0.6 (2026-07-14 revision 03b6d3f889) +YJIT +PRISM [x86_64-linux]
Calculating -------------------------------------
              Warmup      2.246 (± 0.0%) i/s  (445.30 ms/i) -     12.000 in   5.343558s
Side exits: 2
Calculating -------------------------------------
        Profiler off      2.512 (± 0.0%) i/s  (398.08 ms/i) -     13.000 in   5.175023s
Side exits: 1
Calculating -------------------------------------
         Profiler on     19.632 (± 5.1%) i/s   (50.94 ms/i) -     99.000 in   5.042706s
Side exits: 101
Calculating -------------------------------------
  Profiler off again      2.505 (± 0.0%) i/s  (399.12 ms/i) -     13.000 in   5.188599s
Side exits: 1

Comparison:
       Profiler on:       19.6 i/s
      Profiler off:        2.5 i/s - 7.82x  slower
Profiler off again:        2.5 i/s - 7.84x  slower

(Funnily enough, because --yjit-stats=quiet makes the JITted code slower than interpreter, the fact that the profiler forces the code to go back to the interpreter means the code speeds up since interpreter goes vroom)

Thus my question is -- is this "rb_postponed_job_trigger always triggers side exit" behavior something that we'll need to work with (possibly adopting a design closer to vernier), or is this something that could be fixed in YJIT or ZJIT to avoid the footgun?


Some extra data points:

  • stackprof + master + yjit:
$ PROFILER=stackprof ruby --yjit --yjit-call-threshold=1 profiling_jit.rb
Profiler: stackprof

ruby 4.1.0dev (2026-09-28T09:36:41Z master d939272e7d) +YJIT +PRISM [x86_64-linux]
Calculating -------------------------------------
              Warmup    190.831 (± 7.9%) i/s    (5.24 ms/i) -    954.000 in   4.999178s
Calculating -------------------------------------
        Profiler off    192.096 (± 6.2%) i/s    (5.21 ms/i) -    961.000 in   5.002707s
Calculating -------------------------------------
         Profiler on      2.621 (± 0.0%) i/s  (381.54 ms/i) -     14.000 in   5.341527s
Calculating -------------------------------------
  Profiler off again    187.173 (± 8.5%) i/s    (5.34 ms/i) -    936.000 in   5.000721s

Comparison:
      Profiler off:      192.1 i/s
Profiler off again:      187.2 i/s - same-ish: difference falls within error
       Profiler on:        2.6 i/s - 73.29x  slower
  • stackprof + master + zjit:
$ PROFILER=stackprof ruby --zjit --zjit-call-threshold=2 profiling_jit.rb
Profiler: stackprof

ruby 4.1.0dev (2026-09-28T09:36:41Z master d939272e7d) +ZJIT +PRISM [x86_64-linux]
Calculating -------------------------------------
              Warmup    178.615 (±11.2%) i/s    (5.60 ms/i) -    893.000 in   4.999570s
Calculating -------------------------------------
        Profiler off    196.171 (± 3.6%) i/s    (5.10 ms/i) -    981.000 in   5.000751s
Calculating -------------------------------------
         Profiler on      2.584 (± 0.0%) i/s  (386.97 ms/i) -     13.000 in   5.030555s
Calculating -------------------------------------
  Profiler off again    192.681 (± 6.2%) i/s    (5.19 ms/i) -    964.000 in   5.003085s

Comparison:
      Profiler off:      196.2 i/s
Profiler off again:      192.7 i/s - same-ish: difference falls within error
       Profiler on:        2.6 i/s - 75.91x  slower

Files

profiling_jit.rb (2.62 KB) profiling_jit.rb ivoanjo (Ivo Anjo), 09/30/2026 09:53 AM

Related issues 1 (1 open — 0 closed)

Related to Ruby - Feature #21539: Export symbols for external profiling of stripped shared Ruby buildsOpenActions

Updated by mame (Yusuke Endoh) 17 days ago Actions #1

  • Status changed from Open to Assigned
  • Assignee set to jit

Updated by Eregon (Benoit Daloze) 14 days ago Actions #2 [ruby-core:127012]

Draft of a potential fix: https://github.com/ruby/ruby/pull/18205

I have tried several things to avoid overhead on the the no-interrupt-path but they mostly failed, I guess the YJIT backend doesn't really support generating code with control flow, or at least saving registers only under some condition (there is an interrupt) and merging properly after.

I think one important thing to assess here is how much it affects realistic programs/applications.
The repro here uses a very long loop which is expected to be the worse case (cannot reenter JITed until the loop is done in interpreter).

Updated by Eregon (Benoit Daloze) 14 days ago Actions #3 [ruby-core:127013]

I think maybe the bigger issue here is that profiling a program using YJIT or ZJIT might give very misleading results, because the action of profiling itself (if the profiler uses postponed jobs and many do) has the unexpected side effect to cause JITed code to deoptimize, and potentially take a long time to get back to JITed code if there are any long loops (maybe rare-ish for Rails, but might not be the case for Ruby programs in general).
Note that even Integer#times loop are affected significantly (Integer#times is defined in Ruby and uses while internally).

So the profile might show "lots of time spent in #long_loop but actually it's not true, it's just a side effect of the JITs not supporting postponed jobs without deoptimizing, and it wouldn't happen when not profiling, so it might not be the bottleneck at all.

(on a losely-related note I have also tried the opentelemetry EBPF profiler with YJIT, which avoids this issue by observing the process externally, but it doesn't seem to work well, notably it fails to walk the stack of JITed frames)

Updated by ivoanjo (Ivo Anjo) 14 days ago Actions #4 [ruby-core:127014]

Yeah I guess there's two bits here:

  • How should profilers proceed to not make JIT sad
  • How can JIT tell profilers what's going on so profilers aren't sad

Updated by alanwu (Alan Wu) 4 days ago 1Actions #5 [ruby-core:127162]

  • Status changed from Assigned to Closed

Postponed jobs are overall not great for sample collection because it's biased: C methods can run arbitrarily long without checking interrupts which then frames whatever ruby method afterwards with many samples. We've seen this happen with unhelpful profiles that claim all time is spent in the tiny Thread.current. There's probably many other situations I'm forgetting where you have gaps in the timeline where postponed jobs don't trigger or when trigger points are temporally concentrated.

How should profilers proceed to not make JIT sad
How can JIT tell profilers what's going on so profilers aren't sad

For both YJTI and ZJIT, use --[y,z]jit-perf and unwind-based profilers like Linux perf(1) or Samply (works on macOS). This make the JIT generate a perf map that conforms to a perf interface that was originally added for continuous profiling for JVMs. You do have to pay in space and time to generate the mapping, but the idea is that the profiles you get help you speed up your app so you profit overall.

Thus my question is -- is this "rb_postponed_job_trigger always triggers side exit" behavior something that we'll need to work with (possibly adopting a design closer to vernier), or is this something that could be fixed in YJIT or ZJIT to avoid the footgun?

We won't touch it for YJIT. We might change it for ZJIT because side exits are more expensive and interrupt checking is also used for thread switching internally. But, if we change it it will not be for postponed job based profilers.

Happy to have more discussions about this topic, but closing this as this is not a clear bug.

Updated by alanwu (Alan Wu) 4 days ago Actions #6

  • Related to Feature #21539: Export symbols for external profiling of stripped shared Ruby builds added

Updated by ivoanjo (Ivo Anjo) 4 days ago Actions #7 [ruby-core:127167]

Sounds reasonable, thanks very much for chiming in!

Postponed jobs are overall not great for sample collection because it's biased: C methods can run arbitrarily long without checking interrupts which then frames whatever ruby method afterwards with many samples. We've seen this happen with unhelpful profiles that claim all time is spent in the tiny Thread.current. There's probably many other situations I'm forgetting where you have gaps in the timeline where postponed jobs don't trigger or when trigger points are temporally concentrated.

To be clear, both stackprof and the datadog profiler avoid this because they still sample the stack inside the signal handler -- the postponed jobs mechanism handles only the recording of the stack (which might e.g. involve expanding memory and whatnot which can't be done safely there).

For both YJTI and ZJIT, use --[y,z]jit-perf and unwind-based profilers like Linux perf(1) or Samply (works on macOS). This make the JIT generate a perf map that conforms to a perf interface that was originally added for continuous profiling for JVMs. You do have to pay in space and time to generate the mapping, but the idea is that the profiles you get help you speed up your app so you profit overall.

This a great tip -- I vaguely vaguely remember seeing this mentioned before but haven't yet experimented with it yet, on the todo list it goes as an excellent lead :)

Updated by alanwu (Alan Wu) 3 days ago · Edited 1Actions #8 [ruby-core:127176]

To be clear, both stackprof and the datadog profiler avoid this because they still sample the stack inside the signal handler -- the postponed jobs mechanism handles only the recording of the stack (which might e.g. involve expanding memory and whatnot which can't be done safely there).

Sorry, my mistake; I'd missed that part of OP.

My stance that there's no clear bug here doesn't change, though. Postponed jobs are a way to inject/push work into a thread, and side exits (in YJIT) is a reasonable way to handle work injection. If you inject work frequently, well, that's directly modifying the profile of the workload. (The synthetic situation in OP is well, not from real life.) You could maybe move the sample processing to a separate thread with its own queue system, or trigger postponed jobs on that dedicated thread. But of course adding a thread has probe effects from GVL contention.

Given that we have external options for profiling like eBPF/perf that are clearly sharper when it comes to probe effects I would rather profilers focus on that instead of playing whack-a-mole with trying to add a mode to the VM while minimizing probe effect.

Updated by Eregon (Benoit Daloze) 3 days ago 1Actions #9 [ruby-core:127183]

alanwu (Alan Wu) wrote in #note-5:

interrupt checking is also used for thread switching internally

Interesting.
I could reproduce a very similar issue but with no profiler or postponed job at all:

$ ruby -v --yjit --yjit-call-threshold=2 -rbenchmark -e '10.times { p Benchmark.realtime { sum = 0; 150_000_000.times { |i| sum = (sum + i) % 77 } } }'
ruby 4.0.7 (2026-09-15 revision 229531a6cf) +YJIT +PRISM [arm64-darwin25]
2.4568690000014612
0.9585189999925205
0.939632999987225
0.9393829999899026
0.9473690000013448
0.9580200000054901
0.9488700000074459
0.9560230000060983
0.9418580000055954
0.9456040000077337

Same but with an extra Thread sleeping 100ms in a loop:

$ ruby -v --yjit --yjit-call-threshold=2 -rbenchmark -e 'Thread.new { loop { sleep 0.1 } }; 10.times { p Benchmark.realtime { sum = 0; 150_000_000.times { |i| sum = (sum + i) % 77 } } }'
ruby 4.0.7 (2026-09-15 revision 229531a6cf) +YJIT +PRISM [arm64-darwin25]
2.7225329999928363
2.7213770000089426
2.5856759999878705
2.7336639999994077
2.5711339999979828
2.552919000008842
2.5716880000109086
2.5426020000013523
2.48914700000023
2.642996000009589

While debugging this I also found that gc_sweep can use postponed jobs:

* thread #1, queue = 'com.apple.main-thread', stop reason = breakpoint 1.1
   * frame #0: 0x0000000100cb8ae8 libruby.4.0.dylib`rb_postponed_job_trigger
     frame #1: 0x0000000100afa30c libruby.4.0.dylib`gc_sweep_step + 372
     frame #2: 0x0000000100af92ac libruby.4.0.dylib`gc_sweep + 8664
     frame #3: 0x0000000100af6d50 libruby.4.0.dylib`gc_continue + 572
     frame #4: 0x0000000100af6898 libruby.4.0.dylib`newobj_cache_miss + 320
     frame #5: 0x0000000100aecfd8 libruby.4.0.dylib`newobj_of + 364
     frame #6: 0x0000000100c7de78 libruby.4.0.dylib`rb_vm_search_method_slowpath + 608
     frame #7: 0x0000000100c9b3ac libruby.4.0.dylib`vm_search_method_slowpath0 + 32
     frame #8: 0x0000000100edc520 libruby.4.0.dylib`opt_equality + 208
     frame #9: 0x0000000100c85e78 libruby.4.0.dylib`vm_exec_core + 15928

lldb doesn't show all C frames, looking at the code it must be gc_finalize_deferred_register called from gc_sweep_page called from gc_sweep_step.
So it's object finalizers, makes sense, those need a postponed job in the current CRuby semantics (the main alternative would be an extra thread to run them).

So thread switching and object finalizers are two sources of frequent interrupts, causing YJIT & ZJIT to side exit.
Of course, it's very visible in this very-long-running loop, and hopefully much less in most Ruby programs.

Actions

Also available in: PDF Atom