[ruby-core:126892] [Ruby Bug#22396] Using rb_postponed_job_trigger causes YJIT/ZJIT compiled methods side exits
Issue #22396 has been reported by ivoanjo (Ivo Anjo). ---------------------------------------- Bug #22396: Using rb_postponed_job_trigger causes YJIT/ZJIT compiled methods side exits https://bugs.ruby-lang.org/issues/22396 * Author: ivoanjo (Ivo Anjo) * Status: Open * 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/
Issue #22396 has been updated by Eregon (Benoit Daloze). 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). ---------------------------------------- Bug #22396: Using rb_postponed_job_trigger causes YJIT/ZJIT compiled methods side exits https://bugs.ruby-lang.org/issues/22396#change-119410 * 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/
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/
Issue #22396 has been updated by ivoanjo (Ivo Anjo). 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 ---------------------------------------- Bug #22396: Using rb_postponed_job_trigger causes YJIT/ZJIT compiled methods side exits https://bugs.ruby-lang.org/issues/22396#change-119412 * 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/
Issue #22396 has been updated by alanwu (Alan Wu). 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](https://github.com/mstange/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. ---------------------------------------- Bug #22396: Using rb_postponed_job_trigger causes YJIT/ZJIT compiled methods side exits https://bugs.ruby-lang.org/issues/22396#change-119571 * Author: ivoanjo (Ivo Anjo) * Status: Closed * 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/
Issue #22396 has been updated by ivoanjo (Ivo Anjo). 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 :) ---------------------------------------- Bug #22396: Using rb_postponed_job_trigger causes YJIT/ZJIT compiled methods side exits https://bugs.ruby-lang.org/issues/22396#change-119578 * Author: ivoanjo (Ivo Anjo) * Status: Closed * 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/
Issue #22396 has been updated by alanwu (Alan Wu).
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 effect 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. ---------------------------------------- Bug #22396: Using rb_postponed_job_trigger causes YJIT/ZJIT compiled methods side exits https://bugs.ruby-lang.org/issues/22396#change-119589 * Author: ivoanjo (Ivo Anjo) * Status: Closed * 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/
Issue #22396 has been updated by Eregon (Benoit Daloze). 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. ---------------------------------------- Bug #22396: Using rb_postponed_job_trigger causes YJIT/ZJIT compiled methods side exits https://bugs.ruby-lang.org/issues/22396#change-119599 * Author: ivoanjo (Ivo Anjo) * Status: Closed * 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/
participants (3)
-
alanwu (Alan Wu) -
Eregon (Benoit Daloze)
-
ivoanjo (Ivo Anjo)