8. G1垃圾收集日志

1 G1 垃圾收集日志

1.1 垃圾收集器设置

设置 JVM 启动参数-XX:+UseG1GC，将当前 JVM 增加回收器设置为 G1 垃圾收集器，启动参数可参考使用-Xms20m -Xmx20m -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:D://logs/gc.log -XX:+UseG1GC表示使用 G1 作为垃圾收集器将将垃圾收集日志文件打印下载到 D 盘 logs 文件夹下。

1.2 GC 日志内容

Java HotSpot(TM) 64-Bit Server VM (25.91-b15) for windows-amd64 JRE (1.8.0_91-b15), built on May 20 2016 17:43:15 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16629580k(9525864k free), swap 19119948k(8012276k free)
CommandLine flags: -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation
2020-03-19T21:27:52.811+0800: 0.112: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0939705 secs][Parallel Time: 87.9 ms, GC Workers: 10][GC Worker Start (ms): Min: 112.4, Avg: 112.5, Max: 112.6, Diff: 0.1][Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.5][Update RS (ms): Min: 3.5, Avg: 4.3, Max: 4.9, Diff: 1.3, Sum: 42.9][Processed Buffers: Min: 3, Avg: 3.5, Max: 4, Diff: 1, Sum: 35][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: 80.5, Avg: 82.6, Max: 83.5, Diff: 3.0, Sum: 825.7][Termination (ms): Min: 0.0, Avg: 0.3, Max: 1.8, Diff: 1.8, Sum: 2.8][Termination Attempts: Min: 1, Avg: 314.9, Max: 414, Diff: 413, Sum: 3149][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.4][GC Worker Total (ms): Min: 87.3, Avg: 87.3, Max: 87.4, Diff: 0.1, Sum: 873.3][GC Worker End (ms): Min: 199.8, Avg: 199.8, Max: 199.9, Diff: 0.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.4 ms][Other: 5.7 ms][Evacuation Failure: 5.0 ms][Choose CSet: 0.0 ms][Ref Proc: 0.2 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.4 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 9216.0K(9216.0K)->0.0B(1024.0K) Survivors: 0.0B->2048.0K Heap: 14.0M(20.0M)->18.0M(20.0M)][Times: user=0.28 sys=0.03, real=0.09 secs]
2020-03-19T21:27:52.906+0800: 0.207: [GC pause (G1 Evacuation Pause) (young) (initial-mark) (to-space exhausted), 0.0683399 secs][Parallel Time: 64.2 ms, GC Workers: 10][GC Worker Start (ms): Min: 206.7, Avg: 206.8, Max: 206.9, Diff: 0.2][Ext Root Scanning (ms): Min: 0.7, Avg: 0.8, Max: 1.0, Diff: 0.3, Sum: 8.4][Update RS (ms): Min: 3.4, Avg: 3.5, Max: 3.6, Diff: 0.2, Sum: 35.0][Processed Buffers: Min: 4, Avg: 7.8, Max: 19, Diff: 15, Sum: 78][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: 59.5, Avg: 59.6, Max: 59.7, Diff: 0.2, Sum: 596.4][Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3][Termination Attempts: Min: 1, Avg: 112.2, Max: 157, Diff: 156, Sum: 1122][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1][GC Worker Total (ms): Min: 63.9, Avg: 64.0, Max: 64.1, Diff: 0.3, Sum: 640.3][GC Worker End (ms): Min: 270.8, Avg: 270.8, Max: 270.8, Diff: 0.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.1 ms][Other: 4.0 ms][Evacuation Failure: 3.5 ms][Choose CSet: 0.0 ms][Ref Proc: 0.2 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.3 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 2048.0K->0.0B Heap: 18.0M(20.0M)->18.0M(20.0M)][Times: user=0.11 sys=0.01, real=0.07 secs]
2020-03-19T21:27:52.974+0800: 0.275: [GC concurrent-root-region-scan-start]
2020-03-19T21:27:52.974+0800: 0.275: [GC concurrent-root-region-scan-end, 0.0000166 secs]
2020-03-19T21:27:52.974+0800: 0.275: [GC concurrent-mark-start]
2020-03-19T21:27:52.974+0800: 0.275: [Full GC (Allocation Failure)  17M->8621K(20M), 0.0263017 secs][Eden: 0.0B(1024.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 18.0M(20.0M)->8621.6K(20.0M)], [Metaspace: 3280K->3280K(1056768K)][Times: user=0.03 sys=0.00, real=0.03 secs]
2020-03-19T21:27:53.001+0800: 0.302: [GC concurrent-mark-abort]
2020-03-19T21:27:53.003+0800: 0.304: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0092809 secs][Parallel Time: 8.5 ms, GC Workers: 10][GC Worker Start (ms): Min: 304.3, Avg: 304.3, Max: 304.5, Diff: 0.2][Ext Root Scanning (ms): Min: 0.0, Avg: 0.6, Max: 3.8, Diff: 3.8, Sum: 5.6][Update RS (ms): Min: 0.0, Avg: 1.2, Max: 5.8, Diff: 5.8, Sum: 11.8][Processed Buffers: Min: 0, Avg: 0.8, Max: 2, Diff: 2, Sum: 8][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: 2.4, Avg: 6.5, Max: 8.0, Diff: 5.6, Sum: 64.6][Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.0][Termination Attempts: Min: 1, Avg: 326.0, Max: 479, Diff: 478, Sum: 3260][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1][GC Worker Total (ms): Min: 8.2, Avg: 8.3, Max: 8.4, Diff: 0.2, Sum: 83.2][GC Worker End (ms): Min: 312.7, Avg: 312.7, Max: 312.7, Diff: 0.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.3 ms][Other: 0.4 ms][Choose CSet: 0.0 ms][Ref Proc: 0.1 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.2 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 3072.0K(4096.0K)->0.0B(2048.0K) Survivors: 0.0B->1024.0K Heap: 11.0M(20.0M)->11.3M(20.0M)][Times: user=0.14 sys=0.00, real=0.01 secs]
2020-03-19T21:27:53.013+0800: 0.314: [GC concurrent-root-region-scan-start]
2020-03-19T21:27:53.014+0800: 0.314: [GC concurrent-root-region-scan-end, 0.0007523 secs]
2020-03-19T21:27:53.014+0800: 0.314: [GC concurrent-mark-start]
2020-03-19T21:27:53.040+0800: 0.340: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0889972 secs][Parallel Time: 85.5 ms, GC Workers: 10][GC Worker Start (ms): Min: 340.4, Avg: 340.4, Max: 340.4, Diff: 0.1][Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.3][Update RS (ms): Min: 1.0, Avg: 1.5, Max: 2.0, Diff: 1.0, Sum: 15.4][Processed Buffers: Min: 1, Avg: 1.7, Max: 2, Diff: 1, Sum: 17][Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.1][Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Object Copy (ms): Min: 83.2, Avg: 83.6, Max: 83.9, Diff: 0.7, Sum: 835.9][Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4][Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 10][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1][GC Worker Total (ms): Min: 85.4, Avg: 85.4, Max: 85.5, Diff: 0.1, Sum: 854.1][GC Worker End (ms): Min: 425.8, Avg: 425.8, Max: 425.8, Diff: 0.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.1 ms][Other: 3.3 ms][Evacuation Failure: 2.7 ms][Choose CSet: 0.0 ms][Ref Proc: 0.2 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.4 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 2048.0K(2048.0K)->0.0B(1024.0K) Survivors: 1024.0K->0.0B Heap: 16.4M(20.0M)->17.5M(20.0M)][Times: user=0.14 sys=0.02, real=0.09 secs]
2020-03-19T21:27:53.129+0800: 0.430: [GC pause (G1 Evacuation Pause) (young), 0.0022483 secs][Parallel Time: 1.1 ms, GC Workers: 10][GC Worker Start (ms): Min: 429.6, Avg: 429.6, Max: 429.7, Diff: 0.1][Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.2][Update RS (ms): Min: 0.7, Avg: 0.8, Max: 0.9, Diff: 0.2, Sum: 7.9][Processed Buffers: Min: 1, Avg: 2.3, Max: 6, Diff: 5, Sum: 23][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: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][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: 10][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1][GC Worker Total (ms): Min: 1.0, Avg: 1.0, Max: 1.1, Diff: 0.1, Sum: 10.3][GC Worker End (ms): Min: 430.6, Avg: 430.6, Max: 430.7, Diff: 0.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.4 ms][Other: 0.7 ms][Choose CSet: 0.0 ms][Ref Proc: 0.3 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.3 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->0.0B Heap: 17.5M(20.0M)->17.5M(20.0M)][Times: user=0.00 sys=0.00, real=0.00 secs]
2020-03-19T21:27:53.131+0800: 0.432: [Full GC (Allocation Failure)  17M->13M(20M), 0.0346185 secs][Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->0.0B Heap: 17.5M(20.0M)->14.0M(20.0M)], [Metaspace: 3280K->3280K(1056768K)][Times: user=0.05 sys=0.00, real=0.03 secs]
2020-03-19T21:27:53.166+0800: 0.467: [GC concurrent-mark-abort]
2020-03-19T21:27:53.167+0800: 0.467: [GC pause (G1 Evacuation Pause) (young), 0.0125616 secs][Parallel Time: 6.9 ms, GC Workers: 10][GC Worker Start (ms): Min: 467.5, Avg: 467.6, Max: 467.7, Diff: 0.2][Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6][Update RS (ms): Min: 0.0, Avg: 0.5, Max: 3.0, Diff: 3.0, Sum: 4.9][Processed Buffers: Min: 0, Avg: 0.3, Max: 1, Diff: 1, Sum: 3][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: 2.6, Avg: 5.1, Max: 6.4, Diff: 3.8, Sum: 51.1][Termination (ms): Min: 0.0, Avg: 0.8, Max: 0.9, Diff: 0.9, Sum: 8.1][Termination Attempts: Min: 1, Avg: 140.5, Max: 190, Diff: 189, Sum: 1405][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1][GC Worker Total (ms): Min: 6.4, Avg: 6.5, Max: 6.6, Diff: 0.2, Sum: 64.8][GC Worker End (ms): Min: 474.1, Avg: 474.1, Max: 474.1, Diff: 0.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 2.5 ms][Other: 3.2 ms][Choose CSet: 0.0 ms][Ref Proc: 1.6 ms][Ref Enq: 0.0 ms][Redirty Cards: 1.5 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 1024.0K(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->1024.0K Heap: 15.0M(20.0M)->15.0M(20.0M)][Times: user=0.00 sys=0.01, real=0.01 secs]
2020-03-19T21:27:53.181+0800: 0.483: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0085896 secs][Parallel Time: 6.4 ms, GC Workers: 10][GC Worker Start (ms): Min: 482.9, Avg: 483.0, Max: 483.0, Diff: 0.2][Ext Root Scanning (ms): Min: 0.0, Avg: 0.4, Max: 3.5, Diff: 3.5, Sum: 4.3][Update RS (ms): Min: 0.0, Avg: 0.5, Max: 1.4, Diff: 1.4, Sum: 4.8][Processed Buffers: Min: 0, Avg: 1.3, Max: 3, Diff: 3, Sum: 13][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: 2.4, Avg: 5.0, Max: 5.6, Diff: 3.2, Sum: 49.6][Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.4][Termination Attempts: Min: 1, Avg: 31.6, Max: 53, Diff: 52, Sum: 316][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.8, Avg: 5.9, Max: 6.0, Diff: 0.2, Sum: 59.1][GC Worker End (ms): Min: 488.9, Avg: 488.9, Max: 488.9, Diff: 0.0][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.5 ms][Other: 1.7 ms][Choose CSet: 0.0 ms][Ref Proc: 0.9 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.7 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 1024.0K(1024.0K)->0.0B(1024.0K) Survivors: 1024.0K->1024.0K Heap: 16.0M(20.0M)->16.1M(20.0M)][Times: user=0.00 sys=0.00, real=0.01 secs]
2020-03-19T21:27:53.190+0800: 0.492: [GC concurrent-root-region-scan-start]
2020-03-19T21:27:53.190+0800: 0.492: [GC pause (G1 Humongous Allocation) (young)2020-03-19T21:27:53.191+0800: 0.492: [GC concurrent-root-region-scan-end, 0.0004869 secs]
2020-03-19T21:27:53.191+0800: 0.492: [GC concurrent-mark-start](to-space exhausted), 0.0162043 secs][Root Region Scan Waiting: 0.3 ms][Parallel Time: 6.7 ms, GC Workers: 10][GC Worker Start (ms): Min: 492.1, Avg: 492.1, Max: 492.1, Diff: 0.1][Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.2][Update RS (ms): Min: 0.2, Avg: 0.4, Max: 0.5, Diff: 0.3, Sum: 4.0][Processed Buffers: Min: 1, Avg: 1.2, Max: 2, Diff: 1, Sum: 12][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: 3.4, Avg: 3.7, Max: 3.9, Diff: 0.5, Sum: 36.6][Termination (ms): Min: 0.0, Avg: 0.3, Max: 2.4, Diff: 2.4, Sum: 3.1][Termination Attempts: Min: 1, Avg: 4.3, Max: 16, Diff: 15, Sum: 43][GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1][GC Worker Total (ms): Min: 4.2, Avg: 4.5, Max: 6.5, Diff: 2.3, Sum: 44.9][GC Worker End (ms): Min: 496.3, Avg: 496.6, Max: 498.7, Diff: 2.3][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.8 ms][Other: 8.4 ms][Evacuation Failure: 7.9 ms][Choose CSet: 0.0 ms][Ref Proc: 0.1 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.3 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms][Eden: 1024.0K(1024.0K)->0.0B(1024.0K) Survivors: 1024.0K->1024.0K Heap: 16.3M(20.0M)->17.7M(20.0M)][Times: user=0.02 sys=0.00, real=0.02 secs]
2020-03-19T21:27:53.207+0800: 0.508: [Full GC (Allocation Failure)  17M->16M(20M), 0.0391069 secs][Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 1024.0K->0.0B Heap: 17.7M(20.0M)->16.1M(20.0M)], [Metaspace: 3280K->3280K(1056768K)][Times: user=0.05 sys=0.00, real=0.04 secs]
2020-03-19T21:27:53.246+0800: 0.547: [Full GC (Allocation Failure)  16M->16M(20M), 0.0404771 secs][Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->0.0B Heap: 16.1M(20.0M)->16.1M(20.0M)], [Metaspace: 3280K->3280K(1056768K)][Times: user=0.03 sys=0.00, real=0.04 secs]
2020-03-19T21:27:53.287+0800: 0.588: [GC concurrent-mark-abort]
Heapgarbage-first heap   total 20480K, used 16441K [0x00000000fec00000, 0x00000000fed000a0, 0x0000000100000000)region size 1024K, 1 young (1024K), 0 survivors (0K)Metaspace       used 3312K, capacity 4500K, committed 4864K, reserved 1056768Kclass space    used 363K, capacity 388K, committed 512K, reserved 1048576K

