记一次JVM导致数组长度变化的bug

前几天,搞图检索的少爷说他们发现了一个JDK 8很诡异的问题. 说是数组长度会变.

我非常懵逼, 心想如果真有这错误简直是会毁天灭地, 肯定是代码哪里写错了.

还没看就先"赌"起来, 出于对JVM的迷之自信, 我赌是java代码错了, 少爷很刚, 赌jvm错了.


数组长度变化问题


在做对象序列化过程中, 使用了Unsafe来提升性能, 这也是很多Java项目的常规优化手段.

但其中发生了一个很诡异的现象:

某函数内部会创建一个长度为397的byte数组(这个数字只是举例), 然后做了一个Unsafe写操作, 函数返回后该数组的长度变为了141.

由于数组长度发生变化, 导致反序列化时内容不对报了相关错误.

注: 理论上Unsafe往特定位置写是可以改数组长度的, 但并没有这种操作.


可重现的简化代码长这样:

public static void main(String[] args) {
  System.err.close();
  int count = 0;
  while (count++ < 120000) {
    test();
  }
}

public static void test() {
  byte[] newBuf = serBytes(397);
  if (newBuf.length != 397) {
    System.out.println(/*ERROR_MSG*/);
  }
}

static final long BYTE_ARRAY_BASE_OFFSET = (long)THE_UNSAFE.arrayBaseOffset(byte[].class);

public static byte[] serBytes(int bufLen) {
    byte[] buf = new byte[bufLen];
    THE_UNSAFE.putInt(buf, BYTE_ARRAY_BASE_OFFSET + 1L, buf.length);
    System.err.println("ref " + buf);
    return buf;
}

(注: 代码中使用了一些System.err.println逻辑是为了(期望)hack一些编译器优化, 确保更大概率出问题.)

主要逻辑是循环调用serBytes(397), 如果返回长度不一致会有报错 array length internal error, expected: 397 (0x18d) actual: 141 (0x8d).


期望输出: (无输出)

ERROR_MSG出错输出: array length internal error, expected: 397 (0x18d) actual: 141 (0x8d) (多行输出)


虽然Unsafe不算官方接口, 但也得到了广泛使用, 用法也算正常, 不应该改变数组长度.

这段代码加一些Unsafe的实现基本可以直接编译 + 无参数java运行, 运行多次, 中间有概率出现错误输出, 大家尝试一下.


初步分析排查

静态地检查代码, 没发现代码层面的bug.

中间还做了很多实验, 仔细确认过相关业务代码确保没有一些低级错误, 包括确认了没有多线程影响, 也验证了下返回数组的reference没变.

最后在函数内部输出长度是没变的, 但函数返回后输出就变了.

从常识来看,在返回对象时不会对它的内存做修改, 这就更诡异了.

至此我们基本把问题的怀疑指向了JVM内部. 以我们对JVM的了解, 不太相信是在函数边界或者函数外部修改了长度, 只可能是内部就出错了. 但毕竟函数内部编译器是很容易做优化, 可以直接把长度输出替换成创建的长度 (除非我们写个很复杂的函数绕过优化).

在分析出错中有个很重要的现象, 出错的信息不会一直打, 大概只有中间少数量的调用会出错, 而且有时候还不会出错.


接下来就是得靠理智分析(瞎猜)了.

多线程编译bug?

这个出错带有一定的随机性, 从本质而言源头一定是一个随机的事件触发的.

以我们粗浅对编译器的了解, 一般编译是没必要加入一些随机因子的, 换言之一个方法经过一个比较"原子"的编译过程是不会生成两种代码的.

首先想到的是, JVM默认编译线程有两个, 难道是两个线程获得同一个方法编译时的多线程bug?

但可惜的是, JDK 8的生产版限制了至少需要两个编译线程, JDK 7可以设置单线程, 但用原有业务代码跑起来并不会出错(后续分析发现其实稍微改一下代码, 上述精简代码可以重现错误出错).

多线程编译引起bug这条分析线似乎不好继续展开了. 换个思路.


错误的编译代码 + 随机的编译时机?

那么另外一个随机来源可能就是: 编译时机. JIT一般用方法用调用次数来做编译触发条件, 这个总体而言是一个稳定的过程. 但JVM会有多次编译优化, 可能有OSR, 或者JIT优化方法本身, 或者外层方法内联方法后的合并优化.

这里面如果某个阶段是出错的代码, 但由于后续优化过早或过晚完成带来了随机性呢?

那就直接刚一波汇编吧.

java -XX:+UnlockDiagnosticVMOptions -XX:+PrintAssembly

确实中间编译过几次, 当出现错误后, 一旦某次编译完成以后就不会有错误了. 至此比较确认是某一次编译代码执行会出错误, 而其它编译没有问题.


既然编译器可能出bug, 那么我们跑跑解释器. java -Xint 跑起来, 发现错误不能重现, 符合预期.

全编译的话 java -Xcomp也会出错, 可以稳定出错, 出错次数也较为稳定.

全编译的情况依然比较复杂, 为了利于分析, 我们继续实验.


锁定编译器问题

我们还是着重怀疑serBytes方法, 那么也实验了下只编译这个方法.

java -XX:CompileOnly=JvmTest.serBytes. (该参数要求jvm只对方法JvmTest.serBytes进行编译.)

在这样设置后, 可以确保一定重现问题, 而且基本所有调用都会出错.

同样的, 我们也在Java 7, 8, 10的多个版本测试(包括最新版), 都存在相同问题(使用简化版代码, 不同版本代码可能需要微调, 但原理是一样), 不开-XX:CompileOnly也可以出错, 看来波及面还是挺大的.

那么得仔细看下serBytes方法编译出来的汇编究竟有什么问题了.

