JVM解剖公园3:GC设计和暂停

问题

GC是程序的敌人,但我不能害怕,因为害怕是心灵杀手,害怕是慢性死亡...等等,我刚在说什么?
好吧,今天的问题其实是要讨论“在数组中分配100M的对象可以让Java程序在几秒钟内短暂嗝屁”的说法是真的吗?

背景

我们经常把GC视为性能杀手,说GC的实现辜负了家乡父老的期待。不过,有时这些期待本身就有问题,用了不合适的GC策略,让我们看看OpenJDK中的GC是什么样子:

黄色是JVM短暂嗝屁的“stop-the-world”阶段,绿色是并发阶段。
大多数收集器在常规GC循环中的都有暂停现象。

实验

我们本可以拒绝做“在数组中分配100M的对象 ”的测试,这不切实际。

import java.util.*;

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

关于这一点,有一头的母牛有话要说:

$ cow say ...
 ________________________
/哞......,这是一个蹩脚的GC  \
| 基准测试。我一头牛都能看明白 |
 -------------------------
        \   ^__^
         \  (oo)\_______
            (__)\       )\/\
                ||----w |
                ||     ||

即使是蹩脚的基准测试也会告诉你有关被测系统的信息。你只要认真了解它告诉你什么。事实证明,上面代码照样能显示出OpenJDK中不同收集器的GC设计。

让我们使用最新的JDK 9 + Shenandoah收集器来认识最新的GC改进。
请在装有Linux x86_64的低配 1.7 GHz i5 Ultrabook超极本上执行此操作。由于我们即将分配100M 16字节对象,因此将堆设置为固定的4GB,这某种程度上消除了收集器之间的差异。

G1(默认为JDK 9)

$ time java -Xms4G -Xmx4G -Xlog:gc AL
[0.030s][info][gc] Using G1
[1.525s][info][gc] GC(0) Pause Young (G1 Evacuation Pause) 370M->367M(4096M) 991.610ms
[2.808s][info][gc] GC(1) Pause Young (G1 Evacuation Pause) 745M->747M(4096M) 928.510ms
[3.918s][info][gc] GC(2) Pause Young (G1 Evacuation Pause) 1105M->1107M(4096M) 764.967ms
[5.061s][info][gc] GC(3) Pause Young (G1 Evacuation Pause) 1553M->1555M(4096M) 601.680ms
[5.835s][info][gc] GC(4) Pause Young (G1 Evacuation Pause) 1733M->1735M(4096M) 465.216ms
[6.459s][info][gc] GC(5) Pause Initial Mark (G1 Humongous Allocation) 1894M->1897M(4096M) 398.453ms
[6.459s][info][gc] GC(6) Concurrent Cycle //并发GC循环
[7.790s][info][gc] GC(7) Pause Young (G1 Evacuation Pause) 2477M->2478M(4096M) 472.079ms
[8.524s][info][gc] GC(8) Pause Young (G1 Evacuation Pause) 2656M->2659M(4096M) 434.435ms
[11.104s][info][gc] GC(6) Pause Remark 2761M->2761M(4096M) 1.020ms
[11.979s][info][gc] GC(6) Pause Cleanup 2761M->2215M(4096M) 2.446ms
[11.988s][info][gc] GC(6) Concurrent Cycle 5529.427ms

real  0m12.016s
user  0m34.588s
sys   0m0.964s

元芳,你对G1怎么看?
大人,平均500~1000 ms的年轻代暂停。稳定状态可能会更小,并且能启发式计算出暂停时间。一段时间后,并发GC循环阶段开始,并持续到结束。(注意Pause Young与Concurrent Cycle阶段重叠)。本来应该是“混合”收集暂停,但VM在此之前已经退出。这些间歇性的停顿确实促成了这项工作的长期运行。

另外,“user”时间大于“real”时间。这是当程序在单个线程中运行时,而GC在并行执行,这会让GC更快。

Parallel

$ time java -XX:+UseParallelOldGC -Xms4G -Xmx4G -Xlog:gc AL
[0.023s][info][gc] Using Parallel
[1.579s][info][gc] GC(0) Pause Young (Allocation Failure) 878M->714M(3925M) 1144.518ms
[3.619s][info][gc] GC(1) Pause Young (Allocation Failure) 1738M->1442M(3925M) 1739.009ms

real  0m3.882s
user  0m11.032s
sys   0m1.516s

在Parallel中,有类似的年轻代暂停,这也可能使Eden / Survivors区的能接受更多的临时分配。两个大暂停后,GC工作很快就完成了。在稳定状态下,这个收集器可能会保持相同的大停顿。“user”>>“real”也同上面一样,有一些开销隐藏在并发GC后。

