初探JAVA 10之G1收集器并行Full GC

96
Roger_黄
2018.04.29 18:10 字数 1387

G1收集器时JAVA 9正式引入的。JAVA 10发布之后,对G1收集器的Full GC做了优化,优化点就是把单线程的Full GC变成了多线程并行Full GC。那我们怎么看出这个优化点呢?下面我们来做个实验。

ObjectChurn

上面的代码会往data数组里面写数据,重复十遍。我们先用JDK 9来看看程序GC情况如何。启动之前,我们加入JVM启动参数:-Xlog:gc,gc+cpu::uptime -Xmx4g -Xms4g -Xlog:gc*:details.vgc。注:-Xlog:gc,gc+cpu::uptime就是把GC的每一个事件和CPU使用情况打印到控制台,使用uptime作为标签打印在最前面。 -Xlog:gc*跟JDK 9之前的-XX:+PrintGCDetails是一样的意思,就是打印GC详细日志,后面的details.vgc就是GC日志写入的文件。对了,我的CPU是4核。

我们先用JDK 9执行一遍该程序。执行完毕之后分析以下打出来的日志。取一个cycle出来:

[13.886s] GC(106) Pause Initial Mark (G1 Humongous Allocation) 3467M->3459M(4096M) 21.957ms

[13.886s] GC(106) User=0.16s Sys=0.00s Real=0.02s

[13.886s] GC(107) Concurrent Cycle

[13.942s] GC(108) Pause Young (G1 Evacuation Pause) 3669M->3648M(4096M) 38.552ms

[13.943s] GC(108) User=0.22s Sys=0.00s Real=0.03s

[13.993s] GC(109) To-space exhausted

[13.993s] GC(109) Pause Young (G1 Evacuation Pause) 3882M->3894M(4096M) 22.696ms

[13.993s] GC(109) User=0.17s Sys=0.01s Real=0.03s

[13.997s] GC(107) Pause Remark 3914M->3914M(4096M) 1.153ms

[13.997s] GC(107) User=0.00s Sys=0.00s Real=0.00s

[14.019s] GC(110) To-space exhausted

[14.019s] GC(110) Pause Young (G1 Evacuation Pause) 4040M->4034M(4096M) 9.122ms

[14.019s] GC(110) User=0.07s Sys=0.00s Real=0.01s

[14.021s] GC(111) To-space exhausted

[14.021s] GC(111) Pause Young (G1 Evacuation Pause) 4040M->4040M(4096M) 1.599ms

[14.021s] GC(111) User=0.01s Sys=0.00s Real=0.00s

[14.784s] GC(112) Pause Full (Allocation Failure) 4040M->3331M(4096M) 762.372ms

[14.784s] GC(112) User=0.87s Sys=0.00s Real=0.77s

[14.784s] GC(107) Concurrent Cycle 898.093ms

[14.800s] GC(113) Pause Initial Mark (G1 Humongous Allocation) 3418M->3419M(4096M) 10.044ms

[14.800s] GC(113) User=0.08s Sys=0.00s Real=0.01s

[14.800s] GC(114) Concurrent Cycle

[14.839s] GC(115) Pause Young (G1 Evacuation Pause) 3623M->3594M(4096M) 23.689ms

[14.839s] GC(115) User=0.18s Sys=0.00s Real=0.02s

[14.880s] GC(116) Pause Young (G1 Evacuation Pause) 3772M->3725M(4096M) 24.273ms

[14.880s] GC(116) User=0.18s Sys=0.01s Real=0.02s

[14.890s] GC(114) Pause Remark 3813M->3813M(4096M) 1.140ms

[14.890s] GC(114) User=0.01s Sys=0.00s Real=0.00s

我标黑了两段日志。第一段是新生代的收集日志。user time是0.17秒,real time是0.03秒。user time是指gc花费的所有CPU时间之和,real time是指gc暂停的实际时间。第二段是full gc的日志。user time是0.87秒,real time是0.77秒,两者相差无几。

