JVM GC 压测与日志分析

发表于： 2021年9月30日 2021年9月30日
分类： java
标签： java

本文主要分析各种JVM GC方式在压测环境的表现。

压测环境

工具：wrk，运行在Mac物理机的docker容器中
命令：wrk -t4 -c1000 -d30s --latency http://192.168.1.53:8088/api/hello
环境：Centos，4核心，8GB物理内存
JVM：Java 14 Oracle / Java 8 Oracle
程序：一个简单的SpringBoot程序，在Controller中的API方法添加些初始化临时变量的操作。

@GetMapping("/api/hello")

public String sayHello(HttpServletRequest request){

final byte[] b = new byte[1024 * 100];

return "ok";

}

压测结论

JVM运行在100MB低内存场景

限制Xmx和Xms在100m的场景下的Lantency对比。

从延时数据上看内存在100MB的场景性能最好的还是ParallelGC，因为在小内存场景，G1的分段GC，并发GC之类的优化并不能起到很好的效果。

从吞吐量（QPS）的角度进行对比，仍然是ParallelGC最优。

JVM运行在6GB高内存场景

限制Xmx和Xms在6GB内存场景下的Lantency对比。

这一次压测我使用了Java 14进行，原因是想顺便测下ZGC的效果。

从延时分布上看，G1GC是最优的，在平均延时差不多的情况下，P99比其他GC有明显减少。

从吞吐量上看，还是ParallelGC最高，基本上也符合预期。

可能因为ZGC还是处于试验阶段，所以效果还不是很明显，后面会整理下ZGC相关的文章。

总结

从数据上看，在低内存（比如100MB）JVM上ParllelGC是最优的，无论是在吞吐量指标还是延时指标。

其实这个时候选用什么GC垃圾收集器并没有什么明显差别，因为堆内存不大，收集一次也并不会耗费多少时间。

而在高内存场景，需要根据策略进行选择。如果是吞吐量（QPS）优先，则需要选用ParallelGC，如果是RT（响应时间优先）那么最好选好用G1 GC。

下面对压测阶段产生的GC日志进行分析

GC 日志分析

SerialGC 日志分析

