摘要：系列垃圾回收基礎的編譯策略的三大基礎算法的三大高級算法策略的評價指標信息查看通用日志解讀的數據結構類初始化順序對象結構及大小計算的類加載機制對象分配簡要流程年老代過大有什么影響空間溢出實例關于線程與序本文主要講述日志的解讀。

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]