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

收集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 指定输出路径收集日志到日志文件

例如,我使用如下参数启动:

1
2
3
4
5
6
7
8
-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),日志如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
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)的日志如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
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)的日志如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
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)的日志如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
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收集器的组合。日志如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
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),它的格式差异较大,日志如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
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的垃圾收集比之前的收集器稍微复杂一些。