GC通用日志解读

摘要：系列垃圾回收基础的编译策略的三大基础算法的三大高级算法策略的评价指标信息查看通用日志解读的数据结构类初始化顺序对象结构及大小计算的类加载机制对象分配简要流程年老代过大有什么影响空间溢出实例关于线程与序本文主要讲述日志的解读。

jvm系列

垃圾回收基础

JVM的编译策略

GC的三大基础算法

GC的三大高级算法

GC策略的评价指标

JVM信息查看

GC通用日志解读

jvm的card table数据结构

Java类初始化顺序

Java对象结构及大小计算

Java的类加载机制

Java对象分配简要流程

年老代过大有什么影响

Survivor空间溢出实例

关于Object=null

Java线程与Xss

本文主要讲述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时间是完全正常的。

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]

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]

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]

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]