换成JDK 10再执行一遍。

[13.589s] GC(107) To-space exhausted

[13.589s] GC(107) Pause Young (G1 Evacuation Pause) 4033M->4025M(4096M) 9.213ms

[13.589s] GC(107) User=0.05s Sys=0.01s Real=0.00s

[13.592s] GC(108) To-space exhausted

[13.592s] GC(108) Pause Young (G1 Evacuation Pause) 4033M->4031M(4096M) 2.165ms

[13.592s] GC(108) User=0.00s Sys=0.00s Real=0.00s

[13.593s] GC(109) To-space exhausted

[13.594s] GC(109) Pause Young (G1 Evacuation Pause) 4033M->4033M(4096M) 0.859ms

[13.594s] GC(109) User=0.01s Sys=0.00s Real=0.00s

[14.201s] GC(110) Pause Full (Allocation Failure) 4033M->3275M(4096M) 607.673ms

[14.202s] GC(110) User=3.94s Sys=0.03s Real=0.61s

[14.202s] GC(103) Concurrent Cycle 782.493ms

[14.204s] GC(111) Pause Initial Mark (G1 Humongous Allocation) 3277M->3277M(4096M) 1.856ms

[14.204s] GC(111) User=0.00s Sys=0.00s Real=0.00s

[14.204s] GC(112) Concurrent Cycle

[14.263s] GC(113) Pause Young (G1 Evacuation Pause) 3511M->3490M(4096M) 28.171ms

[14.263s] GC(113) User=0.20s Sys=0.01s Real=0.03s

[14.283s] GC(112) Pause Remark 3662M->3662M(4096M) 2.256ms

[14.283s] GC(112) User=0.01s Sys=0.00s Real=0.00s

[14.314s] GC(114) Pause Young (G1 Evacuation Pause) 3722M->3724M(4096M) 25.194ms

[14.314s] GC(114) User=0.16s Sys=0.00s Real=0.02s

[14.350s] GC(115) To-space exhausted

[14.350s] GC(115) Pause Young (G1 Evacuation Pause) 3910M->3915M(4096M) 18.179ms

[14.350s] GC(115) User=0.12s Sys=0.00s Real=0.02s

[14.368s] GC(116) To-space exhausted

[14.368s] GC(116) Pause Young (G1 Humongous Allocation) 4031M->4003M(4096M) 7.258ms

[14.368s] GC(116) User=0.04s Sys=0.00s Real=0.00s

[14.371s] GC(117) To-space exhausted

[14.372s] GC(117) Pause Young (G1 Evacuation Pause) 4031M->4031M(4096M) 1.698ms

[14.372s] GC(117) User=0.01s Sys=0.00s Real=0.00s

[14.938s] GC(118) Pause Full (Allocation Failure) 4031M->3318M(4096M) 566.566ms

[14.939s] GC(118) User=3.53s Sys=0.03s Real=0.56s

[14.939s] GC(112) Concurrent Cycle 734.758ms

[14.957s] GC(119) Pause Initial Mark (G1 Humongous Allocation) 3391M->3388M(4096M) 10.799ms

[14.957s] GC(119) User=0.05s Sys=0.00s Real=0.01s

[14.957s] GC(120) Concurrent Cycle

[15.005s] GC(121) Pause Young (G1 Evacuation Pause) 3572M->3518M(4096M) 30.110ms

[15.005s] GC(121) User=0.18s Sys=0.01s Real=0.03s

同样,我也标黑了两段日志。第一段跟JDK 9的差不多,但是第二段就不一样了,user time是3.53秒,real time是0.56秒。这个差异是怎么来的呢?就是并行Full GC。JDK 10利用了CPU的多个核来做并行full gc,最后user time会增长成real time的好几倍,上面的日志里user time / real time = 6.2。

JAVA
Web note ad 1