jvm系列
序
本文主要讲述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: [DefNewDesired 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: [ParNewDesired 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: [GCDesired 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]