前2天看到有台机器的 Java 应用突然 CPU 高企, 再看其它metrics, 发现是由 GC 导致的, 但是看到 JVM available 内存, 却有很多, 再去观察 verboseGC log, 形状也很奇怪. 它到底是什么原因导致的呢?

症状表现

首先, 我们看到下面的metrics, CPU 几乎100%, GC overhead 几乎是100%, 然而可用内存却有5G空闲, 如下图:

初步分析

由于有很多的可用内存, 所以怀疑是不是显式调用 System.gc() 或者 Runtime.gc() 导致的, 于是去查看 verbose GC 日志, 发现并没有找到这些关键字. 于是观察了 verbose GC的形状, 发现很奇怪的地方, 如下图:

这是截取从刚开始 full GC 到 一直 full GC的那段, 从图中可以看到, 年轻代大小一直缩小, 老年代空间一直增大, 老年代被频繁回收(full GC 导致), 每次回收都能回到一个稳定值, 然后又继续快速大量占用, 再次被回收到稳定值.

这是有关heap的相关参数(从verbose GC log 头部截取):

2022-11-23 05:46:52 GC log file created ./log/verbosegc.log.1
OpenJDK 64-Bit Server VM (25.342-b07) for linux-amd64 JRE (Zulu 8.64.0.16-SA-linux64) (1.8.0_342-b07), built on Jul 20 2022 08:43:38 by "zulu_re" with gcc 7.3.0
Memory: 4k page, physical 45613056k(29362788k free), swap 0k(0k free)
CommandLine flags: -XX:CompileCommand=exclude,org/mozilla/javascript/gen/*.* -XX:CompileThreshold=1000 -XX:CompressedClassSpaceSize=528482304 -XX:ConcGCThreads=2 -XX:+DisableExplicitGC -XX:G1HeapRegionSize=4194304 -XX:GCLogFileSize=5120000 -XX:InitialHeapSize=12884901888 -XX:+ManagementServer -XX:MarkStackSize=4194304 -XX:MaxDirectMemorySize=1073741824 -XX:MaxHeapSize=12884901888 -XX:MaxMetaspaceSize=536870912 -XX:MaxNewSize=7730102272 -XX:MinHeapDeltaBytes=4194304 -XX:NumberOfGCLogFiles=40 -XX:ParallelGCThreads=6 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:ReservedCodeCacheSize=251658240 -XX:-TieredCompilation -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseG1GC -XX:+UseGCLogFileRotation 
2022-11-23T05:46:52.810-0700: 882083.527: [GC pause (G1 Evacuation Pause) (young)

从上面的参数可以看到, 这个JVM 的heap 设置的最大值是12G, 结合 verbose GC log的数据, 我们可以看到老年代已经扩展到 10G 多, 每次回收能回收到大概5.6G的样子, 到底是什么对象突然扩展到10G, 然后又能突然缩小呢? 年轻代, 那么小, 从其中移过来的对象, 一般也不大. 那么只有某些直接分配在老年代的对象才可能导致这样. 于是我们做个heap dump 然后做分析.

检查分析

对heap dump的分析很快给我们了答案, 又一个数组太大了:

从图中可见, 这个Object[]竟然有145万个元素, 占用了4.1G的heap 空间. 然后我们看它在哪里被使用的, 找到线程栈, 如下图:

从上面的线程运行栈可以看到, 这个 Object[] 是CopyOnWriteArrayList的内部表示, 而它正在执行 add() 操作, 如果我们去查看 CopyOnWriteArrayList 的 add() 方法, 我们会发现, 每次 add 一个新元素, 它都会复制一块新内存, 把新元素加到结尾, 而给这个 4.1G 的数组加一个新元素, 会导致系统要再申请一个 4.1G多的空间, 把新元素添加到末尾, 这就解释了为啥快速的申请, 做完就释放, 由于4.1G 的新空间只能在老年代申请(年轻代只有2G了), 所以频繁 full GC.

所以这里使用 CopyOnWriteArrayList 就是一个错误, 而如果每个元素都是这么一个个加进来的, 那么对系统来说, 简直是一场巨大灾难.