第五行是老年代Old区的GC，首先是GC发生的时间。然后是GC发生的原因System.gc()，由于代码调用。[CMS: 846K->1930K(14336K), 0.0103698 secs]表示回收前老年代是846K，回收后1930K，老年代总大小14336K，回收耗时0.0103698 secs。7165K->1930K(27264K)表示回收前堆大小7165K，回收后堆大小1930K，堆的总大小27264K。
后面有一次并发标记周期，设置参数-XX:InitiatingHeapOccupancyPercent的值，可以指定堆占有率达到百分之多少时，触发并发标记，默认值是45%。
最后打印出了堆的整体使用情况，分为新生代、老年代、元空间。
-XX:+UseG1GC日志解析G1是JDK1.9中的默认收集器，指定G1收集器并发、并行执行内存回收（-XX:+UseG1GC），它的格式差异较大，日志如下：
Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for windows-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:23:53 by "java_re" with MS VC++ 10.0 (VS2010) Memory: 4k page, physical 8303556k(2436164k free), swap 16215992k(7422076k free) CommandLine flags: -XX:InitialHeapSize=29360128 -XX:MaxHeapSize=29360128 -XX:MaxNewSize=14680064 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation # 新生代GC，young区，暂停0.0022375秒 2018-05-09T20:59:47.639+0800: 0.484: [GC pause (G1 Evacuation Pause) (young), 0.0022375 secs] # 并行时间1.7ms，4个GC线程 [Parallel Time: 1.7 ms, GC Workers: 4] # 开始时刻，相对开始时间点，4个线程的最小值、平均值、最大值 [GC Worker Start (ms): Min: 484.4, Avg: 484.4, Max: 484.5, Diff: 0.0] # 根节点扫描耗时 [Ext Root Scanning (ms): Min: 0.4, Avg: 0.7, Max: 1.6, Diff: 1.2, Sum: 2.7] # 更新记忆集（RS, Remembered Set）耗时G1中每块区域都有一个RS与之对应，RS记录了该区域被其他区域引用的对象。回收时，就把RS作为根集的一部分，从而加快回收。 [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] # Processed Buffers就是记录引用变化的缓存空间 [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] # 扫描RS耗时 [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.1, Diff: 0.1, Sum: 0.1] # 对象拷贝（疏散回收的区域） [Object Copy (ms): Min: 0.0, Avg: 0.8, Max: 1.1, Diff: 1.1, Sum: 3.3] # 线程在终止阶段的耗时，线程在终止前，会检查其他线程的队列，看是否有未清理完的Reference。如有则帮助其他线程清理，之后再尝试终止 [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3] # 尝试终止次数 [Termination Attempts: Min: 1, Avg: 1.8, Max: 2, Diff: 1, Sum: 7] # GC线程花在其他任务中的耗时 [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] # GC线程耗时 [GC Worker Total (ms): Min: 1.6, Avg: 1.6, Max: 1.6, Diff: 0.0, Sum: 6.5] # 完成时刻 [GC Worker End (ms): Min: 486.1, Avg: 486.1, Max: 486.1, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] # 清空CardTable耗时，RS是依赖CardTable记录区域存活对象的 [Clear CT: 0.0 ms] # 其他任务耗时 [Other: 0.5 ms] # 选取将要被回收的区域的集合耗时 [Choose CSet: 0.0 ms] # 弱引用、软引用的处理耗时 [Ref Proc: 0.4 ms] # 弱引用、软引用的入队耗时 [Ref Enq: 0.0 ms] [Redirty Cards: 0.0 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] # 释放被回收区域的耗时（包含他们的RS） [Free CSet: 0.0 ms] # Eden区、Survivor区、堆的回收前大小、回收后大小、以及总大小 [Eden: 5120.0K(5120.0K)->0.0B(11.0M) Survivors: 0.0B->1024.0K Heap: 5120.0K(28.0M)->1631.5K(28.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] # 并发标记周期开始，根区域扫描 2018-05-09T20:59:47.982+0800: 9.634: [GC concurrent-root-region-scan-start] 2018-05-09T20:59:47.982+0800: 9.652: [GC concurrent-root-region-scan-end, 0.0184308 secs] # 并发标记 2018-05-09T20:59:47.982+0800: 9.652: [GC concurrent-mark-start] 2018-05-09T20:59:47.982+0800: 9.693: [GC concurrent-mark-end, 0.0406187 secs] # 重新标记 2018-05-09T20:59:47.982+0800: 9.695: [GC remark 9.695: [Finalize Marking, 0.0005100 secs] 9.695: [GC ref-proc, 0.0003461 secs] 9.696: [Unloading, 0.0069466 secs], 0.0082011 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] # 独占清理 2018-05-09T20:59:47.982+0800: 9.703: [GC cleanup 25M->21M(1024M), 0.0027119 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] # 并发清理 2018-05-09T20:59:47.982+0800: 9.706: [GC concurrent-cleanup-start] 2018-05-09T20:59:47.982+0800: 9.706: [GC concurrent-cleanup-end, 0.0000167 secs] # 下一轮回收，FullGC，堆的回收前、回收后、以及总大小。Eden、Survivor、元空间的大小。 2018-05-09T20:59:47.982+0800: 0.828: [Full GC (System.gc()) 12M->2223K(28M), 0.0128065 secs] [Eden: 11.0M(11.0M)->0.0B(12.0M) Survivors: 1024.0K->0.0B Heap: 12.2M(28.0M)->2223.0K(28.0M)], [Metaspace: 5951K->5951K(1056768K)] [Times: user=0.02 sys=0.00, real=0.01 secs] # 新生代GC 2018-05-09T20:59:48.040+0800: 0.886: [GC pause (G1 Evacuation Pause) (young), 0.0005693 secs] [Parallel Time: 0.4 ms, GC Workers: 4] [GC Worker Start (ms): Min: 886.1, Avg: 886.1, Max: 886.1, Diff: 0.0] [Ext Root Scanning (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.8] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2] [Processed Buffers: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [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.1] [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 0.3, Avg: 0.3, Max: 0.4, Diff: 0.0, Sum: 1.4] [GC Worker End (ms): Min: 886.5, Avg: 886.5, Max: 886.5, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.0 ms] [Other: 0.1 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.0 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.0 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 12.0M(12.0M)->0.0B(12.0M) Survivors: 0.0B->2048.0K Heap: 14.2M(28.0M)->3460.3K(28.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] 2018-05-09T20:59:48.103+0800: 0.949: [GC pause (G1 Evacuation Pause) (young), 0.0004664 secs] [Parallel Time: 0.3 ms, GC Workers: 4] [GC Worker Start (ms): Min: 949.2, Avg: 949.3, Max: 949.5, Diff: 0.3] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 0.6] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 0, Avg: 1.0, Max: 2, Diff: 2, Sum: 4] [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.0, Max: 0.0, Diff: 0.0, Sum: 0.1] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.8] [GC Worker End (ms): Min: 949.5, Avg: 949.5, Max: 949.5, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.0 ms] [Other: 0.1 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.1 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.0 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 12.0M(12.0M)->0.0B(13.0M) Survivors: 2048.0K->1024.0K Heap: 15.4M(28.0M)->2383.6K(28.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] 2018-05-09T20:59:48.146+0800: 0.992: [GC pause (G1 Evacuation Pause) (young), 0.0004067 secs] [Parallel Time: 0.3 ms, GC Workers: 4] [GC Worker Start (ms): Min: 991.9, Avg: 991.9, Max: 991.9, Diff: 0.0] [Ext Root Scanning (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.8] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 1, Avg: 1.3, Max: 2, Diff: 1, Sum: 5] [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.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.9] [GC Worker End (ms): Min: 992.2, Avg: 992.2, Max: 992.2, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.0 ms] [Other: 0.1 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.0 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.0 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 13.0M(13.0M)->0.0B(13.0M) Survivors: 1024.0K->1024.0K Heap: 15.3M(28.0M)->2277.1K(28.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] 2018-05-09T21:01:18.300+0800: 91.146: [Full GC (System.gc()) 9971K->1815K(28M), 0.0099218 secs] [Eden: 8192.0K(13.0M)->0.0B(14.0M) Survivors: 1024.0K->0.0B Heap: 9971.7K(28.0M)->1815.8K(28.0M)], [Metaspace: 6026K->6026K(1056768K)] [Times: user=0.00 sys=0.00, real=0.01 secs] Heap garbage-first heap total 28672K, used 1815K [0x00000000fe400000, 0x00000000fe5000e0, 0x0000000100000000) region size 1024K, 1 young (1024K), 0 survivors (0K) Metaspace used 6038K, capacity 6252K, committed 6400K, reserved 1056768K class space used 691K, capacity 761K, committed 768K, reserved 1048576KG1日志分析详见上面代码中的注释，G1的垃圾收集比之前的收集器稍微复杂一些。