1.3 G1 垃圾收集器运行示意图

由于 G1 垃圾收集器执行过程分了多个阶段，所以这里配合垃圾收集器的运行示意图进行垃圾收集日志的理解。G1 运行示意图如下：

1.4 GC 日志分析

第1行显示当前运行环境基本信息。
第2行显示当前运行环境内存信息。
第3行中显示当前运行 JVM 使用的参数。

-XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520表示启动堆内存与最大堆内存都是20M，与配置参数一致。

第4-248行显示执行 GC 的具体情况。

由于 G1 垃圾收集器的算法中将 Java 堆分成多个 Region 区域，垃圾收集日志又代表着垃圾收集器的执行过程，所以会发现 G1 的垃圾收集日志会比其它收集器的日志内容要多非常多。

2020-03-19T21:27:52.811+0800: 0.112:表示在指定的时间（2020-03-19T21:27:52.811+0800）触发了垃圾回收器中的某个动作，这个时间点发生在从启动 JVM 开始算起的第(0.112)秒中。从整个垃圾回收日志找规律，得出以这个格式开头的都是单独的一个垃圾回收的动作。

[GC pause表示在新生代中发生了 GC 事件。

(G1 Evacuation Pause)表示疏散停顿（Evacuation Pause），是将活着的对象从一个区域（young or young + old）拷贝到另一个区域的阶段。

[Parallel Time表示并行阶段的耗时。

GC Workers: 10表示10个 GC 线程运行。

[GC Worker Start (ms): Min: 112.4, Avg: 112.5, Max: 112.6, Diff: 0.1]表示所有工作线程的平均、最小、最大和差异时间。

[Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.5]表示每一个扫描根(全局、寄存器、线程栈、虚拟机数据结构)的工作线程花费的平均、最小、最大、差异和总时间。

[Update RS (ms): Min: 3.5, Avg: 4.3, Max: 4.9, Diff: 1.3, Sum: 42.9]表每一个线程更新Remembered Sets花费的平均、最小、最大、差异和总时间。Remembered Sets是保存到堆中的区域的跟踪引用。
设值方法线程持续改变对象图，自此引指向一个特定的区域。我们保存这些改变的跟踪信息到叫作Update Buffers的更新缓存中。Update RS 子任务不能并发的处理更新缓存，更新一致所有区域的Remembered Sets。

[Processed Buffers:表示每一个线程处理的Update Buffers(上面提到的)的数量。

[Scan RS (ms):表示每一个工作线程扫描Remembered Sets花费的时间。一个区域的Remembered Sets包含指向这个区域的引用的相符合的卡片。这个阶段扫描这些卡片寻找指向所有这些区域的Collection Set的引用。

[Code Root Scanning (ms):表示扫描code root耗时。Code Root是JIT编译后的代码里引用了heap中的对象。

[Object Copy (ms):表示每一个工作线程把Collection Sets的区域里的活跃对象复制到另一个区域里花费时间。

[Termination (ms):表示每一个工作线程提供中断花费的时间。但是在中断之前，它检查其它线程的工作队列，如果在其它工作队列中仍然有引用，它会尝试固定对象引用，如果它成功的固定了一个引用，它会处理并再次提供中断。

[Termination Attempts:表示每一个线程提供中断的次数。

[GC Worker Other (ms):表示每一个工作线程执行其它上面我们没有在总并行时间里统计的任务花费的时间。

[GC Worker Total (ms):表示每一个工作线程的总生存时间。

[GC Worker End (ms):表示每一个工作线程的以毫秒为单位的停止时间。

[Code Root Fixup: 0.0 ms]表示修复GC期间code root指针改变的耗时。

[Code Root Purge: 0.0 ms]表示清除code root耗时。

[Clear CT: 0.4 ms]表示清除card tables 中的dirty card的耗时。

[Other: 5.7 ms]表示其它时间。

[Eden: 9216.0K(9216.0K)->0.0B(1024.0K) Survivors: 0.0B->2048.0K Heap: 14.0M(20.0M)->18.0M(20.0M)]表示 Eden 区、Survivors 区、Heap 区对应的内存变化。

[Times: user=0.28 sys=0.03, real=0.09 secs]表示三个执行时长，单位是秒。user/sys/real 分别表示用户态消耗的CPU时间、内核态消耗的CPU时间、操作从开始到结束所经过的墙钟时间。

上面内容表示一次 GC 活动事件，第4行中的耗时为第5/18/19/20/21行执行时间的总合，即该段日志的规则为总-分结构。

(initial-mark)表示在初始标记阶段。

[GC concurrent-root-region-scan-start]表示 region 区域扫描开始。

[GC concurrent-root-region-scan-end, 0.0000166 secs]表示 region 区域扫描结束。

[GC concurrent-mark-start]表示并发标记开始。

[GC concurrent-mark-abort]表示并发标记终止。

2 GC 日志分析工具

虽说 GC 日志本身没有太多的技术含量，但对于 G1 的垃圾收集日志，人眼去看内容太多还是挺耗眼的，所以对于一些复杂的 GC 日志可以通过一些工具进行查看以减少人力。目前有两款工具可以进行 GC 文件的分析，一个是GCViewer（本地分析），一个是GCeasy（在线分析）。

这里不做过多的工具的使用方法，别人已经有相关的博客进行描述。

GCViewer可参考 https://blog.csdn.net/cpzhong/article/details/6831751 进行学习查看。
GCeasy 可参考 https://blog.csdn.net/CoderBruis/article/details/101234738 进行学习查看。

3 引用

《深入理解Java虚拟机 JVM高级特性与最佳实践》-周志明著
https://blogs.oracle.com/poonam/understanding-g1-gc-logs
https://www.cnblogs.com/rainwang/p/7213918.html

8. G1垃圾收集日志相关推荐

浅谈 G1 GC 日志格式
在 Java9 中,G1 GC 将成为默认的垃圾收集器,G1 垃圾收集器的关键特性之一是能够在不牺牲吞吐量的同时,限制 GC 暂停时间(即可以设置所需的最大停顿时间). 由于 G1 GC 正在逐渐成为 ...
G1 GC 日志格式
在 Java9 中,G1 GC 将成为默认的垃圾收集器,G1 垃圾收集器的关键特性之一是能够在不牺牲吞吐量的同时,限制 GC 暂停时间(即可以设置所需的最大停顿时间). 由于 G1 GC 正在逐渐成为 ...
java g1 gc ref proc_深入理解垃圾收集器的G1及日志分析
尽管Hotspot 最新的垃圾回收器G1是在2006年推出的.但是G1从推行至今的市场反响来看,但现在足以证明这款垃圾收集器是经得起考验的,从java9开始,就默认为G1垃圾收集器.G1是一款面向服务 ...
转：深入理解Java G1垃圾收集器
本文首先简单介绍了垃圾收集的常见方式,然后再分析了G1收集器的收集原理,相比其他垃圾收集器的优势,最后给出了一些调优实践. 一,什么是垃圾回收首先,在了解G1之前,我们需要清楚的知道,垃圾回收是什么 ...
深入理解 Java G1 垃圾收集器--转
原文地址:http://blog.jobbole.com/109170/?utm_source=hao.jobbole.com&utm_medium=relatedArticle 本文首先简单 ...
深入理解 Java G1 垃圾收集器
本文首先简单介绍了垃圾收集的常见方式,然后再分析了G1收集器的收集原理,相比其他垃圾收集器的优势,最后给出了一些调优实践. 一,什么是垃圾回收首先,在了解G1之前,我们需要清楚的知道,垃圾回收是什么 ...
G1 垃圾收集器原理详解
一.G1 垃圾收集器的开发背景: 1.CMS 垃圾收集器的缺陷: JVM 团队设计出 G1 收集器的目的就是取代 CMS 收集器,因为 CMS 收集器在很多场景下存在诸多问题,缺陷暴露无遗,具体如下: ...
深入理解 Java G1 垃圾收集器GC调优
本文首先简单介绍了垃圾收集的常见方式,然后再分析了G1收集器的收集原理,相比其他垃圾收集器的优势,最后给出了一些调优实践. 一,什么是垃圾回收首先,在了解G1之前,我们需要清楚的知道,垃圾回收是什么 ...
G1垃圾收集器深度剖析
G1垃圾收集器深度剖析一.G1垃圾收集器概述 1.1 思考开始学习前,抛出两个常见面试问题:1.G1的回收原理是什么?为什么G1比传统的GC回收性能好?2.为什么G1如此完美仍然会有ZGC?简单的 ...