GC通用日志解读

本文主要讲述gc日志的解读。除了CMS和G1收集器的GC稍微特殊外，其展示形式其实都大同小异。

通用日志格式

各个收集器的日志都维持一定的共性，例如以下两段典型的GC日志：

33.125: [GC [DefNew: 3324K->152K(3712K), 0.0025925 secs] 3324K->152K(11904K), 0.0031680 secs]

100.667: [Full GC [Tenured: 0K->210K(10240K), 0.0149142 secs] 4603K->210K(19456K), [Perm : 2999K->2999K(21248K)], 0.0150007 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]

最前面的数字“33.125：”和“100.667：”代表了GC发生的时间，这个数字的含义是从Java虚拟机启动以来经过的秒数。GC日志开头的“[GC”和“[Full GC”说明了这次垃圾收集的停顿类型，而不是用来区分新生代GC还是老年代GC的。如果有“Full”，说明这次GC是发生了Stop-The-World的，例如下面这段新生代收集器ParNew的日志也会出现“[Full GC”（这一般是因为出现了分配担保失败之类的问题，所以才导致STW）。如果是调用System.gc()方法所触发的收集，那么在这里将显示“[Full GC（Sys-tem）”。
[Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000288 secs]

接下来的“[DefNew”、“[Tenured”、“[Perm”表示GC发生的区域，这里显示的区域名称与使用的GC收集器是密切相关的，例如上面样例所使用的Serial收集器中的新生代名为“Default NewGeneration”，所以显示的是“[DefNew”。如果是ParNew收集器，新生代名称就会变为“[ParNew”，意为“Parallel New Generation”。如果采用Parallel Scavenge收集器，那它配套的新生代称为“PSYoungGen”，老年代和永久代同理，名称也是由收集器决定的。

后面方括号内部的“3324K->152K（3712K）”含义是“GC前该内存区域已使用容量->GC后该内存区域已使用容量（该内存区域总容量）”。

而在方括号之外的“3324K->152K（11904K）”表示“GC前Java堆已使用容量->GC后Java堆已使用容量（Java堆总容量）”。

再往后，“0.0025925 secs”表示该内存区域GC所占用的时间，单位是秒。有的收集器会给出更具体的时间数据，如“[Times：user=0.01 sys=0.00，real=0.02 secs]”，这里面的user、sys和real与Linux的time命令所输出的时间含义一致，分别代表用户态消耗的CPU时间、内核态消耗的CPU事件和操作从开始到结束所经过的墙钟时间（WallClock Time）。CPU时间与墙钟时间的区别是，墙钟时间包括各种非运算的等待耗时，例如等待磁盘I/O、等待线程阻塞，而CPU时间不包括这些耗时，但当系统有多CPU或者多核的话，多线程操作会叠加这些CPU时间，所以读者看到user或sys时间超过real时间是完全正常的。

一、Serial/SerialOld收集器的日志

新生代

0.148: [GC 0.148: [DefNew: 32443K->334K(39296K), 0.0383600 secs] 32443K->25080K(126720K),
0.0384220 secs] [Times: user=0.02 sys=0.01, real=0.04 secs]

对象分布

0.280: [GC 0.280: [DefNew
Desired survivor size 2228224 bytes, new threshold 15 (max 15)
- age   1:         56 bytes,         56 total
- age   2:         56 bytes,        112 total
- age   3:         40 bytes,        152 total
- age   4:        536 bytes,        688 total
- age   5:     314800 bytes,     315488 total
: 20473K->308K(39296K), 0.0282400 secs]0.309: [Tenured: 105619K->105927K(107592K), 0.0054030 secs]
 105927K->105927K(146888K), [Perm : 2872K->2872K(21248K)], 0.0340160 secs]
 [Times: user=0.02 sys=0.01, real=0.04 secs]

晋升失败

0.633: [GC 0.633: [DefNew (promotion failed) : 136158K->149171K(157248K), 0.1441370 secs]0.777:
 [Tenured: 333101K->327922K(349568K), 0.0983430 secs] 370626K->327922K(506816K),
 [Perm : 2872K->2872K(21248K)], 0.2425880 secs] [Times: user=0.18 sys=0.07, real=0.24 secs]

年老代

2.012: [Full GC 2.012: [Tenured: 343656K->216196K(349568K), 0.0886910 secs]
 492212K->216196K(506816K), [Perm : 2870K->2870K(21248K)], 0.0887540 secs]
 [Times: user=0.09 sys=0.00, real=0.09 secs]

二、ParNew收集器的日志

新生代

0.130: [GC 0.130: [ParNew: 24187K->342K(39296K), 0.0275930 secs] 24187K->16133K(126720K),
 0.0276490 secs] [Times: user=0.03 sys=0.01, real=0.03 secs]

对象分布

0.245: [GC 0.245: [ParNew
Desired survivor size 2228224 bytes, new threshold 15 (max 15)
- age   1:        392 bytes,        392 total
- age   2:         56 bytes,        448 total
- age   3:        256 bytes,        704 total
- age   4:     311144 bytes,     311848 total
: 29587K->451K(39296K), 0.0349430 secs]0.280: [Tenured: 97630K->80633K(104540K),
 0.0371550 secs] 98793K->80633K(143836K), [Perm : 2872K->2872K(21248K)], 0.0723530 secs]
 [Times: user=0.08 sys=0.03, real=0.08 secs]

晋升失败

5.031: [GC 5.031: [ParNew (promotion failed): 132163K->146998K(157248K), 0.0405880 secs]5.071:
 [Tenured: 335614K->284433K(349568K), 0.1145870 secs] 382197K->284433K(506816K),
 [Perm : 2870K->2870K(21248K)], 0.1552900 secs] [Times: user=0.19 sys=0.00, real=0.16 secs]

年老代

0.954: [Full GC 0.954: [Tenured: 338420K->337591K(349568K), 0.1746320 secs]
 472544K->429640K(506816K), [Perm : 2872K->2870K(21248K)], 0.1747090 secs]
 [Times: user=0.17 sys=0.00, real=0.17 secs]

三、Parallel/ParallelOld收集器的日志

新生代

0.110: [GC [PSYoungGen: 32768K->384K(38208K)] 32768K->26662K(125632K), 0.0317620 secs]
 [Times: user=0.04 sys=0.03, real=0.03 secs]

[GC [PSYoungGen: 32768K->384K(38208K)] 32768K->26662K(125632K)，表示执行完后新生代的内存使用率，PSYoungGen表示所回收的内存区域类型，与使用的垃圾收集器相关，PS来说，新生代是PSYoungGen，年老代是ParOldGen，永久代是PSPermGen。

32768K为回收前新生代的内存使用大小，384K为回收后新生代的内存使用大小，38208K为新生代的内存总大小。后面的
32768K是回收前Java堆区的整体内存使用大小，26662K是回收后Java堆区的整体内存使用大小，125632K是整个Java堆区的内存大小。

0.0317620 表示此次执行MinorGC的耗时，以秒为单位。

[Times: user=0.04 sys=0.03, real=0.03 secs]，表示程序耗时、系统耗时、实际耗时。如何发现user或者sys的时间超过real的时间，这是正常的，因为如果是多线程的话，进行CPU切换，会叠加多线程的时间。

对象分布

0.223: [GC
Desired survivor size 5570560 bytes, new threshold 7 (max 15)
 [PSYoungGen: 29285K->416K(38208K)] 187914K->181767K(239104K), 0.0342700 secs]
 [Times: user=0.04 sys=0.01, real=0.04 secs]

年老代

0.186: [Full GC [PSYoungGen: 29813K->13540K(38208K)] [ParOldGen: 64141K->77375K(87424K)]
93955K->90916K(125632K) [PSPermGen: 2872K->2870K(21248K)], 0.0321400 secs]
[Times: user=0.03 sys=0.01, real=0.03 secs]

完整log

2015-04-30T14:54:41.461+0800: 99170.722: [GC [PSYoungGen: 690000K->8498K(688704K)] 2084845K->1405110K(2086848K), 0.0223390 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
2015-04-30T14:55:05.874+0800: 99195.134: [GC [PSYoungGen: 688690K->7584K(689600K)] 2085302K->1404798K(2087744K), 0.0223200 secs] [Times: user=0.04 sys=0.01, real=0.03 secs] 
2015-04-30T14:55:05.913+0800: 99195.173: [Full GC [PSYoungGen: 7584K->0K(689600K)] [ParOldGen: 1397214K->913970K(1398144K)] 1404798K->913970K(2087744K) [PSPermGen: 83025K->82697K(166016K)], 4.3123060 secs] [Times: user=13.48 sys=0.17, real=4.32 secs] 
2015-04-30T14:55:31.227+0800: 99220.488: [GC [PSYoungGen: 680192K->8010K(689792K)] 1594162K->921980K(2087936K), 0.0412930 secs] [Times: user=0.09 sys=0.00, real=0.04 secs]