背景一条集成测试用 JRuby 并发执行外部命令开 5 个线程每个线程用反引号跑同一个转换工具最后断言 5 个返回码都正常。绝大多数时候它都能通过但 CI 上偶尔会红一次结果是[127, 50, 50, 50, 50]这里 50 是该工具约定的正常返回码。127 在 shell 里的意思是command not found。可这 5 路执行的是同一条命令另外 4 路都正常单独跑也从来没失败过。本地反复跑就是复现不出来。这篇文章记录了从定位到稳定复现的过程、背后的原理和规避方法文末附完整的复现脚本、Java agent 源码和日志。结论先说这是 JRuby 底层 jnr 库的一个 use-after-free 问题GC 在子进程读完参数之前就把命令串所在的 native 内存释放了。术语表文中的缩写和专有名词先列在这里读到不熟的词可以回来查。退出码与 shell词说明127shell 的退出码表示 command not found要执行的命令找不到2shell 的退出码这里表示命令串有语法错误EFAULTLinux 错误码 Bad address传给系统调用的地址无效sh -c让/bin/sh把后面的字符串当一条命令执行反引号 /%x{}Ruby 执行外部命令并拿到输出的写法进程启动词说明argv传给新进程的参数数组这里是[sh, -c, 命令]posix_spawnpC 库里创建子进程并执行程序的函数execve用新程序替换当前进程的系统调用子进程在这里读取argvglibcLinux 上的标准 C 库malloc、free、posix_spawnp都在里面JVM 与内存词说明GCGarbage Collection垃圾回收JVM 自动回收没有引用的对象栈函数的局部变量和参数调用时自动分配返回时自动释放堆运行中用malloc临时申请的内存用完要free。命令串在这里native 内存JVM 堆以外、用malloc申请给 C 代码用的内存也属于上面的堆finalizer / CleanerJava 对象被回收时执行的清理逻辑这里会free掉 native 内存use-after-free内存已经释放还有代码在读写它JITJust-In-Time 编译JVM 把热点代码编译成机器码竞争窗口race window内存已经可以回收、但还有人要读它的那段时间JRuby 底层词说明JRuby跑在 JVM 上的 Ruby 实现CRubyMRI官方的 C 语言 Ruby 实现没有 JVM GC也不经过 jnrGILGlobal Interpreter LockCRuby 同一时刻只让一个线程执行 Ruby 代码jnr-ffiJRuby 用来从 Java 调用 C 函数的库jnr-posix基于 jnr-ffi 封装的 POSIX 调用posix_spawnp从这里调generated stubjnr-ffi 默认为每个 C 函数自动生成的调用代码速度快reflection invoker反射调用jnr-ffi 的另一条较慢路径调用期间一直持有参数PostInvocationjnr-ffi 的回调接口让参数对象在 C 调用结束后才释放Reference.reachabilityFenceJDK 方法保证某个对象到这一行之前都不会被 GC 回收复现工具词说明Java agentJVM 启动时加载的插件可以在类加载时修改字节码java.lang.instrumentJDK 提供的 agent 接口ASM读写 Java 字节码的库JDK 内部自带一份规避方式词说明ProcessBuilderJDK 自己的启动外部进程接口不经过 jnrProcess.spawnRuby 启动子进程的方法在 JRuby 里同样走 jnr1. 现场线索CI 的 stderr 里有这样两行sh: line 1: $\214\177...: command not found两个线索sh收到的命令名是乱码。不是工具找不到是 shell 拿到的命令串本身已经坏了。乱码里有\177。它不是某个字段的名字而是一个字节的显示方式。下一节把它还原成一个堆地址。另外失败的那一路几乎不耗时工具根本没启动sh在解析命令名时就退出了。2. 命令串怎么变成了一个地址这块内存一开始放的就是命令比如tool --input /path/to/input.dat ...。失败时sh读到的却是一个地址。中间发生了三件事命令放在堆上GC 把这块内存释放了分配器又往里面写了下一个空闲块的地址。2.1 一个进程里的几块内存一台机器上的内存是同一块分类看的是谁在用、什么时候借、什么时候还。一个进程里常见的就这几块种类放什么谁管代码程序本身的指令启动时就定好一直在全局数据全局变量、常量启动时就定好一直在栈函数的局部变量、参数函数调用时自动借返回时自动还堆运行中才知道要多大的数据程序自己malloc用完自己free命令串是运行时才拼出来的长度不固定所以用malloc放在堆上。Java 程序里还要再分一层Java 堆new出来的对象由 GC 回收。代表这块命令的 Java 对象在这里。native 内存JVM 外面、用malloc申请的 C 内存。命令串的内容在这里也属于上面说的堆。2.2 GC 把代表它的对象收走了GCGarbage Collection垃圾回收判断对象是否还活着只看还有没有引用指向它不看你“打不打算继续用”。什么时候跑程序没法精确控制。jnr 把命令拷进 native 内存后用一个 Java 对象代表它。这个对象一旦没有引用GC 就回收它回收时对象的清理逻辑finalizer / Cleaner会free掉那块 native 内存。打个比方你把一张写着命令的纸条递给同事自己手里没留底。同事还没看清保洁阿姨GC看到“这张纸没人拿着”就收走了。于是有一条铁律C 函数还在用这块内存的时候代表它的 Java 对象必须一直被引用着。2.3free之后写进去的是下一个空闲块的地址free不会把内容擦成空白。分配器要记住“下一块空闲内存在哪”就把那个地址写进刚释放的这块内存。sh还以为这里是命令拿去执行读到的就是这个地址的字节于是报command not found。2.4\177是这个地址里的一个字节\177是八进制写法等于十六进制的0x7f。这个字节没法当字符显示shell 就写成\177。堆地址经常长成0x00007fxxxxxxxxxx。整段才是一个地址xxxxxxxxxx表示后面的数字每次运行都不同。例如0x00007f1234567890是一个完整的指针1234567890不是存在这个地址里的值。64 位 Linux 给程序用的地址最高到0x00007fffffffffff。分配器向系统要的大块堆内存通常放在靠近这个上限的位置所以地址以0x00007f开头。代码和栈不在这一带开头不是这个样子。地址在内存里按小端序存放低位字节在前。0x00007f1234567890实际摆成90 78 56 34 12 7f 00 00sh把这几个字节当成命令名其中的7f就显示成\177。旁边的\214、\005是同一个地址里的其他字节。乱码里出现\177说明这里已经不是命令而是分配器写进去的指针。3. JRuby 执行反引号的调用链在 JRuby 里执行cmd 21大致会走Kernel#backquote → 命令里有 等 shell 元字符决定通过 /bin/sh -c 执行 → jnr-posix: posix_spawnp(/bin/sh, [sh, -c, cmd], envp) → jnr-ffi: CharSequenceArrayParameterConverter.toNative 把 argv 里每个字符串拷进 native 内存生成一个 StringArray返回它的地址 → glibc posix_spawnp → 子进程 sh 读取 argv → execve问题出在toNative生成的StringArray它把地址交给 native 调用之后Java 侧不再持有它的引用。jnr-ffi 的这个转换器没有实现 PostInvocation不会在调用结束前保持对象存活。如果 GC 恰好发生在这个窗口里时间 ───────────────────────────────────────────── Java 线程 argv 拷到 native 内存 → 交出地址 → [等待 posix_spawnp] GC ↑ StringArray 不可达被回收finalizer free 掉内存 glibc ↑ 往刚 free 的块里写空闲链表指针 子进程 sh ↑ 读 argv读到的是指针字节结果就是命令串被改写sh报command not found返回 127命令串里恰好混进反引号之类的字符syntax error返回 2被释放的是 argv 指针数组本身Errno::EFAULT: Bad address。因为报错发生在sh解析命令名阶段命令末尾的21还没生效所以反引号捕获不到任何输出报错直接打在了父进程的 stderr 上。4. 竞争窗口以及用 sleep 拉大窗口4.1 竞争窗口上面时序图里从“Java 交出地址、不再引用StringArray”到“子进程sh读完 argv”中间有一段时间。这段时间里内存已经可以被回收但还有人要读它。只要 GC 落在这段时间里就会出错落在外面就什么事都没有。这段时间就叫竞争窗口race window。这个窗口非常短。实测把 GC 往后推 100 微秒就几乎碰不上了所以它是微秒到毫秒级的。这就是问题偶发的根本原因GC 每次都正常运行只是极少数时候恰好落进这个窄缝里。4.2 用 sleep 拉大窗口这是调试多线程 bug 的经典手法。假设你怀疑线程 A 在第 1 步和第 2 步之间有个漏洞线程 B 要正好插进来才会出错。窗口只有 1 微秒可能跑一万次才碰上一次。那就在第 1 步和第 2 步之间临时加一句sleep(0.1)把窗口从 1 微秒拉到 100 毫秒线程 B 几乎每次都能插进来bug 就变得稳定可复现。原本 A: 第1步 |1µs| 第2步 B 要正好插在这 1µs 里 加 sleepA: 第1步 |---- sleep 100ms ----| 第2步 B 很容易插进来它只是把本来就存在的窗口拉长不制造新的错误所以被认为是合法的复现手段。4.3 这次不能直接加 sleep这次的窗口在 jnr 的 native 调用内部Java 交出地址之后执行就进了 C 代码posix_spawnp什么时候 fork、子进程什么时候读 argv都在 C 和内核里。没法在中间插 sleep也不想改 JRuby。所以反过来做窗口拉不长就让 GC 准时出现在窗口开始的那一刻。这就是下面 Java agent 做的事。它和加 sleep 是同一个思路都是放大本来就存在的竞争不改写内存、不伪造错误。注意区分复现脚本里的假命令sleep 0.2; /bin/echo ...中的sleep 0.2和上面说的“加 sleep 拉大窗口”无关。它只是让子进程跑久一点模拟真实工具的耗时。5. 本地难以复现的原因要出错必须同时满足某个线程正处在posix_spawnp的竞争窗口里GC 正好在这个窗口里完成回收finalizer 也执行了free。这两件事各自都很常见但碰到同一瞬间的概率很低。CI 机器上同一个 JVM 里跑了大量用例垃圾多GC 频繁所以偶尔会撞上本地只跑一条用例几乎碰不到。6. 复现过程6.1 概率复现后台狂跑 GC开 5 个线程用反引号循环执行一条超过 256 字节的命令另开一个线程不停调用 GC。完整脚本见附录 A.1。我在 JRuby 9.2 上大约每 1000 次调用命中 0–3 次在 JRuby 10.0 上更容易一些。能出现但很难稳定。6.2 卡时机用 Java agent 把 GC 放到窗口开始的时刻写了一个很小的 Java agent用 JDK 自带的 instrument 机制只在CharSequenceArrayParameterConverter.toNative返回前插一句调用唤醒一个后台线程立刻执行 GC。完整源码见附录 B。agent 不读写任何内存。释放仍然是 jnr 自己的 finalizer 做的agent 只是把原本随机的 GC 挪到了窗口里。效果对比JRuby 9.2每组 1000 次调用条件命中次数不挂 agent0挂 agent10–14 次大部分是 127挂 agent但 GC 前延迟 ≥100 µs基本为 0挂 agent模拟真实节奏5 线程、每轮各调一次、子进程耗时5–17 次几乎全是 127最后用真实的转换命令、和测试完全相同的写法跑第 97 轮打出了 127日志见附录 C。乱码特征和 CI 完全一致。这一轮 5 路全挂是因为 agent 把 GC 卡在了 5 个线程同时 spawn 的时刻一次 GC 把所有人的 argv 一起回收了。CI 上 GC 是自然发生的只碰巧落在一路的窗口里所以只坏了一路。6.3 两个反直觉的发现限制 CPU 反而更难复现。我本以为 CPU 紧张会让子进程更晚读 argv、窗口更长。可实测绑到 2 个核以后4000 次调用一次都没命中。这个问题要求 GC 线程和 spawn 线程真正同时在跑核少了只能轮流执行反而撞不上。把堆调小帮助不大。关键在 GC 发生的时机不在 GC 的频率。7. 影响范围写法是否受影响反引号、%x{}是已验证Process.spawn是已验证GC 压力下出现过EFAULTsystem、IO.popen很可能是推断走同一路径未单独验证java.lang.ProcessBuilder否不经过 jnrCRubyMRI否没有 JVM GC也不经过 jnr我测过的 JRuby 9.2.21.0jnr-ffi 2.2.11和 JRuby 10.0.2.0jnr-ffi 2.2.17都有这个问题所以升级 JRuby 不能直接解决。8. 怎么避免8.1 推荐在 JRuby 里改用ProcessBuilder启动子进程JDK 的ProcessBuilder走 JDK 自己的进程创建代码参数在创建子进程期间由 JDK 持有不经过 jnr也就没有这个窗口。原来的公共方法是反引号版本测试文件里几十处都在调用它def run_capture(cmd) output #{cmd} 21 return $?.exitstatus, output end有两种改法。做法一直接改公共run_capture最直接的是把方法体换成 JDK 的ProcessBuilder方法名和返回值不变所有调用处自动生效。redirectErrorStream(true)就是原来的21require java def run_capture(cmd) pb java.lang.ProcessBuilder.new([/bin/sh, -c, cmd]) pb.redirectErrorStream(true) process pb.start output String.from_java_bytes(process.getInputStream.readAllBytes) return process.waitFor, output end不要换成Process.spawn它在 JRuby 里还是走 jnrpid Process.spawn(/bin/sh, -c, cmd) # 不行做法一的缺点是影响面大这个方法被几十处调用改了之后所有用例都换了启动方式而出问题的只有并发启动的那几条。做法二推荐新增方法只给并行用例用不改公共方法另加一个方法只让出问题的并行用例调用require java def run_capture_with_process_builder(cmd) pb java.lang.ProcessBuilder.new(/bin/sh, -c, cmd) pb.redirectErrorStream(true) # 相当于 21 process pb.start output String.from_java_bytes(process.getInputStream.readAllBytes) [process.waitFor, output] end并行用例里把run_capture(cmd)换成run_capture_with_process_builder(cmd)返回值仍然是[退出码, 输出]断言不用改。只改并行用例公共方法被几十处调用问题只在多线程并发启动时出现。单独加一个方法影响范围最小其他用例保持原样。会不会拖慢测试不会。多出来的只是一次进程启动方式的差别是毫秒级被调用的工具本身每轮要跑几十秒。这不是反射调用这里是通过 JRuby 的 Java 互操作直接调用 JDK 的ProcessBuilder完全绕开 jnr。下面 8.2 的反射调用是 jnr 内部的另一条路进程仍然经过 jnr 启动。如果不需要 shell 特性管道、重定向、通配符更好的做法是直接传 argv连 shell 解析都省掉pb java.lang.ProcessBuilder.new(/path/to/tool, --input, input, --output, output)验证情况在 JRuby 10.0 上后台线程持续强制 GC 的压力下ProcessBuilder版本跑了 3 轮各 1000 次0 次出错同样条件下反引号版本每轮命中 3–31 次。用真实工具五路并行结果全部正常。还没有在 agent 卡时机的条件下验证。8.2 另一条路关闭 jnr 的 generated stubjnr-ffi 默认为 C 函数生成 generated stub问题就出在这段代码交出地址后不再持有参数。可以用一个系统属性关掉它让 jnr-ffi 改走 reflection invoker反射调用。反射调用会把参数一直持有到posix_spawnp返回窗口就没了export JRUBY_OPTS${JRUBY_OPTS:$JRUBY_OPTS }-J-Djnr.ffi.asm.enabledfalse它能一次覆盖进程里所有的反引号、system、popen但有两个代价所有经过 jnr 的调用都会变慢。不只是启动进程File.exist?这类文件操作也走 jnr。实测 20 万次File.exist?从 0.28 秒增加到 0.42 秒单次约多 0.7 微秒整套测试会慢多少要另外测。要改全局启动参数。一般加在测试框架的环境脚本里所有测试进程都受影响。框架不归你管时这不是改一个用例能决定的事。改不了 JRuby、也不方便动框架时用 8.1 只改出问题的用例。上游对应的 issue 是 jnr/jnr-ffi#358。8.3 不要用Process.spawn来“修”Process.spawn在 JRuby 里同样走 jnr 的posix_spawnpGC 压力下出现过EFAULT。从反引号换成Process.spawn只是换了个写法问题还在。8.4 加锁串行化 spawn不能当修复直觉上会想给反引号加一把Mutex让 5 个线程排队 spawn是不是就好了这能减少“一个线程的 GC 撞上另一个线程的窗口”但 GC 的来源不只是这几个线程JVM 里任何地方分配内存都可能触发 GC单个 spawn 的窗口依然存在。所以它最多降低概率不能消除问题而且会让并行测试变成串行失去测试意义。我没有用数据验证过它的效果不推荐。8.5 测试代码里顺手要改的多线程收集结果要线程安全。复现那一轮 5 路全部失败结果数组里却只有 4 个值text results[127, 127, 2, 127]原因是多个线程同时往同一个 Array 里。CRuby 有 GIL 兜着问题不明显JRuby 的线程是真并行的Array 不是线程安全的并发追加会丢元素。改法ruby results threads.map(:value) # 每个线程把 rc 作为返回值 # 或者 lock Mutex.new lock.synchronize { results rc }失败时把每一路的输出打出来。原测试把输出丢掉了rc, _out ...CI 失败时只看得到[127, 50, ...]看不到是哪一路、报了什么。断言信息里带上失败那一路的输出下次一眼就能定位。8.6 如果你是写 native 绑定的库作者根本原则把内存地址交给 C 函数期间代表这块内存的 Java 对象必须保持可达。常见做法native 调用结束后再用一次这个对象或者调用java.lang.ref.Reference.reachabilityFence(obj)告诉 JIT 和 GC 它在这之前一直活着在 jnr-ffi 里实现ToNativeConverter.PostInvocation让框架在调用结束后才释放参数对象。8.7 上报上游这是 jnr-ffi / JRuby 的缺陷上游已有 issue jnr/jnr-ffi#358可以附上附录里的复现脚本和 agent 补充。在上游修复之前业务代码按 8.1 绕开。这次的处理这是 JRuby 底层 jnr 库的 GC 问题JRuby 本身改不了。只在并行用例里改用 Java 的ProcessBuilder启动命令绕开 jnr不影响其他用例也不拖慢测试。并行用例偶发 127是sh拿到的命令串变成了乱码被测工具根本没启动。反引号通过 jnr 把命令拷进 native 内存后不再持有对应的 Java 对象GC 正好在子进程读命令之前把它释放了。改法是给并行用例加一个用ProcessBuilder启动命令的方法参数由 JDK 持有不再经过 jnr。公共的run_capture不动其他用例照旧。也可以在进程启动参数里关掉 jnr 的 generated stub但所有 jnr 调用都会变慢所以只改用例更合适。9. 排查经验小结先看退出码和耗时。127 加上几乎为 0 的耗时说明命令根本没执行不要去查被调用的程序。乱码里有\177/0x7f就往 use-after-free 的方向想。这是 64 位堆指针的高位字节。“本地复现不了”不等于“环境问题”。时序类 bug 要主动放大条件加并发、加 GC 压力、卡准时机。区分“复现”和“制造问题”。放大自然条件更多 GC、卡准时机、拉大窗口是复现直接改写内存只能验证后果证明不了成因。确认实际运行的版本。测试框架里的子进程用的 JRuby 版本可能和你 PATH 里的不一样。我一开始就分析错了版本。一句话总结GC 只认引用不认意图。交给 C 函数的内存只要 Java 侧手里没拿着就可能被提前收走。附录 A复现脚本Ruby运行环境JRuby 9.2.21.0Java 21。A.1 概率复现后台狂跑 GCrepro_backtick_gc.rbrequire java LONG /tmp/ (p * 300) stop false hits [] lock Mutex.new gc Thread.new do until stop java.lang.System.gc java.lang.System.runFinalization Array.new(2000) { x * 100 } end end workers 5.times.map do |i| Thread.new do 200.times do |n| cmd /bin/echo OK #{i}-#{n} #{LONG} 21 begin out #{cmd} rc $?.exitstatus lock.synchronize { hits [i, n, rc, out] } if rc ! 0 || !out.start_with?(OK) rescue e lock.synchronize { hits [i, n, e.class.to_s, e.message[0, 80]] } end end end end workers.each(:join) stop true gc.join hits.first(5).each { |h| p h } puts hits#{hits.size} of 1000运行JAVA_HOME/usr/lib/jvm/java-21 jruby -J-Xmx64m repro_backtick_gc.rbA.2 echo 连续调用配合 agentecho_timed.rb不开后台 GC 线程GC 时机完全由 agent 控制。run_capture和原测试的写法一致。def run_capture(cmd) output #{cmd} 21 return $?.exitstatus, output end LONG /tmp/ (p * 300) hits [] lock Mutex.new workers 5.times.map do |i| Thread.new do 200.times do |n| begin rc, out run_capture(/bin/echo OK #{i}-#{n} #{LONG}) lock.synchronize { hits [i, n, rc, out[0, 160]] } if rc ! 0 || !out.start_with?(OK) rescue e lock.synchronize { hits [i, n, e.class.to_s, e.message[0, 80]] } end end end end workers.each(:join) hits.first(3).each { |h| p h } puts hits#{hits.size} of 1000 rc127#{hits.count { |h| h[2] 127 }}运行JAVA_HOME/usr/lib/jvm/java-21 jruby -J-javaagent:/path/to/crgc-agent.jar echo_timed.rbA.3 模拟真实测试节奏pattern_sim.rb每轮开 N 个线程每个线程只调用一次子进程先sleep 0.2模拟耗时和原测试的调用节奏一致。def run_capture(cmd) output #{cmd} 21 return $?.exitstatus, output end threads_n (ENV[THREADS] || 5).to_i iters (ENV[ITERS] || 200).to_i LONG /tmp/ (p * 300) calls 0 bad [] lock Mutex.new iters.times do |it| ths threads_n.times.map do |i| Thread.new do begin rc, out run_capture(sleep 0.2; /bin/echo OK #{it}-#{i} #{LONG}) lock.synchronize { bad [it, i, rc, out[0, 120]] } if rc ! 0 rescue e lock.synchronize { bad [it, i, e.class.to_s] } end end end ths.each(:join) calls threads_n end bad.first(2).each { |b| p b } puts threads#{threads_n} calls#{calls} hits#{bad.size} rc127#{bad.count { |b| b[2] 127 }}运行THREADS5 ITERS200 JAVA_HOME/usr/lib/jvm/java-21 \ jruby -J-javaagent:/path/to/crgc-agent.jar pattern_sim.rbA.4 真实命令复现real_cmd_repro.rb和原测试的写法一致5 个线程每轮各执行一次真实转换命令期望返回码为 50。下面用通用路径代替当时的工具和输入文件。require fileutils CONVERTER /path/to/converter INPUT_FILE /path/to/input.dat KEY_FILE /path/to/key EXPECTED_RC 50 def run_capture(cmd) output #{cmd} 21 return $?.exitstatus, output end def one_iteration threads [] results [] outputs {} 5.times do |i| threads Thread.new do out_file File.join(/tmp, parallel_out_#{i}_#{Time.now.to_f}.bin) cmd #{CONVERTER} --input #{INPUT_FILE} --key #{KEY_FILE} --output #{out_file} rc, out run_capture(cmd) FileUtils.rm_f(out_file) results rc # 保留原测试的写法非线程安全见 8.5 outputs[i] out unless rc EXPECTED_RC end end threads.each(:join) [results, outputs] end max (ENV[MAX_ITER] || 100).to_i max.times do |n| t0 Time.now begin results, outputs one_iteration rescue e puts iteration #{n 1}: exception #{e.class}: #{e.message[0, 200]} next end puts iteration #{n 1}: results#{results.inspect} (#{(Time.now - t0).round(1)}s) $stdout.flush next if results.all? { |rc| rc EXPECTED_RC } outputs.each { |i, out| puts thread #{i} output: #{out.inspect[0, 600]} } puts Not all parallel executions returned rc#{EXPECTED_RC}: #{results.inspect} break if results.include?(127) end运行MAX_ITER150 JAVA_HOME/usr/lib/jvm/java-21 nice -n 19 \ jruby -J-javaagent:/path/to/crgc-agent.jar real_cmd_repro.rb real_run.log 21附录 B卡 GC 时机的 Java agent 源码三个类只依赖 JDK 21 自带的java.lang.instrument和 JDK 内置的 ASMjdk.internal.org.objectweb.asm。B.1Agent.javapackage crgc; import java.lang.instrument.Instrumentation; import java.util.Map; import java.util.Set; public final class Agent { public static void premain(String args, Instrumentation inst) { Module self Agent.class.getModule(); Module javaBase Object.class.getModule(); // 让 agent 能访问 JDK 内置的 ASM inst.redefineModule(javaBase, Set.of(), Map.of(jdk.internal.org.objectweb.asm, Set.of(self)), Map.of(), Set.of(), Map.of()); inst.addTransformer(new Transformer(inst)); System.err.println([crgc] agent installed); } }B.2Transformer.javapackage crgc; import java.lang.instrument.ClassFileTransformer; import java.lang.instrument.Instrumentation; import java.security.ProtectionDomain; import java.util.Map; import java.util.Set; import jdk.internal.org.objectweb.asm.ClassReader; import jdk.internal.org.objectweb.asm.ClassVisitor; import jdk.internal.org.objectweb.asm.ClassWriter; import jdk.internal.org.objectweb.asm.MethodVisitor; import jdk.internal.org.objectweb.asm.Opcodes; final class Transformer implements ClassFileTransformer { private static final String TARGET jnr/ffi/provider/converters/CharSequenceArrayParameterConverter; private static final String DESC ([Ljava/lang/CharSequence;Ljnr/ffi/mapper/ToNativeContext;)Ljnr/ffi/Pointer;; private final Instrumentation inst; Transformer(Instrumentation inst) { this.inst inst; } Override public byte[] transform(Module module, ClassLoader loader, String className, Class? redefined, ProtectionDomain pd, byte[] bytes) { if (!TARGET.equals(className)) return null; try { // jruby.jar 是具名模块需要让它能读到 agent 所在的模块 if (module.isNamed()) { inst.redefineModule(module, Set.of(Trigger.class.getModule()), Map.of(), Map.of(), Set.of(), Map.of()); } ClassReader cr new ClassReader(bytes); ClassWriter cw new ClassWriter(cr, ClassWriter.COMPUTE_MAXS); cr.accept(new ClassVisitor(Opcodes.ASM9, cw) { Override public MethodVisitor visitMethod(int access, String name, String desc, String sig, String[] ex) { MethodVisitor mv super.visitMethod(access, name, desc, sig, ex); if (!toNative.equals(name) || !DESC.equals(desc)) return mv; return new MethodVisitor(Opcodes.ASM9, mv) { Override public void visitInsn(int opcode) { // 在 toNative 返回前插入 Trigger.fire() if (opcode Opcodes.ARETURN) { super.visitMethodInsn(Opcodes.INVOKESTATIC, crgc/Trigger, fire, ()V, false); } super.visitInsn(opcode); } }; } }, 0); System.err.println([crgc] instrumented className (module module )); return cw.toByteArray(); } catch (Throwable t) { System.err.println([crgc] transform failed: t); return null; } } }B.3Trigger.javapackage crgc; import java.util.concurrent.Semaphore; import java.util.concurrent.atomic.AtomicLong; import java.util.concurrent.locks.LockSupport; /** jnr 生成 native argv 后唤醒后台线程立刻执行一次真实的 GC finalization。 */ public final class Trigger { private static final Semaphore PENDING new Semaphore(0); public static final AtomicLong FIRES new AtomicLong(); public static final AtomicLong GCS new AtomicLong(); private static final long DELAY_NS Long.getLong(crgc.delayUs, 0L) * 1000L; static { Thread t new Thread(() - { while (true) { PENDING.acquireUninterruptibly(); PENDING.drainPermits(); if (DELAY_NS 0) LockSupport.parkNanos(DELAY_NS); System.gc(); System.runFinalization(); GCS.incrementAndGet(); } }, crgc-trigger); t.setDaemon(true); t.start(); Runtime.getRuntime().addShutdownHook(new Thread(() - System.err.println([crgc] toNative fires FIRES.get() gcs GCS.get()))); } private Trigger() {} public static void fire() { FIRES.incrementAndGet(); PENDING.release(); } }-Dcrgc.delayUs微秒可以在 GC 前加延迟用来测窗口有多宽。B.4 编译和打包JH/usr/lib/jvm/java-21 mkdir -p out $JH/bin/javac --add-exports java.base/jdk.internal.org.objectweb.asmALL-UNNAMED -d out src/crgc/*.java printf Premain-Class: crgc.Agent\n manifest.txt $JH/bin/jar cfm crgc-agent.jar manifest.txt -C out .使用时给 JRuby 加-J-javaagent:/path/to/crgc-agent.jar即可。附录 C关键日志C.1 真实命令复现real_cmd_repro.rb第 97 轮命中[crgc] agent installed [crgc] instrumented jnr/ffi/provider/converters/CharSequenceArrayParameterConverter (modulemodule org.jruby.dist) iteration 1: results[50, 50, 50, 50, 50] (277.6s) iteration 2: results[50, 50, 50, 50, 50] (288.3s) ... iteration 95: results[50, 50, 50, 50, 50] (80.0s) iteration 96: results[50, 50, 50, 50, 50] (79.7s) sh: line 1: $\360\f: command not found sh: line 1: $\360: command not found sh: -c: line 1: unexpected EOF while looking for matching sh: -c: line 2: syntax error: unexpected end of file sh: line 1: $G\005$\244\177: command not found sh: line 1: $\360R: command not found iteration 97: results[127, 127, 2, 127] (0.1s) thread 1 output: thread 2 output: thread 3 output: thread 0 output: thread 4 output: Not all parallel executions returned rc50: [127, 127, 2, 127] [crgc] toNative fires970 gcs245怎么读前 96 轮同一条命令都正常第 97 轮 5 路命令串全被改写成乱码。\244\177是堆地址高位字节说明这块内存被 glibc 当成空闲块写进了指针。本轮只用 0.1 秒正常一轮约 80 秒说明真实工具一次都没启动。一路返回 2乱码里恰好有个反引号字符触发了语法错误。5 路都失败results只有 4 个值多线程results rc丢了一个元素。每一路的output都是空的报错发生在21生效之前打到了父进程的 stderr。中途有十几轮因为环境原因返回 1与本问题无关。C.2 echo 连续调用echo_timed.rb### without agent hits0 of 1000 rc1270 ### with agent round 1 sh: line 1: 0*: command not found [2, 82, Errno::EFAULT, Bad address - /bin/echo OK 2-82 /tmp/ppppppppppppppppppppppppppppppppppppppppppp] hits14 of 1000 rc1276 ### with agent round 2 sh: line 1: $0\v\002\214t\177: command not found [3, 149, 127, ] hits13 of 1000 rc1279 ### with agent round 3 sh: line 1: PN: command not found hits10 of 1000 rc1277$0\v\002\214t\177中的\214…\177和 CI 日志里的乱码是同一种特征。Errno::EFAULT是被释放的恰好是 argv 指针数组本身。C.3 GC 延迟对比echo_timed.rb-Dcrgc.delayUsdelayUs0 : hits6, 7 delayUs100 : hits0, 0 delayUs300 : hits1, 0 delayUs1000 : hits0, 0 delayUs3000 : hits0, 0GC 只要晚 100 微秒就几乎碰不上说明竞争窗口在微秒级。C.4 模拟真实节奏pattern_sim.rb[83, 4, 127, ] [83, 0, 127, ] threads5 calls1000 hits17 rc12716 threads5 calls1000 hits5 rc1275 threads20 calls1000 hits15 rc12711[83, 4, 127, ]表示第 83 轮、4 号线程、返回 127、没有捕获到输出。同一轮里经常有多个线程一起中招。