使用海量对象分配快速测试GC性能|摸鱼编程JVM专栏

问题

GC是java应用性能的一大杀手，今天我们探讨一个问题，1百万对象的分配会不会使JVM暂停秒级别。

背景

先简单学习一下OpenJDK现有的GC。

黄色的图表示这是Stop-The-World(简称STW)的GC，绿色的图表示这是并发(concurrent)，不会导致STW的GC。

测试

测试代码:分配1百万次16byte对象

import java.util.*;

public class AL {
    static List l;
    public static void main(String... args) {
        l = new ArrayList();
        for (int c = 0; c < 100_000_000; c++) {
            l.add(new Object());
        }
    }
}

测试环境为 MBP m1 8core,MacOS 13.2,JDK 17

JDK 信息

java -version
openjdk version "17" 2021-09-14
OpenJDK Runtime Environment Homebrew (build 17+0)
OpenJDK 64-Bit Server VM Homebrew (build 17+0, mixed mode, sharing)

JVM参数设置为Xmx4g Xms4g,这个大小足以存放我们需要分配的1百万的object对象(每个对象大小为16byte,总大小为0.014GB)了,这个大小可以消除不同GC本身之前的一些差距。

使用默认的G1 GC(从JDK9开始，G1GC成为默认GC)。

因为MacOS的time默认不展示real 字段，所以我特意使用了 /usr/bin/time 工具

/usr/bin/time java -Xms4G -Xmx4G -Xlog:gc AL
[0.007s][info][gc] Using G1
[0.301s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 371M->368M(4096M) 158.715ms
[0.498s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 746M->749M(4096M) 114.960ms
[0.689s][info][gc] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 1107M->1110M(4096M) 111.711ms
[0.995s][info][gc] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 1556M->1559M(4096M) 114.919ms
[1.118s][info][gc] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 1737M->1741M(4096M) 82.366ms
[1.234s][info][gc] GC(5) Pause Young (Concurrent Start) (G1 Humongous Allocation) 1900M->1903M(4096M) 80.075ms
[1.234s][info][gc] GC(6) Concurrent Mark Cycle
[1.550s][info][gc] GC(7) Pause Young (Normal) (G1 Evacuation Pause) 2483M->2487M(4096M) 87.877ms
[1.685s][info][gc] GC(8) Pause Young (Normal) (G1 Evacuation Pause) 2665M->2669M(4096M) 87.910ms
[2.148s][info][gc] GC(6) Pause Remark 2771M->2225M(4096M) 0.906ms
[3.071s][info][gc] GC(6) Pause Cleanup 2225M->2225M(4096M) 0.260ms
[3.091s][info][gc] GC(6) Concurrent Mark Cycle 1856.732ms
        3.14 real         9.63 user         0.79 sys

从G1GC的日志中可以看到，平均的GC暂停时间在100ms左右。

注意最后的三个时间，细心的读者会发现user(用户态时间) > real(实际时间) , 这是因为在程序会使用多线程来运行，多线程运行的总时间就是user时间，所以它会比real 时间更长。

整体运行时间为3.14s

使用ZGC

/usr/bin/time java -XX:+UseZGC -Xms4G -Xmx4G -Xlog:gc AL
[0.011s][info][gc] Using The Z Garbage Collector
[0.274s][info][gc] GC(0) Garbage Collection (Warmup) 500M(12%)->826M(20%)
[0.748s][info][gc] GC(1) Garbage Collection (Warmup) 826M(20%)->2012M(49%)
[2.103s][info][gc] GC(2) Garbage Collection (Warmup) Aborted
        2.20 real         3.18 user         1.02 sys

ZGC的日志中没有展示具体的GC耗时，总共进行了三次GC，最后一次GC因为jvm运行完，被终止。

可以从real时间上看出，整体花费了2.2s。

使用ShenandoahGC

/usr/bin/time java -XX:+UseShenandoahGC  -Xms4G -Xmx4G -Xlog:gc AL
[0.002s][info][gc] Min heap equals to max heap, disabling ShenandoahUncommit
[0.006s][info][gc] Heuristics ergonomically sets -XX:+ExplicitGCInvokesConcurrent
[0.006s][info][gc] Heuristics ergonomically sets -XX:+ShenandoahImplicitGCInvokesConcurrent
[0.007s][info][gc] Using Shenandoah
[0.238s][info][gc] Trigger: Learning 1 of 5. Free (2860M) is below initial threshold (2867M)
[0.238s][info][gc] GC(0) Concurrent reset 0.149ms
[0.253s][info][gc] GC(0) Pause Init Mark (unload classes) 0.125ms
[0.253s][info][gc] GC(0) Concurrent marking roots 0.087ms
[0.581s][info][gc] GC(0) Concurrent marking (unload classes) 327.894ms
[0.637s][info][gc] GC(0) Pause Final Mark (unload classes) 0.531ms
[0.637s][info][gc] GC(0) Concurrent weak references 0.016ms
[0.637s][info][gc] GC(0) Concurrent weak roots 0.089ms
[0.637s][info][gc] GC(0) Concurrent cleanup 2281M->2047M(4096M) 0.008ms
[0.637s][info][gc] GC(0) Concurrent class unloading 0.073ms
[0.637s][info][gc] GC(0) Pause Final Roots 0.002ms
[0.638s][info][gc] Trigger: Learning 2 of 5. Free (1832M) is below initial threshold (2867M)
[0.640s][info][gc] GC(1) Concurrent reset 1.395ms
[0.640s][info][gc] GC(1) Pause Init Mark (unload classes) 0.019ms
[0.640s][info][gc] GC(1) Concurrent marking roots 0.082ms
[0.749s][info][gc] Cancelling GC: Stopping VM
[0.750s][info][gc] GC(1) Concurrent marking (unload classes) 110.003ms
       0.79 real         1.23 user         0.28 sys

带有Pause标记的GC时间，整体时间平均在不到1ms.

总的运行时间为 0.79s.

使用并发GC，UseParallelGC

/usr/bin/time java -XX:+UseParallelGC -Xms4G -Xmx4G -Xlog:gc AL
[0.006s][info][gc] Using Parallel
[0.956s][info][gc] GC(0) Pause Young (Allocation Failure) 878M->714M(3925M) 752.631ms
[2.209s][info][gc] GC(1) Pause Young (Allocation Failure) 1738M->1442M(3925M) 1116.042ms
        2.36 real        12.55 user         0.51 sys

UseParallelGC 是并行(parallel)但不并发(concurrent)的GC,暂停时间 752ms - 1116ms。这个级别的延迟非常影响用户体验。

CMS ,无法执行，CMS已经在后续的版本中被移除了，G1彻底取代了CMS

/usr/bin/time java -XX:+UseConcMarkSweepGC -Xms4G -Xmx4G -Xlog:gc AL
Unrecognized VM option 'UseConcMarkSweepGC'
Error: Could not create the Java Virtual Machine.
Error: A fatal exception has occurred. Program will exit.
        0.02 real         0.01 user         0.00 sys

总结

本文中我们使用一个分配一百万对象的方法结合目前的各种GC进行了测试，展示了各种GC的暂停时间和总运行时间。实际工作中，我们应该根据 应用负载特性，GC特性,性能需求SLO(比如要求99.99%的请求都在50ms以内)等因素来综合考虑选择GC。