在此之前,先简单介绍下java数组的内存布局 (基于UseCompressedOops生效, 默认设置且堆不超过32g左右.)

以new byte[397]为例

再来看看汇编:

这一段汇编对应了new byte[397]的相关逻辑, 我们知道java数组初始化后默认要清零, 这段逻辑主要是初始化数组元信息, 然后清零数据.

我们摘取5个比较关键的步骤, 红色为出错步骤, 其中%r8为数组指针

  1. 将类指针放入偏移[8,12)
  2. 将%esi(为数组长度397)放入偏移 [12, 16)
  3. 将值0 (%r12d的值)写入偏移 [13, 17)
  4. 将值0 写入偏移[20, 24)
  5. 将值0 写入偏移[24, ...) : 写入24开始的后续数组内容

在写入长度397 (0x18d)到偏移12后, 代码又对偏移13开始的内存, 用0赋值.

数组长度的最高3个byte清零, 因此只留下0x8d 这个byte当做长度, 这个就是出错的数组长度141.

汇编可以看出, 这段代码本意是想按照java规范完成数组数据清零的.

应该是偏移[16, 16+397) 但似乎偏移算错了, 清零了 [13~17), [20, 16+397) 这一段.

找到出错汇编了, 就是这个"误"清零操作抹掉了长度的高三位, 基本认定是编译器的一个bug.


深入JVM分析


为了弄清楚这个bug的root cause, 我们决定继续深入JVM看看到底是什么原因导致的代码错误.

build了一个8u132版本的debug版本.

有意思, 程序根本跑不起来, 因为一个assert失败导致jvm crash.

# A fatal error has been detected by the Java Runtime Environment:

#

# Internal Error (/home/lty/jdk8/openjdk/hotspot/src/share/vm/opto/memnode.cpp:2883), pid=19749, tid=140692759176960

# assert((end_offset % BytesPerInt) == 0) failed: odd end offset

#


看来是前置条件没满足,但product版本由于不带assert,导致后续代码"带病"执行,生成了错误的代码.

这段代码位于函数ClearArrayNode::clear_memory里. 这段逻辑需要生成一段对某个范围内存清零的代码.

清零[start_offset, endoffset) 的逻辑大概是这样 (它的assert要求end_offset是对齐的, 在加上一些jvm内部假设,如start_offset 也是对齐, 那么这段逻辑看上去是没问题的).

   assert((end_offset % BytesPerInt) == 0)
   done_offset = 满足一定条件(end_offset)? end_offset, end_offset - 4
   if (范围合理) clear (start_offset,    done_offset)
   if (范围合理) clear (done_offset, done_offset + 4)


调试后发现出错时, start_offset = 16, end_offset = 17 , done_offset = 13 会触发第二个clear, 清零 [13, 17).

很显然, 这段内存清零代码多清除了前面几个byte. 在数组的内存, [12, 16) 区间为数组长度, 因此高三个byte会被误清零, 对应了我们看到的错误汇编.

但这并不一定是root cause, 可能其它地方错传了一个start/end_offset呢?


经过一系列上下文分析, 基本明白了这个地方的优化.

编译器在清零该数组的时候尝试做了一个优化,会把后续的一些它认为合理的内存写操作(raw memory store)合并到清零过程中,避免清零完立马又要写入值.

不巧的是, 这个unsafe写被合并进去了. unsafe需要写 [17, 21) 这一段内存, 因此编译器只需要清零[16,17), [21, 16 + 397)的内存. (汇编中是第二段是从20开始清零了, 因为21需要对齐到4字节[BytesPerInt])

这之后, 就会用[16,17)ClearArrayNode::clear_memory, 进而触发上述错误.


问题解决(Workaround):

由于该问题在已知版本的jvm JIT编译器中都出现, 在得到官方修复以前, 只能代码层面workaround.

其中最有效的一种极大概率可以奏效的是, break "合理的内存写操作(raw memory store)合并到清零过程中" 这个逻辑. 这个内存优化的相关注释说明了, 需要(constant) offset 才会合并写操作到数组清零过程中, 而一般Unsafe写的偏移是base + offset.

其中, base一般是从Unsafe的arrayBaseOffset获得, 虽然从接口上这个值没说是常数, 但大家用的话都当它是常数用的, 也会声明final.

而offset一般是业务逻辑相关, 是不是常数或final都有可能.

其实个人认为, 这个地方倒不用真的不是常数, 而只要类型声明上没有final一类明确告诉编译器是常数的行为就行.

那么把代码中的BYTE_ARRAY_BASE_OFFSET的final修饰去了即可, 或者BYTE_ARRAY_BASE_OFFSET+1 用 BYTE_ARRAY_BASE_OFFSET + variable代替 (variable别放在方法内写个int variable = 1;就行, 这种级别编译器还是可以优化掉的).


话说回来, 毕竟编译器是黑盒也会迭代, 我们只能尽可能的告诉(骗)编译器这不是常数, 但它能不能找出这是个常数就看本事了. 实践下来,上面的方法在现有版本中是有效的.


另外还有一些效果一般也更限制代码编写的思路:

a. 不给编译器优化机会: 每一次使用Unsafe写入数组之前的直接相邻代码中 (此处指方法内直接相邻或当unsafe所在方法被inline后的相邻), 没有直接数组创建.

b. 帮助编译器偏移计算不出错, 略hack: 在使用Unsafe写入数组时尽量对齐数据 (或数组头部相邻4-8个byte不要写.)

c. 尽可能的谨慎用Unsafe, 考虑在unsafe数组中(更)保守地记录数组长度.



感谢黑老师,少爷发现及一起分析该问题~


最后打个小广告~ 星环科技实习生&校招持续招聘~ 大数据分布式基础架构/图数据库/大数据云平台/人工智能/机器学习都有位置~

编辑于 2018-04-29