JVM GC 压测 与日志分析
本文主要分析各种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方法添加些初始化临时变量的操作。
1 2 3 4 5 |
@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时,此时的日志会与其他日志有很大不同
可以看到如下信息:
1 2 3 4 5 6 7 8 9 10 11 12 13 |
[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
1 2 3 4 |
[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暂停处理各种复杂的情况。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
# 当前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操作。
日志如下:
1 2 3 |
[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就可以直接使用。
这一阶段的日志如下:
1 2 3 |
[CMS-concurrent-reset-start] # 耗时7ms [CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] |