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

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。

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 158,560评论 4 361
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 67,104评论 1 291
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 108,297评论 0 243
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 43,869评论 0 204
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 52,275评论 3 287
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 40,563评论 1 216
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,833评论 2 312
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 30,543评论 0 197
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 34,245评论 1 241
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,512评论 2 244
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 32,011评论 1 258
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 28,359评论 2 253
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 33,006评论 3 235
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,062评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,825评论 0 194
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 35,590评论 2 273
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 35,501评论 2 268

推荐阅读更多精彩内容