1	[GC (Allocation Failure) [DefNew: 15162K->1242K(15360K), 0.0058139 secs] 19841K->6895K(49536K), 0.0058382 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

根据上面的YGC日志，有几个关键信息要看出：

其中 Allocation Failure表示触发GC原因为空间不足。
DefNew表示SerialGC的新生代，这次GC 新生代空间从15162k下降至1242k，耗时5ms。
整个堆空间从19841k下降至6895k，耗时5ms。

1	[Full GC (Metadata GC Threshold) [Tenured: 5653K->6527K(34176K), 0.0217220 secs] 7483K->6527K(49536K), [Metaspace: 15849K->15849K(16688K)], 0.0217555 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

上面是一条SerialGC的Full GC日志
信息如下：

Tenured老年代从5653K上升到6527K，总共老年代空间为34176k。
整个堆空间从7483k下降至6537k。
Metaspace 区没有变化。

ParallelGC 日志格式分析

YGC

1	[GC (Allocation Failure) [PSYoungGen: 13196K->384K(14592K)] 31101K->18572K(38912K), 0.0043607 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

FullGC

1	[Full GC (Ergonomics) [PSYoungGen: 2290K->0K(14592K)] [ParOldGen: 23196K->19969K(34304K)] 25486K->19969K(48896K), [Metaspace: 23359K->23321K(24880K)], 0.0670752 secs] [Times: user=0.19 sys=0.01, real=0.07 secs]

ParallelGC和SerialGC格式类似，只不过新生代/老年代名称和SerialGC不同而已。

CMS GC日志格式

CMS在新生代使用的是ParNewGC，所以YGC日志与SerialGC和ParalellGC基本相同

1	[GC (Allocation Failure) [ParNew: 15103K->1333K(15360K), 0.0035725 secs] 20866K->7836K(49536K), 0.0035963 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

当触发FullGC时，此时的日志会与其他日志有很大不同
可以看到如下信息：

[GC (CMS Initial Mark) [1 CMS-initial-mark: 6503K(34176K)] 8234K(49536K), 0.0013258 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

[CMS-concurrent-mark-start]

[CMS-concurrent-mark: 0.031/0.031 secs] [Times: user=0.12 sys=0.01, real=0.03 secs]

[CMS-concurrent-preclean-start]

[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

[CMS-concurrent-abortable-preclean-start]

[GC (Allocation Failure) [ParNew: 15029K->1157K(15360K), 0.0051178 secs] 21532K->8243K(49536K), 0.0051430 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

[CMS-concurrent-abortable-preclean: 0.021/0.108 secs] [Times: user=0.35 sys=0.01, real=0.10 secs]

[GC (CMS Final Remark) [YG occupancy: 8358 K (15360 K)][Rescan (parallel) , 0.0019976 secs][weak refs processing, 0.0000316 secs][class unloading, 0.0026277 secs][scrub symbol table, 0.0020630 secs][scrub string table, 0.0000961 secs][1 CMS-remark: 7086K(34176K)] 15445K(49536K), 0.0073523 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

[CMS-concurrent-sweep-start]

[CMS-concurrent-sweep: 0.004/0.004 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

[CMS-concurrent-reset-start]

[CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

阶段1：CMS Initial Mark

初始标记阶段，该阶段是CMS进行GC的第一个过程，该对象从GcRoot开始并且只扫描与GcRoot有关的对象，并做标记。
这个过程需要暂停用户线程。
根据第一行日志可以看出。
[1 CMS-initial-mark: 6503K(34176K)] 这一部分表示老年代的使用量以及老年代空间的大小。
8234K(49536K)后面表示整体堆空间的使用情况。

这一阶段耗时为0.0013258秒。

阶段2：CMS Concurrent Mark

并发标记阶段，从前一阶段initial Mark找到GCRoot开始算起，遍历老年代存活对象，这一阶段不会造成STW。

这一阶段日志如下

1 2	[CMS-concurrent-mark-start] [CMS-concurrent-mark: 0.031/0.031 secs] [Times: user=0.12 sys=0.01, real=0.03 secs]

其中 CMS-concurrent-mark: 0.031/0.031 secs 表示GC线程消耗时间和实际消耗时间。

阶段3：Concurrent Preclean

并发预清理阶段，同样不需要STW

1	[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

阶段4：Concurrent Abortable Preclean

可取消的并发预清理，这一阶段同样不需要STW

[CMS-concurrent-abortable-preclean-start]

# 中间穿插了一次YGC

[GC (Allocation Failure) [ParNew: 15029K->1157K(15360K), 0.0051178 secs] 21532K->8243K(49536K), 0.0051430 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

[CMS-concurrent-abortable-preclean: 0.021/0.108 secs] [Times: user=0.35 sys=0.01, real=0.10 secs]

阶段5：Final Remark

最终标记阶段，这个阶段会在造成一次STW。本次阶段的作用是完成老年代所有存活对象的标记，之前的预清理阶段是并发执行的，可能会存在GC线程速度跟不上应用程序的修改速度。

所以需要一次STW暂停处理各种复杂的情况。

# 当前Young Gen的所有使用量和总容量

[GC (CMS Final Remark) [YG occupancy: 8358 K (15360 K)][Rescan (parallel) , 0.0019976 secs]

# 阶段1：处理弱引用的持续时间

[weak refs processing, 0.0000316 secs]

# 阶段2：卸载不使用的类以及持续时间

[class unloading, 0.0026277 secs]

# 清理符号表及持续时间

[scrub symbol table, 0.0020630 secs]

# 清理内联字符串常量表

[scrub string table, 0.0000961 secs]

# 此阶段完成后老年代的使用量和总容量

[1 CMS-remark: 7086K(34176K)] 15445K(49536K), 0.0073523 secs]

# 耗时20ms

[Times: user=0.02 sys=0.00, real=0.00 secs]

阶段6：Concurrent Sweep

并发清除阶段，不需要进行STW操作。

日志如下：

[CMS-concurrent-sweep-start]

# 占用时间

[CMS-concurrent-sweep: 0.004/0.004 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

阶段7：Concurrent Reset

并发重置阶段，重置CMS算法相关的内部数据结构，下次GC就可以直接使用。

这一阶段的日志如下:

[CMS-concurrent-reset-start]

# 耗时7ms

[CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

JVM GC 压测与日志分析

压测环境