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

第六行，首先也是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日志解析