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。
网友评论