云上JDK17 Crash的案例及补救方案

前言

在云上，对于目标SaaS或PaaS应用的监控显得至关重要。大部分应用都是Java应用。除了对目标数据库的监控以外，对Java应用本身的监控一样显得重要。

本文提到的案例就比较诡异，发生在JDK17身上。最后也只好通过调整相关JVM参数来绕过相关错误。

过程及分析

在Cloud Foundry的BTP平台中，我们发现一些Java应用，发现经常频繁的Crash（宕机），大概每隔一两个小时会发生一次。

我们使用的SAP JDK 17, 相关配置参数是：

JBP_CONFIG_JAVA_OPTS: [ java_opts: '-Xss512K -XX:ReservedCodeCacheSize=150M -XX:MaxMetaspaceSize=200M -XX:MaxDirectMemorySize=256M -XX:+DisableExplicitGC -XX:+UseG1GC -XX:MinHeapFreeRatio=10 -XX:MaxHeapFreeRatio=30 -XX:-ShrinkHeapInSteps -XX:ConcGCThreads=10 -XX:ParallelGCThreads=10 -XX:-UseDynamicNumberOfGCThreads ' ]

JBP_CONFIG_SAP_MACHINE_JRE: "[memory_calculator_v2: {headroom: 18}]"

JBP_CONFIG_COMPONENTS	jres: ['com.sap.xs.java.buildpack.jre.SAPMachineJRE']

jvmkill killing current process
CodeCache: init 2555904, used 102956288, committed 103940096, max 157286400
G1 Old Gen: init 113246208, used 1207994368, committed 1384120320, max 6278873088
G1 Eden Space: init 25165824, used 8388608, committed 62914560, max -1
Compressed Class Space: init 0, used 18318032, committed 18808832, max 167772160
G1 Survivor Space: init 0, used 531800, committed 4194304, max -1
Metaspace: init 0, used 152454416, committed 153288704, max 209715200
Memory pool usage:
Non-heap memory: init 2555904, used 273728736, committed 276037632, max 534773760
Heap memory: init 138412032, used 1216914776, committed 1451229184, max 6278873088

从上边的相关JVM出错的警告日志，可以看到：

Memory pool usage:
Non-heap memory: init 2555904, used 273728736, committed 276037632, max 534773760
Heap memory: init 138412032, used 1216914776, committed 1451229184, max 6278873088

JVM Heap的消耗情况，可以看出，commit的大小只到了：1451229184 （约1.45GB), 离max heap size : 6.28G还差的很远，因而不可能会OOM (Out of Memory)。

接着我们再查查系统当中出现的日志：

[86015.185s][warning][gc,alloc] http-nio-8080-exec-8:Retried waiting
for GCLocker too often allocating 262210 words

我们可以看到有很多如上边显示的日志。它总是抱怨在分配N个字长空间时进行了retry等待GCLocker去释放某种锁。

这是一个非常严重的问题。

为什么呢？

系统的内存得不到充分利用。明明6个多G的Java Heap, 最后用到了1.4G以后就频繁Crash。在云平台上，内存和CPU就是对应的银子。这意味着会极大的浪费资源。

这个问题如何解决呢？

我们来看看JNI Critical和GCLocker之间的关系：

一旦该特定线程在VM中恢复执行，如果该线程在JNI临界状态时被请求，则该线程将运行一个GC周期。这将在GC日志中反映为“GCLocker发起的GC”。

简单地说，GCLocker是一种工具，用于防止JVM在JNI读/写地址时移动对象，因为移动对象会导致地址发生变化，而JNI对此并不知情。

很好，最后确实运行了一个GC周期，那么为什么会抛出OOM错误呢?让我们考虑以下场景:

当然，当GCLocker Initiated GC周期完成时，一定释放了一些内存，对吗? 是的，但是也有其他线程请求内存! 当涉及到GC周期释放的内存时，没有先进先出的概念。因此，最初请求内存分配的线程必须再次等待，等待另一个周期完成。

真正的问题是:GCLockerRetryAllocationCount的默认值是2(至少在Java 17中是这样)。这将无意中产生一个错误的OOM错误被抛出!

详见openjdk的源码：

src/hotspot/share/gc/shared/gc_globals.hpp

 product(uintx, GCLockerRetryAllocationCount, 2, DIAGNOSTIC,               \
          "Number of times to retry allocations when "                      \
          "blocked by the GC locker")                                       \
          range(0, max_uintx)

调整 G1 GC

对于我们的用例，默认值2显然是不够的。如果将其设置为更大的值，比如100，会发生什么?我们在VM选项中添加了以下两个标志:

-XX:+UnlockDiagnosticVMOptions
-XX:GCLockerRetryAllocationCount=1048576

将默认的2次retry改为100甚至1048576，经过多次retry之后，GCLocker正常放掉以后，resource allocate就能还执行了。意味着GC成功的执行了。

我们在文章：Demystifying G1 GC, GCLocker, JNI Critical, and Fake OOM Exceptions^[1] 也看到了类似的分析。可以好好看一看。

不成熟的OOM不会被抛出，因为许多年轻的GC周期无法释放足够的内存，并且会启动一个完整的GC !

好奇的人: G1不是把每一代都分成固定大小的区域吗? 如果是的话，它不能锁定那个区域吗?是的，但是G1还没有实现区域固定。事实上，有一个JDK特性请求已经开放了一段时间: [JDK-8276094\] JEP 423: Region Pinning for G1 – Java Bug System^[2]

但是，同时，我们也要注意到：

JNI allocation(GetPrimitiveArrayCritical/ReleasePrimitiveArrayCritical)

尽量减少这个函数的调用，可能会有效的降低这个错误的出现。有时候可能是第三方库触发的这个JNI调用。如果能找到，就会有效的降低这个错。

当然将：-XX:GCLockerRetryAllocationCount=2 调整为100甚至为1048576, 只会让效果更好，而不会更糟糕。

关于复杂的jvm调优，我们可以进一步阅读：

1. JVM Anatomy Quark #9: JNI Critical and GC Locker^[3]
2. [JDK-8276094\] JEP 423: Region Pinning for G1 – Java Bug System^[4]
3. GCLocker failure test case^[5]
4. [JDK-8137099\] G1 needs to “upgrade” GC within the safepoint if it can’t allocate during that safepoint to avoid OoME – Java Bug System^[6]
5. [JDK-8192647\] GClocker induced GCs can starve threads requiring memory leading to OOME – Java Bug System^[7]
6. Garbage First Garbage Collector Tuning^[8]
7. Tips for Tuning the Garbage First Garbage Collector^[9]

小结

对于JVM或内存以及CPU的使用情况，是跟数据库监控完全并列的重要工作。相当于在应用层，就可以发现一些潜在的问题。两块结合起来，才能为完成预期的SLA，打下坚实的基础。

后续有时间，将整理一系列关于JVM调优方面的文章，分享给大家。

参考资料