G1 GC日志详解
⭐⭐⭐⭐⭐⭐
Github主页👉https://github.com/A-BigTree
笔记链接👉https://github.com/A-BigTree/Code_Learning
⭐⭐⭐⭐⭐⭐
如果可以，麻烦各位看官顺手点个star~😊
关于G1回收器的前置知识点：
1 G1 GC周期
G1 有两个阶段，它会在这两个阶段往返，分别是 Young-only，Space Reclamation.
- Young-only阶段包含一系列逐渐填满老年代Regin的 GC
- Space Reclamation 阶段G1会递进地回收老年代Regin的空间，同时也处理新生代Region
上图来自 oracle 上对GC周期的描述，实心圆都表示一次 GC 停顿
- 蓝色：Young GC的停顿
- 黄色：标记过程的停顿
- 红色：Mixed GC停顿
在几次GC后，老年代Regin的对象占有比超过了 InitiatingHeapOccupancyPercent，GC就会进入并发标记准备(concurrent mark)。
2 G1日志开启与设置
在java程序运行时，加入运行参数来开启GC日志，不同的参数日志打印的精细程度也不同
-verbosegc(等同于-XX:+PrintGC)：打印细节（最不细节）GC日志
示例：
[GC pause (G1 Humongous Allocation) (young) (initial-mark) 24M- >21M(64M), 0.2349730 secs]
[GC pause (G1 Evacuation Pause) (mixed) 66M->21M(236M), 0.1625268 secs]
-XX:+PrintGCDetails：打印比较细节的CG日志- 显示每个阶段的平均时间、最小时间、和最大时间；
- 根扫描、RSet 更新（带有已处理的缓冲区信息）、RSet 扫描、对象复制、终止（带有尝试次数）；
- 还显示其他执行时间，例如选择 CSet、引用处理、引用排队和释放 CSet 所花费的时间；
- 显示Eden区、幸存区和的整个堆的占用情况；
示例：
[Ext Root Scanning (ms): Avg: 1.7 Min: 0.0 Max: 3.7 Diff: 3.7]
[Eden: 818M(818M)->0B(714M) Survivors: 0B->104M Heap: 836M(4096M)->409M(4096M)]
-XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest：打印最细节的CG日志- 在上面配置的基础上多了线程显示
示例：
[Ext Root Scanning (ms): 2.1 2.4 2.0 0.0
Avg: 1.6 Min: 0.0 Max: 2.4 Diff: 2.3]
[Update RS (ms): 0.4 0.2 0.4 0.0
Avg: 0.2 Min: 0.0 Max: 0.4 Diff: 0.4]
[Processed Buffers : 5 1 10 0
Sum: 16, Avg: 4, Min: 0, Max: 10, Diff: 10]
还有其他参数可以控制打印日志时间和其他显示项目。
3 Young GC日志
# 开始Young GC
[gc,start ] GC(78) Pause Young (Normal) (G1 Evacuation Pause)
[gc,task ] GC(78) Using 10 workers of 10 for evacuation
[gc,phases ] GC(78) Pre Evacuate Collection Set: 3.2ms
[gc,phases ] GC(78) Evacuate Collection Set: 28.8ms
[gc,phases ] GC(78) Post Evacuate Collection Set: 1.8ms
[gc,phases ] GC(78) Other: 1.1ms
[gc,heap ] GC(78) Eden regions: 538->0(871)
[gc,heap ] GC(78) Survivor regions: 69->33(76)
# 老年代被分配
[gc,heap ] GC(78) Old regions: 1041->1077
[gc,heap ] GC(78) Humongous regions: 3->1
[gc,metaspace ] GC(78) Metaspace: 71777K->71777K(1114112K)
[gc ] GC(78) Pause Young (Normal) (G1 Evacuation Pause) 3300M->2220M(6144M) 34.907ms
[gc,cpu ] GC(78) User=0.24s Sys=0.05s Real=0.04s
4 Mixed GC
# Young GC(并发标记开始，1.初始标记)
[gc,start ] GC(79) Pause Young (Concurrent Start) (G1 Humongous Allocation)
[gc,task ] GC(79) Using 10 workers of 10 for evacuation
[gc,phases ] GC(79) Pre Evacuate Collection Set: 0.2ms
[gc,phases ] GC(79) Evacuate Collection Set: 22.3ms
[gc,phases ] GC(79) Post Evacuate Collection Set: 0.9ms
[gc,phases ] GC(79) Other: 1.8ms
[gc,heap ] GC(79) Eden regions: 569->0(656)
[gc,heap ] GC(79) Survivor regions: 33->55(113)
[gc,heap ] GC(79) Old regions: 1077->1077
[gc,heap ] GC(79) Humongous regions: 1->1
[gc,metaspace ] GC(79) Metaspace: 71780K->71780K(1114112K)
[gc ] GC(79) Pause Young (Concurrent Start) (G1 Humongous Allocation) 3357M->2264M(6144M) 25.305ms
[gc,cpu ] GC(79) User=0.21s Sys=0.00s Real=0.03s
# 2.开始并发标记
[gc ] GC(80) Concurrent Cycle
[gc,marking ] GC(80) Concurrent Clear Claimed Marks
[gc,marking ] GC(80) Concurrent Clear Claimed Marks 0.147ms
[gc,marking ] GC(80) Concurrent Scan Root Regions
[gc,marking ] GC(80) Concurrent Scan Root Regions 16.125ms
[gc,marking ] GC(80) Concurrent Mark (373.358s)
[gc,marking ] GC(80) Concurrent Mark From Roots
[gc,task ] GC(80) Using 4 workers of 4 for marking
[gc,marking ] GC(80) Concurrent Mark From Roots 57.029ms
[gc,marking ] GC(80) Concurrent Preclean
[gc,marking ] GC(80) Concurrent Preclean 0.454ms
[gc,marking ] GC(80) Concurrent Mark (373.358s, 373.415s) 57.548ms
# 3.SWT 最终标记阶段
[gc,start ] GC(80) Pause Remark
[gc,stringtable] GC(80) Cleaned string and symbol table, strings: 36361 processed, 315 removed, symbols: 192117 processed, 500 removed
[gc ] GC(80) Pause Remark 2326M->956M(6144M) 14.454ms
[gc,cpu ] GC(80) User=0.08s Sys=0.03s Real=0.02s
# 并发构建RSet
[gc,marking ] GC(80) Concurrent Rebuild Remembered Sets
[gc,marking ] GC(80) Concurrent Rebuild Remembered Sets 38.843ms
# 4.清楚整理
[gc,start ] GC(80) Pause Cleanup
[gc ] GC(80) Pause Cleanup 974M->974M(6144M) 0.660ms
[gc,cpu ] GC(80) User=0.00s Sys=0.00s Real=0.00s
[gc,marking ] GC(80) Concurrent Cleanup for Next Mark
[gc,marking ] GC(80) Concurrent Cleanup for Next Mark 16.673ms
[gc ] GC(80) Concurrent Cycle 146.748ms
# Mixed GC
[gc,start ] GC(81) Pause Young (Mixed) (G1 Evacuation Pause)
[gc,task ] GC(81) Using 10 workers of 10 for evacuation
[gc,mmu ] GC(81) MMU target violated: 61.0ms (60.0ms/61.0ms)
[gc,phases ] GC(81) Pre Evacuate Collection Set: 0.1ms
[gc,phases ] GC(81) Evacuate Collection Set: 76.8ms
[gc,phases ] GC(81) Post Evacuate Collection Set: 0.9ms
[gc,phases ] GC(81) Other: 1.1ms
[gc,heap ] GC(81) Eden regions: 211->0(136)
[gc,heap ] GC(81) Survivor regions: 55->17(34)
# Mixed GC 老年代被回收
[gc,heap ] GC(81) Old regions: 392->312
[gc,heap ] GC(81) Humongous regions: 3->1
[gc,metaspace ] GC(81) Metaspace: 71780K->71780K(1114112K)
[gc ] GC(81) Pause Young (Mixed) (G1 Evacuation Pause) 1320M->919M(6144M) 78.857ms
[gc,cpu ] GC(81) User=0.41s Sys=0.37s Real=0.08s
- GC（79）：因为（G1 Humongous Allocation）巨大对象分配开始Young GC同时并发标记开始；
- GC（80）：GC（79）已完成第一阶段的初始标记，开始并发标记、最终标记、清楚整理；
- GC（81）：GC（80）已获取新生代和老年代标记信息，开始进行Mixed GC，新生代和老年代Regin同时被回收整理；
5 Full GC
下面的日志正好是博主在工作时排查Full GC问题时真实遇到到，生产环境日志比较复杂，这里稍微删减标注了供大家参考～
# 1.Mixed GC尝试分配巨大对象
[gc,start ] GC(1362) Pause Young (Mixed) (G1 Humongous Allocation)
[gc,task ] GC(1362) Using 8 workers of 8 for evacuation
[gc,phases ] GC(1362) Pre Evacuate Collection Set: 0.3ms
[gc,phases ] GC(1362) Evacuate Collection Set: 23.9ms
[gc,phases ] GC(1362) Post Evacuate Collection Set: 19.6ms
[gc,phases ] GC(1362) Other: 4.3ms
[gc,heap ] GC(1362) Eden regions: 3->0(755)
[gc,heap ] GC(1362) Survivor regions: 2->2(74)
[gc,heap ] GC(1362) Old regions: 1617->1443
[gc,heap ] GC(1362) Humongous regions: 144->133
[gc,metaspace ] GC(1362) Metaspace: 419538K->419538K(1300480K)
[gc ] GC(1362) Pause Young (Mixed) (G1 Humongous Allocation) 7054M->6305M(9832M) 47.441ms
[gc,cpu ] GC(1362) User=0.27s Sys=0.01s Real=0.05s
# 2.Mixed GC后空间无法满足，Young GC（并发标记）
[gc,start ] GC(1363) Pause Young (Concurrent Start) (G1 Humongous Allocation)
[gc,task ] GC(1363) Using 8 workers of 8 for evacuation
[gc,phases ] GC(1363) Pre Evacuate Collection Set: 0.6ms
[gc,phases ] GC(1363) Evacuate Collection Set: 21.2ms
[gc,phases ] GC(1363) Post Evacuate Collection Set: 19.5ms
[gc,phases ] GC(1363) Other: 3.1ms
[gc,heap ] GC(1363) Eden regions: 5->0(735)
[gc,heap ] GC(1363) Survivor regions: 2->2(95)
[gc,heap ] GC(1363) Old regions: 1443->1443
[gc,heap ] GC(1363) Humongous regions: 144->138
[gc,metaspace ] GC(1363) Metaspace: 419538K->419538K(1300480K)
[gc ] GC(1363) Pause Young (Concurrent Start) (G1 Humongous Allocation) 6365M->6325M(9832M) 43.719ms
[gc,cpu ] GC(1363) User=0.25s Sys=0.00s Real=0.05s
# 3.开始并发标记
[gc ] GC(1364) Concurrent Cycle
[gc,marking ] GC(1364) Concurrent Clear Claimed Marks
[gc,marking ] GC(1364) Concurrent Clear Claimed Marks 0.509ms
[gc,marking ] GC(1364) Concurrent Scan Root Regions
[gc,marking ] GC(1364) Concurrent Scan Root Regions 5.111ms
[gc,marking ] GC(1364) Concurrent Mark From Roots
[gc,task ] GC(1364) Using 2 workers of 2 for marking
# 4.第一次Young GC仍然空间不够，为在年轻代分配巨大对象，继续引发Young GC
[gc,start ] GC(1365) Pause Young (Normal) (G1 Humongous Allocation)
[gc,task ] GC(1365) Using 8 workers of 8 for evacuation
[gc,phases ] GC(1365) Pre Evacuate Collection Set: 3.0ms
[gc,phases ] GC(1365) Evacuate Collection Set: 9.0ms
[gc,phases ] GC(1365) Post Evacuate Collection Set: 17.9ms
[gc,phases ] GC(1365) Other: 2.3ms
# 回收无效果
[gc,heap ] GC(1365) Eden regions: 0->0(735)
[gc,heap ] GC(1365) Survivor regions: 2->2(93)
[gc,heap ] GC(1365) Old regions: 1443->1443
[gc,heap ] GC(1365) Humongous regions: 138->138
[gc,metaspace ] GC(1365) Metaspace: 419538K->419538K(1300480K)
[gc ] GC(1365) Pause Young (Normal) (G1 Humongous Allocation) 6325M->6325M(9832M) 28.565ms
[gc,cpu ] GC(1365) User=0.18s Sys=0.00s Real=0.02s
# 5.开始Full GC
[gc,task ] GC(1366) Using 8 workers of 8 for full compaction
[gc,start ] GC(1366) Pause Full (G1 Humongous Allocation)
[gc,phases,start] GC(1366) Phase 1: Mark live objects
[gc,stringtable ] GC(1366) Cleaned string and symbol table, strings: 141014 processed, 117 removed, symbols: 838192 processed, 0 removed
[gc,phases ] GC(1366) Phase 1: Mark live objects 246.403ms
[gc,phases,start] GC(1366) Phase 2: Prepare for compaction
[gc,phases ] GC(1366) Phase 2: Prepare for compaction 56.600ms
[gc,phases,start] GC(1366) Phase 3: Adjust pointers
[gc,phases ] GC(1366) Phase 3: Adjust pointers 148.139ms
[gc,phases,start] GC(1366) Phase 4: Compact heap
[gc,phases ] GC(1366) Phase 4: Compact heap 138.928ms
[gc,heap ] GC(1366) Eden regions: 0->0(450)
[gc,heap ] GC(1366) Survivor regions: 2->0(93)
# 效果显著
[gc,heap ] GC(1366) Old regions: 1443->320
[gc,heap ] GC(1366) Humongous regions: 138->130
[gc,metaspace ] GC(1366) Metaspace: 419538K->419538K(1300480K)
[gc ] GC(1366) Pause Full (G1 Humongous Allocation) 6325M->1769M(6000M) 744.919ms
[gc,cpu ] GC(1366) User=4.18s Sys=0.19s Real=0.75s
# 6. Full GC后巨大对象已分配，停止并发标记
[gc,marking ] GC(1364) Concurrent Mark From Roots 777.174ms
[gc,marking ] GC(1364) Concurrent Mark Abort
[gc ] GC(1364) Concurrent Cycle 782.954ms