花钱的年华

江南白衣,公众号:春天的旁边

JNI是终极加速?我们来谈谈副作用

| Filed under 技术

0. 引言

小时候,觉得C写的JNI代码很快。

后来,听说Java JIT编译后的代码不比C慢,而且JNI代码还要跨越JNI的边界,只适用于请求JDK没有封装的系统调用。

现在,发现JNI 还有其他的副作用。

 

1. 现象

在JDK8的GC日志里,出现GC cause 为GCLocker Initiated GC,而不是常见的Allocation Failure。这引起了大家的恐慌和猜测。

2017-10-17T09:48:50.879 : [GC (GCLocker Initiated GC) [ParNew: 1758554K->197723K(1887488K), 0.0403800 secs] 1758554K->197723K(3984640K), 0.0405080 secs] [Times: user=0.65 sys=0.03, real=0.04 secs]

而眼不见为净的JDK7里,需要加上-XX:+PrintGCCause参数才会把GC原因打印出来(JDK7的低版本还不支持呢)。

 

2. 原因

堆内存是JVM管理的,而JNI的由Native Code自行管理。

当一段String或数组要从JVM传向JNI,两者共享引用而不是拷贝传递时,就需要避免在JNI代码还用着的时候,JVM执行GC,将某个地址的内容从eden移到survivor区甚至清理掉。

所以,JNI代码调用的GetPrimitiveArrayCritical() or GetStringCritical()函数时会加锁,用完了之后再调用对应的Release函数解锁,并把这段时间称为"JNI critical section"。

jni.cpp中 GetStringCritical的简化版如下:

当GC发生时,如果发现GC Locker加了锁,就会进行标记并放弃当前GC。然后在最后一个进入了JNI critical section的线程退出时,发现了标志,就会进行一次补偿GC。

 
加上 -XX:+PrintJNIGCStalls启动参数,在GC日志里就会发现多了两条记录,分别对应上面的两步。

24.366: Setting _needs_gc. Thread "VM Thread" 1 locked.
 
2017-10-17T09:48:50.879: 24.366: Total time for which application threads were stopped: 0.0003180 seconds, Stopping threads took: 0.0000550 seconds
 
24.366: Thread "Thread-29" is performing GC after exiting critical section, 0 locked

通过线程号,thread dump一下能看到是谁调用了JNI,最常见的情况就是Logback 滚动并压缩文件的时候,压缩的代码用了Native Code,比如Defalter.c简化后的deflateBytes函数如下:

 

3. 副作用

副作用1: JNI critical section 期间,会导致对象直接在老生代分配,让临时对象逃逸到老生代。

聪明的同学可能会想到,新生代满了所触发的YGC,如果放弃了,那Java程序就没内存用了哦,会把所有线程Block住,直到JNI线程退出critical section么?如果真是这样就太恐怖了,因为不知道JNI代码会锁多久。

好在,策略是如果新生代放不下了会在老生代分配。在collectorPolicy.cpp中的简化代码如下:

副作用2: 如果进入JNI critical section 时间很长,连老生代也满了,会真正锁住所有线程。
如果有加-XX:+PrintJNIGCStalls参数, 就会打印出下面的语句

1.079: Allocation failed. Thread "pool-1-thread-1" is stalled by JNI critical section, 1 locked.

顺便发现了一件不开心的事情,一直很信赖的,代表着所有JVM 停顿的 -XX:+PrintGCApplicationStoppedTime,此时并没有在GC日志打印出相应的Total time for which application threads were stopped。

副作用3: 因为GCLocker而没有实际执行的那次GC的停顿时间

见前面+XX:+PrintJNIGCStalls的例子, Total time for which application threads were stopped,这个时间比较飘忽,有些测试里小到只有零点几毫秒,有些测试里是一两毫秒。

副作用4: 可能触发额外不必要的YGC

JVM好像还有一个一直没修的bug,https://bugs.openjdk.java.net/browse/JDK-8048556,有一定的几率,本来只该触发一次GCLocker Initiated GC的YGC,实际发生了一次Allocation Failure GC又紧接着一次GCLocker Initiated GC。看Bug里的描述,是因为GCLocker Initiated GC的属性被设为full,导致两次GC不能收敛。

 

4. 踩坑的优化参数

之前有一个 -XX:+ExplicitGCInvokesConcurrent,可以让System.gc() 使用轻量的CMS GC,所以看到-XX:+GCLockerInvokesConcurrent时,恰逢遇到了比较慢的GCLocker GC, 就想当然的用了。

结果,原本GCLocker只需要补偿YGC就够的,变成要执行YGC + CMS GC了。

这参数就是个坑,唯一的原因可能是想清理掉那些逃逸进老生代的临时对象吧,但代价还是太大了。

genCollectedHeap.cpp中的代码如下:

 

5. 参考资料

https://shipilev.net/jvm-anatomy-park/9-jni-critical-gclocker/ 有些GC实现,不要完全放弃GC,而是把需要共享内容的地方,Pin一个SubPage出来不收集。

发表评论

您的电子邮箱不会被公开。

您可以使用这些 HTML 标签和属性: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>