Concurrent Mark Sweep
$ time java -XX:+UseConcMarkSweepGC -Xms4G -Xmx4G -Xlog:gc AL
[0.012s][info][gc] Using Concurrent Mark Sweep
[1.984s][info][gc] GC(0) Pause Young (Allocation Failure) 259M->231M(4062M) 1788.983ms
[2.938s][info][gc] GC(1) Pause Young (Allocation Failure) 497M->511M(4062M) 871.435ms
[3.970s][info][gc] GC(2) Pause Young (Allocation Failure) 777M->850M(4062M) 949.590ms
[4.779s][info][gc] GC(3) Pause Young (Allocation Failure) 1117M->1161M(4062M) 732.888ms
[6.604s][info][gc] GC(4) Pause Young (Allocation Failure) 1694M->1964M(4062M) 1662.255ms
[6.619s][info][gc] GC(5) Pause Initial Mark 1969M->1969M(4062M) 14.831ms
[6.619s][info][gc] GC(5) Concurrent Mark
[8.373s][info][gc] GC(6) Pause Young (Allocation Failure) 2230M->2365M(4062M) 1656.866ms
[10.397s][info][gc] GC(7) Pause Young (Allocation Failure) 3032M->3167M(4062M) 1761.868ms
[16.323s][info][gc] GC(5) Concurrent Mark 9704.075ms
[16.323s][info][gc] GC(5) Concurrent Preclean
[16.365s][info][gc] GC(5) Concurrent Preclean 41.998ms
[16.365s][info][gc] GC(5) Concurrent Abortable Preclean
[16.365s][info][gc] GC(5) Concurrent Abortable Preclean 0.022ms
[16.478s][info][gc] GC(5) Pause Remark 3390M->3390M(4062M) 113.598ms
[16.479s][info][gc] GC(5) Concurrent Sweep
[17.696s][info][gc] GC(5) Concurrent Sweep 1217.415ms
[17.696s][info][gc] GC(5) Concurrent Reset
[17.701s][info][gc] GC(5) Concurrent Reset 5.439ms

real  0m17.719s
user  0m45.692s
sys   0m0.588s

与流行的说法相反,在CMS中,“并发”只意味着老年代的并发收集。正如我们在这里看到的那样,年轻代收集仍在stop-the-world。从GC日志的角度来看,分阶段看起来有点像G1:年轻代停顿,并发循环。不同之处在于,与G1混合暂停相反,“并发收集”可以在不停止应用的情况下清除对象。但是,较长的Young GC暂停,导致它的性能只是相对快了点。

Shenandoah

$ time java -XX:+UseShenandoahGC -Xms4G -Xmx4G -Xlog:gc AL
[0.026s][info][gc] Using Shenandoah
[0.808s][info][gc] GC(0) Pause Init Mark 0.839ms
[1.883s][info][gc] GC(0) Concurrent marking 2076M->3326M(4096M) 1074.924ms
[1.893s][info][gc] GC(0) Pause Final Mark 3326M->2784M(4096M) 10.240ms
[1.894s][info][gc] GC(0) Concurrent evacuation  2786M->2792M(4096M) 0.759ms
[1.894s][info][gc] GC(0) Concurrent reset bitmaps 0.153ms
[1.895s][info][gc] GC(1) Pause Init Mark 0.920ms
[1.998s][info][gc] Cancelling concurrent GC: Stopping VM
[2.000s][info][gc] GC(1) Concurrent marking 2794M->2982M(4096M) 104.697ms

real  0m2.021s
user  0m5.172s
sys   0m0.420s

Shenandoah中没有年轻代收集(至少现在我们有一些想法:如何在不引入分代机制的情况下快速进行部分收集,希望不会是世界末日)。
然后,并发GC循环启动,并与应用程序一起运行,通过两次小暂停完成并发标记。并发复制时没有暂停,一切活动着。后面由于VM关闭,第二个GC周期提前终止。
以上,就解释了Shenandoah为什么会快。

Epsilon

$ time java -XX:+UnlockExperimentalVMOptions -XX:+UseEpsilonGC -Xms4G -Xmx4G  -Xlog:gc AL
[0.031s][info][gc] Initialized with 4096M non-resizable heap.
[0.031s][info][gc] Using Epsilon GC
[1.361s][info][gc] Total allocated: 2834042 KB.
[1.361s][info][gc] Average allocation rate: 2081990 KB/sec

real  0m1.415s
user  0m1.240s
sys   0m0.304s

运行实验性的"no-op(无操作)" Epsilon GC可以估算不运行收集器时的GC开销。在这里,我们用预先调整的4GB堆,并且程序运行时不会有任何暂停。如果程序更频繁修改堆内存数据,它将无法继续运行。请注意,“real”和“user”+“sys”的时间几乎相等,这证明理论上只有一个应用程序线程。

结论

不同的GC在其实现中有不同的考量。将GC干掉是是一个糟糕的主意。
通过了解实际业务,可用GC的类型和性能要求,为程序选择一个收集器。即使针对没有GC的平台,我们仍然需要知道(并选择)本机内存分配。运行实验程序时,请尝试了解它们的机制,并从中学习。
为了世界和平。

Comments
Write a Comment