JVM探秘：GC日志收集与分析

Posted 2021-04-17 Cellei

收集GC日志

不同的垃圾收集器，输出的日志格式各不相同，但也有一些相同的特征。熟悉各个常用垃圾收集器的GC日志，是进行JVM调优的必备一步。 
解析GC日志，首先需要收集日志，常用的有以下JVM参数用来打印输出日志信息：

参数	说明
-XX:+PrintGCDetails	打印GC详细信息
-XX:+PrintGCTimeStamps	输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps	输出GC的时间戳（以日期的形式）
-XX:+PrintHeapAtGC	在进行GC的前后打印出堆的信息
-XX:+PrintTenuringDistribution	在进行GC时打印survivor中的对象年龄分布信息
-Xloggc:$CATALINA_HOME/logs/gc.log	指定输出路径收集日志到日志文件

例如，我使用如下参数启动：

-Xms28m
-Xmx28m
-XX:PermSize=14M
-XX:MaxNewSize=14m
-XX:MaxPermSize=14m
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-Xloggc:E:/logs/gc.log

如果要指定垃圾收集器，还需要添加对应的JVM参数，例如-XX:+UseG1GC、-XX:+UseConcMarkSweepGC等

-XX:+UseParallelGC日志解析

JDK1.8的默认收集器为Parallel收集器+Serial Old收集器组合（-XX:+UseParallelGC），日志如下：

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(2789672k free), swap 16215992k(6967912k 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:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
2018-05-08T19:23:01.815+0800: 0.574: [GC (Allocation Failure) [PSYoungGen: 11264K->1531K(12800K)] 11264K->2283K(27136K), 0.0039021 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:23:01.906+0800: 0.664: [GC (System.gc()) [PSYoungGen: 6560K->1516K(12800K)] 7311K->2625K(27136K), 0.0030390 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:23:01.908+0800: 0.667: [Full GC (System.gc()) [PSYoungGen: 1516K->0K(12800K)] [ParOldGen: 1109K->2005K(14336K)] 2625K->2005K(27136K), [Metaspace: 5955K->5955K(1056768K)], 0.0102082 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2018-05-08T19:23:01.954+0800: 0.714: [GC (Allocation Failure) [PSYoungGen: 11263K->64K(12800K)] 13269K->2069K(27136K), 0.0005071 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:23:01.988+0800: 0.748: [GC (Allocation Failure) [PSYoungGen: 11327K->64K(12800K)] 13333K->2069K(27136K), 0.0003509 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:23:02.019+0800: 0.779: [GC (Allocation Failure) [PSYoungGen: 11328K->128K(12800K)] 13333K->2133K(27136K), 0.0003730 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:23:02.049+0800: 0.809: [GC (Allocation Failure) [PSYoungGen: 11391K->64K(9728K)] 13397K->2077K(24064K), 0.0003454 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:24:28.365+0800: 87.124: [GC (System.gc()) [PSYoungGen: 306K->32K(11264K)] 2320K->2045K(25600K), 0.0005228 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:24:28.365+0800: 87.124: [Full GC (System.gc()) [PSYoungGen: 32K->0K(11264K)] [ParOldGen: 2013K->1706K(14336K)] 2045K->1706K(25600K), [Metaspace: 6027K->6021K(1056768K)], 0.0135435 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
Heap
 PSYoungGen      total 11264K, used 324K [0x00000000ff200000, 0x0000000100000000, 0x0000000100000000)
  eden space 8192K, 3% used [0x00000000ff200000,0x00000000ff2513a0,0x00000000ffa00000)
  from space 3072K, 0% used [0x00000000ffa00000,0x00000000ffa00000,0x00000000ffd00000)
  to   space 3072K, 0% used [0x00000000ffd00000,0x00000000ffd00000,0x0000000100000000)
 ParOldGen       total 14336K, used 1706K [0x00000000fe400000, 0x00000000ff200000, 0x00000000ff200000)
  object space 14336K, 11% used [0x00000000fe400000,0x00000000fe5aa8f8,0x00000000ff200000)
 Metaspace       used 6032K, capacity 6242K, committed 6400K, reserved 1056768K
  class space    used 688K, capacity 756K, committed 768K, reserved 1048576K

第三行把当前使用的JVM参数打印了出来，初始化了堆大小，设置了最大堆，最后打印出来GC参数-XX:+UseParallelGC。

第四行开始是垃圾收集记录，首先是垃圾收集的时间。然后是发生GC的原因，GC (Allocation Failure)对象分配失败，GC表示新生代Young区的GC，Full GC则包含老年代。[PSYoungGen: 11264K->1531K(12800K)]表示Young区回收前大小是11264K，回收后是1531K，总大小是12800K。紧接着中括号外，11264K->2283K(27136K)表示回收前整个堆大小是11264K，回收后堆大小2283K，堆总大小27136K。0.0039021 secs是垃圾回收用的时间。可以看出，新生代由11M变为了约1.5M，而整个堆由11M变为了约2.2M，也就是这次GC后，老年代约为0.7M。

后面的格式都是类似的，再看第六行Full GC的日志。

第六行，首先也是GC发生的时间。然后是发生GC的原因，Full GC (System.gc())由于代码System.gc()发起了Full GC。[PSYoungGen: 1516K->0K(12800K)]表示回收前新生代是1516K，回收后0K，新生代总大小是12800K。[ParOldGen: 1109K->2005K(14336K)]表示回收前老年代是1109K，回收后2005K，老年代总大小14336K。紧接着中括号外，2625K->2005K(27136K)回收前堆大小2625K，回收后2005K，堆总大小27136K。[Metaspace: 5955K->5955K(1056768K)]回收前元空间大小5955K，回收后5955K，总大小1056768K。这次GC用时0.0102082 secs。

日志的最后打印出了堆的信息，新生代总大小11264K，已使用324K，新生代中的eden区大小8192K，已用3%，两个survivor区都是3072K。老年代总大小14336K，已使用1706K。元空间已使用6032K。

-XX:+UseSerialGC日志解析

Serial收集器+Serial Old收集器组合（-XX:+UseSerialGC）的日志如下：

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(2575660k free), swap 16215992k(7063788k 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:-UseLargePagesIndividualAllocation -XX:+UseSerialGC 
2018-05-08T19:31:03.644+0800: 0.676: [GC (Allocation Failure) 2018-08-08T19:31:03.644+0800: 0.676: [DefNew: 11520K->1408K(12928K), 0.0049897 secs] 11520K->2234K(27264K), 0.0051851 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:31:03.744+0800: 0.775: [Full GC (System.gc()) 2018-08-08T19:31:03.744+0800: 0.775: [Tenured: 826K->2569K(14336K), 0.0292213 secs] 7147K->2569K(27264K), [Metaspace: 5939K->5939K(1056768K)], 0.0292829 secs] [Times: user=0.02 sys=0.00, real=0.03 secs] 
2018-05-08T19:31:03.811+0800: 0.843: [GC (Allocation Failure) 2018-08-08T19:31:03.811+0800: 0.843: [DefNew: 11519K->4K(12928K), 0.0009580 secs] 14088K->2573K(27264K), 0.0010026 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:31:03.878+0800: 0.909: [GC (Allocation Failure) 2018-08-08T19:31:03.878+0800: 0.909: [DefNew: 11523K->3K(12928K), 0.0003602 secs] 14092K->2572K(27264K), 0.0004109 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-08T19:31:03.935+0800: 0.967: [GC (Allocation Failure) 2018-08-08T19:31:03.935+0800: 0.967: [DefNew: 11523K->3K(12928K), 0.0004648 secs] 14092K->2572K(27264K), 0.0005109 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2018-05-08T19:32:31.148+0800: 88.179: [Full GC (System.gc()) 2018-08-08T19:32:31.148+0800: 88.179: [Tenured: 2569K->2540K(14336K), 0.0078915 secs] 13176K->2540K(27264K), [Metaspace: 6017K->6017K(1056768K)], 0.0079582 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
Heap
 def new generation   total 12928K, used 458K [0x00000000fe400000, 0x00000000ff200000, 0x00000000ff200000)
  eden space 11520K,   3% used [0x00000000fe400000, 0x00000000fe472838, 0x00000000fef40000)
  from space 1408K,   0% used [0x00000000fef40000, 0x00000000fef40000, 0x00000000ff0a0000)
  to   space 1408K,   0% used [0x00000000ff0a0000, 0x00000000ff0a0000, 0x00000000ff200000)
 tenured generation   total 14336K, used 2540K [0x00000000ff200000, 0x0000000100000000, 0x0000000100000000)
   the space 14336K,  17% used [0x00000000ff200000, 0x00000000ff47b1e8, 0x00000000ff47b200, 0x0000000100000000)
 Metaspace       used 6029K, capacity 6252K, committed 6400K, reserved 1056768K
  class space    used 691K, capacity 761K, committed 768K, reserved 1048576K

Serial收集器已经很少使用，GC日志的格式也是大同小异，[GC开头的是新生代GC，DefNew表示新生代。会打印GC发生时间，GC原因，新生代回收前大小、回收后大小、以及新生代总大小。打印堆的回收前大小、回收后大小、及总大小，打印GC耗时。

[Full GC开头的是老年代GC，Tenured表示老年代。会打印GC发生时间，GC原因，老年代回收前大小、回收后大小、以及老年代总大小。打印堆的回收前大小、回收后大小、及堆的总大小。打印元空间的回收前、回收后、及总大小，打印GC耗时。

最后打印出整个堆的使用情况。

-XX:+UseParNewGC日志解析

ParNew收集器+Serilal Old组合（-XX:+UseParNewGC）的日志如下：

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(2874368k free), swap 16215992k(9448728k 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:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
2018-05-09T20:41:34.699+0800: 4.632: [GC (Allocation Failure) 2018-08-09T08:41:34.711+0800: 4.633: [ParNew: 11520K->1408K(12928K), 0.0149096 secs] 11520K->2265K(27264K), 0.0271137 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] 
2018-05-09T20:41:34.886+0800: 4.808: [Full GC (System.gc()) 2018-08-09T08:41:34.886+0800: 4.808: [Tenured: 857K->2567K(14336K), 0.0091055 secs] 6992K->2567K(27264K), [Metaspace: 5940K->5940K(1056768K)], 0.0091703 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2018-05-09T20:41:34.964+0800: 4.887: [GC (Allocation Failure) 2018-08-09T08:41:34.964+0800: 4.887: [ParNew: 11519K->1214K(12928K), 0.0132311 secs] 14086K->3781K(27264K), 0.0132796 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2018-05-09T20:41:35.024+0800: 4.946: [GC (Allocation Failure) 2018-08-09T08:41:35.024+0800: 4.946: [ParNew: 12734K->151K(12928K), 0.0004635 secs] 15301K->2719K(27264K), 0.0005408 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:41:35.057+0800: 4.979: [GC (Allocation Failure) 2018-08-09T08:41:35.057+0800: 4.979: [ParNew: 11671K->38K(12928K), 0.0003371 secs] 14239K->2605K(27264K), 0.0003801 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:42:59.030+0800: 88.953: [Full GC (System.gc()) 2018-08-09T08:42:59.030+0800: 88.953: [Tenured: 2567K->2536K(14336K), 0.0086218 secs] 13341K->2536K(27264K), [Metaspace: 6012K->6012K(1056768K)], 0.0086850 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
Heap
 par new generation   total 12928K, used 227K [0x00000000fe400000, 0x00000000ff200000, 0x00000000ff200000)
  eden space 11520K,   1% used [0x00000000fe400000, 0x00000000fe438f88, 0x00000000fef40000)
  from space 1408K,   0% used [0x00000000fef40000, 0x00000000fef40000, 0x00000000ff0a0000)
  to   space 1408K,   0% used [0x00000000ff0a0000, 0x00000000ff0a0000, 0x00000000ff200000)
 tenured generation   total 14336K, used 2536K [0x00000000ff200000, 0x0000000100000000, 0x0000000100000000)
   the space 14336K,  17% used [0x00000000ff200000, 0x00000000ff47a1e8, 0x00000000ff47a200, 0x0000000100000000)
 Metaspace       used 6023K, capacity 6252K, committed 6400K, reserved 1056768K
  class space    used 691K, capacity 761K, committed 768K, reserved 1048576K

以上是ParNew收集器+Serilal Old组合的GC日志，格式大同小异。

-XX:+UseParallelOldGC日志解析

Parallel收集器+Parallel Old收集器组合（-XX:+UseParallelOldGC）的日志如下：

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(2759076k free), swap 16215992k(7616208k 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:-UseLargePagesIndividualAllocation -XX:+UseParallelOldGC 
2018-05-09T20:44:49.341+0800: 0.618: [GC (Allocation Failure) [PSYoungGen: 11264K->1531K(12800K)] 11264K->2274K(27136K), 0.0043755 secs] [Times: user=0.05 sys=0.00, real=0.00 secs] 
2018-05-09T20:44:49.478+0800: 0.754: [GC (System.gc()) [PSYoungGen: 6544K->1531K(12800K)] 7286K->2626K(27136K), 0.0064927 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2018-05-09T20:44:49.484+0800: 0.761: [Full GC (System.gc()) [PSYoungGen: 1531K->0K(12800K)] [ParOldGen: 1094K->1917K(14336K)] 2626K->1917K(27136K), [Metaspace: 5968K->5968K(1056768K)], 0.0125897 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2018-05-09T20:44:49.624+0800: 0.901: [GC (Allocation Failure) [PSYoungGen: 11263K->64K(12800K)] 13181K->1981K(27136K), 0.0227273 secs] [Times: user=0.00 sys=0.00, real=0.02 secs] 
2018-05-09T20:44:49.690+0800: 0.967: [GC (Allocation Failure) [PSYoungGen: 11327K->64K(12800K)] 13245K->1981K(27136K), 0.0004702 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:44:49.729+0800: 1.007: [GC (Allocation Failure) [PSYoungGen: 11328K->64K(12800K)] 13245K->1981K(27136K), 0.0080092 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2018-05-09T20:44:49.774+0800: 1.052: [GC (Allocation Failure) [PSYoungGen: 11327K->64K(9728K)] 13245K->1989K(24064K), 0.0019594 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:46:15.771+0800: 87.048: [GC (System.gc()) [PSYoungGen: 302K->64K(11264K)] 2227K->1989K(25600K), 0.0004195 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:46:15.771+0800: 87.048: [Full GC (System.gc()) [PSYoungGen: 64K->0K(11264K)] [ParOldGen: 1925K->1704K(14336K)] 1989K->1704K(25600K), [Metaspace: 6039K->6033K(1056768K)], 0.0126567 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
Heap
 PSYoungGen      total 11264K, used 324K [0x00000000ff200000, 0x0000000100000000, 0x0000000100000000)
  eden space 8192K, 3% used [0x00000000ff200000,0x00000000ff2513a0,0x00000000ffa00000)
  from space 3072K, 0% used [0x00000000ffa00000,0x00000000ffa00000,0x00000000ffd00000)
  to   space 3072K, 0% used [0x00000000ffd00000,0x00000000ffd00000,0x0000000100000000)
 ParOldGen       total 14336K, used 1704K [0x00000000fe400000, 0x00000000ff200000, 0x00000000ff200000)
  object space 14336K, 11% used [0x00000000fe400000,0x00000000fe5aa360,0x00000000ff200000)
 Metaspace       used 6044K, capacity 6242K, committed 6400K, reserved 1056768K
  class space    used 688K, capacity 756K, committed 768K, reserved 1048576K

以上是Parallel收集器+Parallel Old收集器组合的GC日志，格式跟JDK1.8默认的-XX:+UseParallelGC大同小异。

-XX:+UseConcMarkSweepGC日志解析

-XX:+UseConcMarkSweepGC会指定CMS收集器+ParNew收集器+Serial Old收集器组合，优先使用ParNew收集器+CMS收集器的组合，当出现ConcurrentMode Fail或者Promotion Failed时，则采用ParNew收集器+Serial Old收集器的组合。日志如下：

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(2846816k free), swap 16215992k(7664596k free)
CommandLine flags: -XX:InitialHeapSize=29360128 -XX:MaxHeapSize=29360128 -XX:MaxNewSize=14680064 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
2018-05-09T20:53:14.086+0800: 0.590: [GC (Allocation Failure) 2018-08-09T11:53:14.086+0800: 0.590: [ParNew: 11520K->1407K(12928K), 0.0034803 secs] 11520K->2254K(27264K), 0.0039082 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:53:14.247+0800: 0.751: [Full GC (System.gc()) 2018-08-09T11:53:14.247+0800: 0.751: [CMS: 846K->1930K(14336K), 0.0103698 secs] 7165K->1930K(27264K), [Metaspace: 5963K->5963K(1056768K)], 0.0104529 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2018-05-09T20:53:14.292+0800: 0.795: [GC (Allocation Failure) 2018-08-09T11:53:14.292+0800: 0.795: [ParNew: 11519K->1199K(12928K), 0.0085679 secs] 13450K->3129K(27264K), 0.0086244 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2018-05-09T20:53:14.333+0800: 0.836: [GC (Allocation Failure) 2018-08-09T11:53:14.333+0800: 0.836: [ParNew: 12719K->300K(12928K), 0.0002620 secs] 14649K->2230K(27264K), 0.0003041 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2018-05-09T20:53:14.364+0800: 0.867: [GC (Allocation Failure) 2018-08-09T11:53:14.364+0800: 0.867: [ParNew: 11820K->75K(12928K), 0.0002787 secs] 13750K->2005K(27264K), 0.0003223 secs] [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]
2018-05-09T20:54:39.299+0800: 85.803: [Full GC (System.gc()) 2018-08-09T11:54:39.299+0800: 85.803: [CMS: 1930K->1832K(14336K), 0.0089015 secs] 12748K->1832K(27264K), [Metaspace: 6035K->6035K(1056768K)], 0.0089724 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

Heap
 par new generation   total 12928K, used 227K [0x00000000fe400000, 0x00000000ff200000, 0x00000000ff200000)
  eden space 11520K,   1% used [0x00000000fe400000, 0x00000000fe438cd8, 0x00000000fef40000)
  from space 1408K,   0% used [0x00000000fef40000, 0x00000000fef40000, 0x00000000ff0a0000)
  to   space 1408K,   0% used [0x00000000ff0a0000, 0x00000000ff0a0000, 0x00000000ff200000)
 concurrent mark-sweep generation total 14336K, used 1832K [0x00000000ff200000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 6045K, capacity 6252K, committed 6400K, reserved 1056768K
  class space    used 691K, capacity 761K, committed 768K, reserved 1048576K

第三行把当前使用的JVM参数打印出来，其中，-XX:MaxTenuringThreshold=6是指对象从新生代晋升到老年代需要对象年龄达到6岁，即经过6次GC。

第四行是新生代Young区的GC，首先是GC发生的时间。然后是GC发生的原因GC (Allocation Failure)，对象分配失败。[ParNew: 11520K->1407K(12928K), 0.0034803 secs]表示新生代回收前是11520K，回收后是1407K，新生代总大小12928K，回收耗时0.0034803 secs。11520K->2254K(27264K), 0.0039082 secs表示回收前堆大小11520K，回收后堆大小2254K，堆的总大小27264K。

第五行是老年代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 1048576K

G1日志分析详见上面代码中的注释，G1的垃圾收集比之前的收集器稍微复杂一些。