原文标题:JVM/编译器/CPU,究竟谁是卧底?一个曾经困扰我一个月的 bug
原文作者:阿里云开发者
冷月清谈:
怜星夜思:
2、如何一步步定位到出错的文件?
3、为什么添加条件判断后问题就消失了?
原文内容
阿里妹导读
假设你是一个 Java 程序员,但你早已厌倦了什么 Java 8 什么 CMS GC 什么 SSM。某天你心血来潮,在自己的小破开发机里装了最新版的 JDK,用上了潮到没边的 Shenandoah GC,抄起键盘起手就是 hello world 一把梭,结果发现你写的程序居然跑不了——甚至还把 Java 搞崩溃了,现场只剩下 log、coredump 和一地鸡毛。
你会怀疑是不是自己太长时间没接触 Java 新特性,居然写不出一个能跑的程序……
还是说,你会觉得是 Java 本身,甚至是编译 JVM 的那个编译器、OS、CPU 里出现了更离谱的 bug 呢?
0x00 发生什么事了?
我的日常工作之一是给 OpenJDK 上游修 bug。某天我百无聊赖,用最新 build 出来的 JDK 在 RISC-V 平台跑测试,发现 tier1 测试居然挂了一大片。
0x01 缩圈
public class TestSmallHeap {
public static void main(String[] args) throws Exception {
System.out.println("Hello World!");
}
}
这……这对吗?我没在开玩笑,在某些情况下,目前的这个 JDK 还真就连 hello world 都跑不起来。
-
添加 -Xint,禁用 JIT 编译,解释执行 Java 程序:测试还是会挂,说明出问题的地方和 JIT 编译(即 HotSpot C1/C2 相关的实现)无关。
-
添加 -XX:ParallelGCThreads=1,把 GC 设为单线程:测试还是会挂,说明出问题的地方不在 GC 线程之间(但依然可能在 GC 线程和其他线程之间)。
-
通过参数指定其他 GC,比如 -XX:+UseG1GC:测试正常,问题消失。
--- release.log 2024-02-14 09:31:04
+++ fastdebug.log 2024-02-14 09:36:25
...
@@ -11,13 +11,13 @@
-fno-lifetime-dse
-Wno-format-zero-length -Wtype-limits -Wuninitialized
--DNDEBUG
--DPRODUCT
+-DASSERT
+-DCHECK_UNHANDLED_OOPS
-DTARGET_ARCH_riscv
-DINCLUDE_SUFFIX_OS=_linux
-DINCLUDE_SUFFIX_CPU=_riscv
...
对比发现,fastdebug 除了比 release 多调整了一些诸如 PRODUCT、ASSERT 这类控制调试的宏定义开关之外,还额外定义了 CHECK_UNHANDLED_OOPS 宏。后续测试表明,如果我们给 release 也定义这个宏,之前的问题就会消失。
typedef class oopDesc* oop;
class oop { oopDesc* _o; void check_oop() const { if (check_oop_function != nullptr && _o != nullptr) check_oop_function(_o); } void on_usage() const { check_oop(); }
public:
oopDesc* obj() const { on_usage(); return _o; }
oopDesc* operator->() const { return obj(); }
operator oopDesc* () const { return obj(); }
…
};
这么做是为了在解引用指针时,插入额外的检查操作。然而,除非通过参数手动开启,这个检查永远不会执行。
-
开启 CHECK_UNHANDLED_OOPS,但删除其中的所有检查:问题出现。
-
开启 CHECK_UNHANDLED_OOPS,只在解引用操作中添加检查:问题消失。
-
和 JIT 无关,只和 Shenandoah GC 相关,且不涉及多线程 GC 的部分。
-
只和 RISC-V 架构相关。
-
和 oop 的实现相关。
-
不像是个常规问题,因为多加一些条件判断,问题就会消失。
0x02 coredump 最没用的一集
#22 <signal handler called>
#23 Klass::is_instance_klass (this=0xb8547061) at src/hotspot/share/oops/klass.hpp:643
#24 oopDesc::is_instance (this=0xffcc0c08) at src/hotspot/share/oops/oop.inline.hpp:205
#25 ShenandoahMark::do_task<ShenandoahMarkRefsClosure, (StringDedupMode)0> ...
at src/hotspot/share/gc/shenandoah/shenandoahMark.inline.hpp:73
...
backtrace 表明 JVM 在 Klass::is_instance_klass 里崩掉了,尝试看一下发生了什么:
(gdb) x/i $pc
=> 0x3fa0ac1fc4 <_ZN14ShenandoahMark7do_task...+108>: lw a4,12(a2)
(gdb) x/g $a2 + 12
0xb854706d: Cannot access memory at address 0xb854706d
看起来确实是段错误,出问题的内存地址也和错误日志记录的地址相符。但很奇怪的是:这明明是一条 lw 指令,内存地址的结尾为什么是 d?
#23 <signal handler called>
#24 0x0000003f87bdce7c in ?? ()
通常,如果 JVM 的 coredump 里出现了问号,这说明程序正在执行 Java 方法在运行时生成的代码,而不是 C/C++ 代码。错误日志里的 stack trace 表明确实如此:
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
j java.util.ArrayList.add(Ljava/lang/Object;[Ljava/lang/Object;I)V+0 java.base@23
j java.util.ArrayList.add(Ljava/lang/Object;)Z+20 java.base@23
j java.lang.invoke.InvokerBytecodeGenerator.classData(Ljava/lang/Object;)Ljava/lang/String;+165 java.base@23
...
检查当前指令所做的操作:
(gdb) x/i $pc
=> 0x3f87bdce7c: ld a0,208(a0)
(gdb) x/g $a0 + 208
0x866e623c: Cannot access memory at address 0x866e623c
和前一个 coredump 类似,程序使用 ld 访问了一个无效的内存地址,同时这个地址也没有对齐 8 字节的边界。
(gdb) x/i $pc
=> 0x3fb7385926 <_ZN7oopDesc4sizeEv+118>: ld a5,256(a5)
(gdb) x/g $a5 + 256
0x100: Cannot access memory at address 0x100
居然是 0x100。黑色幽默的是,这次的地址倒是按照 8 字节对齐了。
#8 <signal handler called>
#9 0x0000003fb7385926 in oopDesc::size_given_klass ... at src/hotspot/share/oops/oop.inline.hpp:196
#10 oopDesc::size_given_klass ... at src/hotspot/share/oops/oop.inline.hpp:156
...
#13 0x0000003fb78c3ac0 in ShenandoahMark::mark_loop_work<ShenandoahMarkRefsClosure, true, (StringDedupMode)0> ...
at src/hotspot/share/gc/shenandoah/shenandoahMark.cpp:178
...
虽然出问题的地方依然和前两个 coredump 完全不同,但我们注意到,其中出现了对 ShenandoahMark 类方法的调用,而第一个 coredump 的调用栈里也出现了类似的内容——这说明,JVM 正在执行 Shenandoah GC 的 concurrent marking 阶段。
-
JVM 崩溃的直接原因是访问了无效的内存地址。
-
JVM 每次崩溃的位置都不相同。
-
崩溃时,Shenandoah GC 正在并行标记 Java 对象。
0x03 谁是卧底?先排除几个
-
只要多加一个条件判断,问题就会消失。这说明,要么是 JVM 的代码里出现了 undefined behavior[8],导致 GCC 的某些优化对程序作出了非预期的更改;要么是 GCC 自己出了问题。
-
这个诡异的多线程问题只在 RISC-V 架构存在。RISC-V 的生态目前还不成气候,各种软硬件实现鱼龙混杂,同时 ISA 标准飞速演进——这导致一些实现使用了旧特性,一些实现夹带了私货,还有一些实现和标准相左。这些软硬件实现组合在一起,出一些奇怪的 bug,反而是最不奇怪的事情。
-
我急了,想甩锅。
debian@debian:~$ uname -a
Linux debian 6.6.13-riscv64 #1 SMP Debian 6.6.13-1 (2024-01-20) riscv64 GNU/Linux
然后,只要在这个环境里用 JDK 跑之前挂掉的测试即可。需要注意的是,QEMU 模拟执行的速度非常慢,跑个测试还凑合,但千万别在里面构建 JDK。
0x04 二分,启动!
-
二分 git 的提交记录,找到第一个出现这个问题的提交。
-
二分 include oopsHierarchy.hpp 的那一百多个源代码文件,找到问题出在哪个文件里。
0x05 不是办法的办法
-
读取 JVM 的核心实现,也就是 libjvm.so 的反汇编输出。
-
解析其中的内容,提取所有函数的名称,以及对应的汇编指令序列。为了降低误报率,我们只提取汇编指令的操作码,也就是诸如 ld,add, beq 等,而忽略所有的操作数。
-
比较修改前后反汇编的差异,找出变化了的函数和指令序列。
0000000000ab3200 <_ZN14ShenandoahHeap26conc_update_with_forwardedI9narrowOopEEvPT_>:
...
ab3254: 0ff0000f fence
ab3258: 00c7d7b3 srl a5,a5,a2
ab325c: 00c75733 srl a4,a4,a2
ab3260: 1005a6af lr.w a3,(a1)
ab3264: 00f69563 bne a3,a5,ab326e
ab3268: 18e5a62f sc.w a2,a4,(a1)
ab326c: fa75 bnez a2,ab3260
ab326e: 0ff0000f fence
ab3272: 6422 ld s0,8(sp)
...
而正确的实现是这样的:
0000000000ab2ec0 <_ZN14ShenandoahHeap26conc_update_with_forwardedI9narrowOopEEvPT_>:
...
ab2d08: 00c7d7b3 srl a5,a5,a2
ab2d0c: 00c75733 srl a4,a4,a2
ab2d10: 2781 sext.w a5,a5
ab2d12: 2701 sext.w a4,a4
ab2d14: 0ff0000f fence
ab2d18: 1005a6af lr.w a3,(a1)
ab2d1c: 00f69563 bne a3,a5,ab2d26
ab2d20: 18e5a62f sc.w a2,a4,(a1)
ab2d24: fa75 bnez a2,ab2d18
ab2d26: 0ff0000f fence
ab2d2a: 6422 ld s0,8(sp)
...
发现了吗?正确实现里多了两条 sext.w 指令!如果我们用 16 进制编辑器修改正确的 libjvm.so,把这两个 sext.w 替换成空操作,然后再跑测试,就会出现相同的问题!
ab3258: 00c7d7b3 srl a5,a5,a2
ab325c: 00c75733 srl a4,a4,a2
ab3260: 1005a6af lr.w a3,(a1)
ab3264: 00f69563 bne a3,a5,ab326e
根据 ISA 手册,lr.w 返回的结果,即 a3 里的内容,是符号扩展的;之后的 bne 指令将 a3 与 a5 进行了比较;而 a5 的值又来自于之前的 srl 指令,即逻辑右移——众所周知,逻辑右移会将移动后多出来的高位全部写成 0。
0x06 卧底居然是……?
void foo(uint32_t *p) {
uintptr_t x = *(uintptr_t *)p;
uint32_t e = !p ? 0 : (uintptr_t)p >> 1;
uint32_t d = x;
__atomic_compare_exchange(p, &e, &d, 0, __ATOMIC_RELAXED, __ATOMIC_RELAXED);
}
对应的 Compiler Explorer 链接请看这里[16]。
0x07 又水一个 patch
__asm__ __volatile__ ( "1: lr.w %0, %2 \n\t" " bne %0, %3, 2f \n\t" " sc.w %1, %4, %2 \n\t" " bnez %1, 1b \n\t" "2: \n\t" : /*%0*/"=&r" (old_value), /*%1*/"=&r" (rc_temp), /*%2*/"+A" (*dest) : /*%3*/"r" ((int64_t)(int32_t)compare_value), /*%4*/"r" (exchange_value) : "memory" );
0x08 复盘
-
问题只和 Shenandoah GC 相关:确实,问题出在 concurrent marking 阶段的同步操作上。
-
只和 RISC-V 架构相关:确实,GCC 的 RISC-V 后端在实现上有问题。
-
和 oop 的实现相关:确实,进行 CAS 之前,必须先解码 compressed oop,得到正确的内存地址。
-
多加一些条件判断,问题就会消失:确实,一旦分支变得复杂起来,GCC 的某些优化的结果就会发生变化,绕过这个 bug。
-
JVM 崩溃只因访问了无效的内存地址:确实,conc_update_with_forwarded 方法的目的是更新 forward 指针,这一步出问题,必然会导致后续步骤访问到一个无效的地址。
-
每次崩溃的位置都不相同:确实,这个问题涉及线程同步,发生的时机并不确定。
-
首先,尽可能收集故障现场的信息,确定问题的大方向。
-
其次,大胆假设,小心求证,在验证猜想中不断缩小问题的范围。
-
定位到问题之后,用尽可能短的实现去复现问题,最终找到问题的原因。
参考链接: