G1垃圾回收器日志详解
新生代收集
GC pause (G1 Evacuation Pause) (young)
-- gc前堆内存分布情况
{Heap before GC invocations=1592 (full 4):
garbage-first heap total 6291456K, used 5011297K [0x0000000640000000, 0x0000000640206000, 0x00000007c0000000) --表示使用了G1,堆大小，已经使用大小
region size 2048K, 2048 young (4194304K), 0 survivors (0K) --Reign 大小是1M,yong 2048个，幸存去0个
Metaspace used 79313K, capacity 82517K, committed 83328K, reserved 1122304K
class space used 8641K, capacity 9393K, committed 9600K, reserved 1048576K
2023-05-07T13:43:00.358+0800: 153178.525: [GC pause (G1 Evacuation Pause) (young) --新生代minorgc
Desired survivor size 201326592 bytes, new threshold 15 (max 15)--动态年龄晋升阈值，from区域50%的空间，gc前的新生代空间描述
- age 1: 1855896 bytes, 1855896 total
- age 2: 983640 bytes, 2839536 total
- age 3: 567112 bytes, 3406648 total
500269.127: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 23363, predicted base time: 12.89 ms, remaining time: 187.11 ms, target pause time: 200.00 ms] --选择要收集的regin,cards是关于rset的卡表，预计扫描卡表时间12.89ms
500269.127: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1528 regions, survivors: 8 regions, predicted young region time: 31.77 ms] --添加rigin到cset
500269.127: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1528 regions, survivors: 8 regions, old: 0 regions, predicted pause time: 44.66 ms, target pause time: 200.00 ms] --预计收集时间44.66
2023-05-07T13:43:00.382+0800: 153178.550: [SoftReference, 0 refs, 0.0000481 secs]
2023-05-07T13:43:00.382+0800: 153178.550: [WeakReference, 0 refs, 0.0000081 secs]
2023-05-07T13:43:00.383+0800: 153178.550: [FinalReference, 40 refs, 0.0000298 secs]
2023-05-07T13:43:00.383+0800: 153178.550: [PhantomReference, 0 refs, 6 refs, 0.0000090 secs]
2023-05-07T13:43:00.383+0800: 153178.550: [JNI Weak Reference, 0.0000242 secs], 0.0291750 secs] --本次younggc，耗时0.029,以下是详细信息
[Parallel Time: 23.0 ms, GC Workers: 8] --8个线程执行了23ms
[GC Worker Start (ms): Min: 153178526.5, Avg: 153178526.6, Max: 153178526.7, Diff: 0.2] --线程开始时间，如果 Min 和 Max 相差很大，则可能表明使用了太多线程或机器上的其他进程正在从 JVM 内部的垃圾收集进程中窃取 CPU 时间
[Ext Root Scanning (ms): Min: 2.3, Avg: 4.8, Max: 8.7, Diff: 6.4, Sum: 38.3]--扫描类加载器、JNI 引用、JVM 系统根等外部（非堆）根需要多长时间
[Update RS (ms): Min: 11.1, Avg: 15.3, Max: 17.3, Diff: 6.2, Sum: 122.3] --每个线程花费在更新rset上的时间
[Processed Buffers: Min: 71, Avg: 164.1, Max: 220, Diff: 149, Sum: 1313]
[Scan RS (ms): Min: 0.2, Avg: 0.6, Max: 0.8, Diff: 0.5, Sum: 4.8] --扫描cset中的regin对应的rset,因为rset是points-into,避免扫描老年代，但是会产生浮动垃圾
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2] --扫描code root耗时。code root指的是经过JIT编译后的代码里，引用了heap中的对象。引用关系保存在RSet中
[Object Copy (ms): Min: 0.0, Avg: 1.5, Max: 1.8, Diff: 1.8, Sum: 11.9]--拷贝活的对象到新region的耗时
[Termination (ms): Min: 0.0, Avg: 0.4, Max: 0.5, Diff: 0.5, Sum: 3.2] --线程结束，在结束前，它会检查其他线程是否还有未扫描完的引用，如果有，则”偷”过来，完成后再申请结束，这个时间是线程之前互相同步所花费的时间
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8] --线程尝试终止的次数。如果 worker 发现实际上还有更多工作要做，并且现在终止还为时过早，则尝试失败
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.6]
[GC Worker Total (ms): Min: 22.5, Avg: 22.7, Max: 22.8, Diff: 0.3, Sum: 181.5] --每个线程花费的时间和
[GC Worker End (ms): Min: 153178549.2, Avg: 153178549.3, Max: 153178549.4, Diff: 0.1] --每个线程结束的时间
[Code Root Fixup: 0.2 ms] --用来将code root修正到正确的evacuate之后的对象位置所花费的时间
[Code Root Purge: 0.2 ms] --清除code root的耗时，code root中的引用已经失效，不再指向Region中的对象，所以需要被清除
[Clear CT: 0.8 ms] --清除card table的耗时
[Other: 5.0 ms] --其他事项共耗时5.0ms，其他事项包括，处理已用对象，
[Choose CSet: 0.0 ms] --选择CSet
[Ref Proc: 0.5 ms] --处理非强引用锁花费的时间：清除它们或者确认不清除
[Ref Enq: 0.0 ms] --剩余非强引用添加到ReferenceQueues，
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.3 ms]
[Humongous Reclaim: 0.4 ms]
[Free CSet: 2.1 ms] --释放CSet中的region到free list
[Eden: 4096.0M(4096.0M)->0.0B(4092.0M) Survivors: 0.0B->4096.0K Heap: 4893.8M(6144.0M)->630.5M(6144.0M)] --新生代清空了，下次缩容到4092M
-- gc后堆内存分布情况
Heap after GC invocations=1593 (full 4):
garbage-first heap total 6291456K, used 645599K [0x0000000640000000, 0x0000000640206000, 0x00000007c0000000)
region size 2048K, 2 young (4096K), 2 survivors (4096K)
Metaspace used 79313K, capacity 82517K, committed 83328K, reserved 1122304K
class space used 8641K, capacity 9393K, committed 9600K, reserved 1048576K
}
[Times: user=0.16 sys=0.00, real=0.03 secs] --user垃圾收集器线程在此收集期间消耗的总 CPU 时间，sys花费在操作系统调用或等待系统事件上的时间，real应用程序停止的时钟时间并发收集
GC pause (G1 Humongous Allocation) (young) (initial-mark)
触发时机，分配巨大对象之前，会检测老年代使用占比是否超过 initiating heap occupancy percent（45%），超过会触发并发收集，往往伴随ygc,共用扫描root
{Heap before GC invocations=1581 (full 3):
garbage-first heap total 6291456K, used 6022213K [0x0000000640000000, 0x0000000640206000, 0x00000007c0000000)
region size 2048K, 523 young (1071104K), 0 survivors (0K)
Metaspace used 79338K, capacity 82531K, committed 83328K, reserved 1122304K
class space used 8648K, capacity 9406K, committed 9600K, reserved 1048576K
2023-05-07T13:37:28.970+0800: 152847.138: [GC pause (G1 Humongous Allocation) (young) (initial-mark) --初始标记,标记了从GC Root开始直接可达的对象
Desired survivor size 268435456 bytes, new threshold 15 (max 15)
2023-05-07T13:37:28.985+0800: 152847.152: [SoftReference, 0 refs, 0.0000469 secs]
2023-05-07T13:37:28.985+0800: 152847.152: [WeakReference, 0 refs, 0.0000085 secs]
2023-05-07T13:37:28.985+0800: 152847.152: [FinalReference, 2 refs,0.0000111 secs]
2023-05-07T13:37:28.985+0800: 152847.152: [PhantomReference, 0 refs, 1 refs, 0.0000081 secs]
2023-05-07T13:37:28.985+0800: 152847.152: [JNI Weak Reference, 0.0000225 secs], 0.0162966 secs]
[Parallel Time: 12.2 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 152847139.9, Avg: 152847140.0, Max: 152847140.0, Diff: 0.2]
[Ext Root Scanning (ms): Min: 2.8, Avg: 4.0, Max: 6.4, Diff: 3.5, Sum: 31.7]
[Update RS (ms): Min: 3.8, Avg: 6.6, Max: 8.3, Diff: 4.5, Sum: 52.5]
[Processed Buffers: Min: 10, Avg: 48.8, Max: 114, Diff: 104, Sum: 390]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 0.1, Avg: 0.6, Max: 1.0, Diff: 0.9, Sum: 5.1]
[Termination (ms): Min: 0.0, Avg: 0.4, Max: 0.5, Diff: 0.5, Sum: 2.9]
[Termination Attempts: Min: 1, Avg: 2.5, Max: 5, Diff: 4, Sum: 20]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 11.6, Avg: 11.7, Max: 11.8, Diff: 0.2, Sum: 93.6]
[GC Worker End (ms): Min: 152847151.6, Avg: 152847151.7, Max: 152847151.7, Diff: 0.0]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.4 ms]
[Other: 3.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.5 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.1 ms]
[Free CSet: 0.6 ms]
[Eden: 1046.0M(4096.0M)->0.0B(4094.0M) Survivors: 0.0B->2048.0K Heap: 5882.2M(6144.0M)->4838.4M(6144.0M)]
Heap after GC invocations=1582 (full 3):
garbage-first heap total 6291456K, used 4954520K [0x0000000640000000, 0x0000000640206000, 0x00000007c0000000)
region size 2048K, 1 young (2048K), 1 survivors (2048K)
Metaspace used 79338K, capacity 82531K, committed 83328K, reserved 1122304K
class space used 8648K, capacity 9406K, committed 9600K, reserved 1048576K
}
[Times: user=0.07 sys=0.00, real=0.02 secs]
2023-05-07T13:37:28.987+0800: 152847.155: [GC concurrent-root-region-scan-start] --并发根扫描
2023-05-07T13:37:28.991+0800: 152847.158: [GC concurrent-root-region-scan-end, 0.0036607 secs]
2023-05-07T13:37:28.991+0800: 152847.158: [GC concurrent-mark-start] --并发标记,这个阶段从GC Root开始对heap中的对象标记，标记线程与应用程序线程并行执行，并且收集各个Region的存活对象信息
2023-05-07T13:37:29.856+0800: 152848.023: [GC concurrent-mark-end, 0.8649206 secs]
2023-05-07T13:37:29.859+0800: 152848.026: [GC remark --最终标记.标记那些在并发标记阶段发生变化的对象，将被回收
2023-05-07T13:37:29.859+0800: 152848.026: [Finalize Marking, 0.0010623 secs]
2023-05-07T13:37:29.860+0800: 152848.027: [GC ref-proc
2023-05-07T13:37:29.860+0800: 152848.027: [SoftReference, 415 refs, 0.0006441 secs]
2023-05-07T13:37:29.860+0800: 152848.028: [WeakReference, 436 refs, 0.0005829 secs]
2023-05-07T13:37:29.861+0800: 152848.029: [FinalReference, 154 refs, 0.0004853 secs]
2023-05-07T13:37:29.862+0800: 152848.029: [PhantomReference, 16 refs, 85 refs, 0.0003824 secs]
2023-05-07T13:37:29.862+0800: 152848.030: [JNI Weak Reference, 0.0003531 secs], 0.0025209 secs]
2023-05-07T13:37:29.862+0800: 152848.030: [Unloading, 0.0157916 secs], 0.0230336 secs]
[Times: user=0.12 sys=0.00, real=0.03 secs]
2023-05-07T13:37:29.885+0800: 152848.052: [GC cleanup 5110M->3000M(6144M), 0.0061570 secs] --清除垃圾,清除空Region（没有存活对象的），加入到free list
[Times: user=0.03 sys=0.00, real=0.00 secs]
2023-05-07T13:37:29.892+0800: 152848.060: [GC concurrent-cleanup-start]
2023-05-07T13:37:29.897+0800: 152848.065: [GC concurrent-cleanup-end, 0.0053536 secs]GC pause (G1 Evacuation Pause) (young) (initial-mark)
{Heap before GC invocations=1588 (full 3):
garbage-first heap total 6291456K, used 6269294K [0x0000000640000000, 0x0000000640206000, 0x00000007c0000000)
region size 2048K, 10 young (20480K), 0 survivors (0K)
Metaspace used 79356K, capacity 82595K, committed 83328K, reserved 1122304K
class space used 8648K, capacity 9406K, committed 9600K, reserved 1048576K
2023-05-07T13:41:32.603+0800: 153090.770: [GC pause (G1 Evacuation Pause) (young) (initial-mark)
Desired survivor size 268435456 bytes, new threshold 15 (max 15)
2023-05-07T13:41:32.611+0800: 153090.779: [SoftReference, 0 refs, 0.0000595 secs]
2023-05-07T13:41:32.611+0800: 153090.779: [WeakReference, 0 refs, 0.0000081 secs]
2023-05-07T13:41:32.611+0800: 153090.779: [FinalReference, 0 refs,0.0000069 secs]
2023-05-07T13:41:32.611+0800: 153090.779: [PhantomReference, 0 refs, 0 refs, 0.0000071 secs]
2023-05-07T13:41:32.611+0800: 153090.779: [JNI Weak Reference, 0.0000217 secs] (to-space exhausted), 0.0133664 secs]
[Parallel Time: 6.7 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 153090771.7, Avg: 153090772.0, Max: 153090772.5, Diff: 0.8]
[Ext Root Scanning (ms): Min: 2.0, Avg: 2.8, Max: 3.4, Diff: 1.4, Sum: 22.4]
[Update RS (ms): Min: 0.0, Avg: 1.3, Max: 1.9, Diff: 1.9, Sum: 10.7]
[Processed Buffers: Min: 0, Avg: 32.8, Max: 44, Diff: 44, Sum: 262]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 1.3, Avg: 1.9, Max: 3.2, Diff: 1.9, Sum: 14.9]
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 5.7, Avg: 6.1, Max: 6.4, Diff: 0.8, Sum: 49.2]
[GC Worker End (ms): Min: 153090778.1, Avg: 153090778.1, Max: 153090778.2, Diff: 0.0]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 6.2 ms]
[Evacuation Failure: 3.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.6 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.2 ms]
[Free CSet: 0.2 ms]
[Eden: 20.0M(4096.0M)->0.0B(4096.0M) Survivors: 0.0B->0.0B Heap: 6122.4M(6144.0M)->6121.3M(6144.0M)]
Heap after GC invocations=1589 (full 3):
garbage-first heap total 6291456K, used 6268193K [0x0000000640000000, 0x0000000640206000, 0x00000007c0000000)
region size 2048K, 0 young (0K), 0 survivors (0K)
Metaspace used 79356K, capacity 82595K, committed 83328K, reserved 1122304K
class space used 8648K, capacity 9406K, committed 9600K, reserved 1048576K
}
[Times: user=0.05 sys=0.00, real=0.01 secs]
2023-05-07T13:41:32.616+0800: 153090.784: [GC concurrent-root-region-scan-start]
2023-05-07T13:41:32.617+0800: 153090.784: [GC concurrent-root-region-scan-end, 0.0000993 secs]
2023-05-07T13:41:32.617+0800: 153090.784: [GC concurrent-mark-start]混合收集
GC pause (G1 Evacuation Pause) (mixed)
{Heap before GC invocations=1578 (full 3):
garbage-first heap total 6291456K, used 6254442K [0x0000000640000000, 0x0000000640206000, 0x00000007c0000000)
region size 2048K, 1458 young (2985984K), 0 survivors (0K)
Metaspace used 79338K, capacity 82531K, committed 83328K, reserved 1122304K
class space used 8648K, capacity 9406K, committed 9600K, reserved 1048576K
2023-05-07T13:35:13.451+0800: 152711.618: [GC pause (G1 Evacuation Pause) (mixed)
Desired survivor size 268435456 bytes, new threshold 15 (max 15)
2023-05-07T13:35:13.517+0800: 152711.685: [SoftReference, 0 refs, 0.0000441 secs]
2023-05-07T13:35:13.517+0800: 152711.685: [WeakReference, 0 refs, 0.0000083 secs]
2023-05-07T13:35:13.517+0800: 152711.685: [FinalReference, 0 refs,0.0000073 secs]
2023-05-07T13:35:13.517+0800: 152711.685: [PhantomReference, 0 refs, 0 refs, 0.0000075 secs]
2023-05-07T13:35:13.517+0800: 152711.685: [JNI Weak Reference, 0.0000364 secs] (to-space exhausted), 0.1982703 secs]
[Parallel Time: 64.8 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 152711619.5, Avg: 152711619.6, Max: 152711619.9, Diff: 0.5]
[Ext Root Scanning (ms): Min: 0.6, Avg: 1.5, Max: 2.1, Diff: 1.6, Sum: 12.0]
[Update RS (ms): Min: 16.6, Avg: 19.3, Max: 21.4, Diff: 4.8, Sum: 154.4]
[Processed Buffers: Min: 34, Avg: 101.5, Max: 170, Diff: 136, Sum: 812]
[Scan RS (ms): Min: 0.2, Avg: 0.8, Max: 1.2, Diff: 1.0, Sum: 6.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
[Object Copy (ms): Min: 40.9, Avg: 42.6, Max: 45.1, Diff: 4.2, Sum: 340.7]
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.2]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
[GC Worker Total (ms): Min: 64.1, Avg: 64.4, Max: 64.5, Diff: 0.5, Sum: 514.9]
[GC Worker End (ms): Min: 152711684.0, Avg: 152711684.0, Max: 152711684.0, Diff: 0.1]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.9 ms]
[Other: 132.5 ms]
[Evacuation Failure: 127.9 ms]
[Choose CSet: 0.3 ms]
[Ref Proc: 0.7 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.3 ms]
[Humongous Reclaim: 0.2 ms]
[Free CSet: 1.8 ms]
[Eden: 2916.0M(4096.0M)->0.0B(4096.0M) Survivors: 0.0B->0.0B Heap: 6107.9M(6144.0M)->3387.1M(6144.0M)]
Heap after GC invocations=1579 (full 3):
garbage-first heap total 6291456K, used 3468357K [0x0000000640000000, 0x0000000640206000, 0x00000007c0000000)
region size 2048K, 0 young (0K), 0 survivors (0K)
Metaspace used 79338K, capacity 82531K, committed 83328K, reserved 1122304K
class space used 8648K, capacity 9406K, committed 9600K, reserved 1048576K
}
[Times: user=1.14 sys=0.00, real=0.20 secs]Full GC
Full GC (Allocation Failure)
{Heap before GC invocations=1591 (full 3):
garbage-first heap total 6291456K, used 6270241K [0x0000000640000000, 0x0000000640206000, 0x00000007c0000000)
region size 2048K, 0 young (0K), 0 survivors (0K)
Metaspace used 79356K, capacity 82595K, committed 83328K, reserved 1122304K
class space used 8648K, capacity 9406K, committed 9600K, reserved 1048576K
2023-05-07T13:41:32.777+0800: 153090.945: [Full GC (Allocation Failure)
2023-05-07T13:41:33.325+0800: 153091.492: [SoftReference, 959 refs, 0.0002545 secs]
2023-05-07T13:41:33.325+0800: 153091.493: [WeakReference, 5981 refs, 0.0007317 secs]
2023-05-07T13:41:33.326+0800: 153091.493: [FinalReference, 310 refs, 0.0001153 secs]
2023-05-07T13:41:33.326+0800: 153091.494: [PhantomReference, 0 refs, 116 refs, 0.0000244 secs]
2023-05-07T13:41:33.326+0800: 153091.494: [JNI Weak Reference, 0.0000494 secs] 6123M->626M(6144M), 1.7569551 secs]
[Eden: 0.0B(4096.0M)->0.0B(4096.0M) Survivors: 0.0B->0.0B Heap: 6123.3M(6144.0M)->626.6M(6144.0M)], [Metaspace: 79356K->79216K(1122304K)]
Heap after GC invocations=1592 (full 4):
garbage-first heap total 6291456K, used 641589K [0x0000000640000000, 0x0000000640206000, 0x00000007c0000000)
region size 2048K, 0 young (0K), 0 survivors (0K)
Metaspace used 79216K, capacity 82361K, committed 83328K, reserved 1122304K
class space used 8627K, capacity 9367K, committed 9600K, reserved 1048576K
}
[Times: user=2.57 sys=0.00, real=1.76 secs]
2023-05-07T13:41:34.534+0800: 153092.702: [GC concurrent-mark-abort]深入理解G1 https://juejin.cn/post/6844903893906751501
原文地址：https://blog.csdn.net/qq_28919337/article/details/143486243
免责声明：本站文章内容转载自网络资源，如本站内容侵犯了原著者的合法权益，可联系本站删除。更多内容请关注自学内容网（zxcms.com）！