Issue #22396 has been updated by Eregon (Benoit Daloze). 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) ---------------------------------------- Bug #22396: Using rb_postponed_job_trigger causes YJIT/ZJIT compiled methods side exits https://bugs.ruby-lang.org/issues/22396#change-119411 * Author: ivoanjo (Ivo Anjo) * Status: Assigned * Assignee: jit * 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] * Backport: 3.3: UNKNOWN, 3.4: UNKNOWN, 4.0: UNKNOWN ---------------------------------------- Hey 👋. So at Datadog, while working on the [datadog ruby profiler](https://github.com/DataDog/dd-trace-rb/) 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) -- https://bugs.ruby-lang.org/