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時間是徹底正常的。

1、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]

2、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]

3、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]