JVM調優的GC日志

本系列的最後一部分是有關垃圾收集（GC）日志的JVM參數。GC日志是一個很重要的工具，它準确記錄了每一次的GC的執行時間和執行結果，通過分析GC日志可以優化堆設定和GC設定，或者改進應用程式的對象配置設定模式。

-XX:+PrintGC

參數-XX:+PrintGC（或者-verbose:gc）開啟了簡單GC日志模式，為每一次新生代（young generation）的GC和每一次的Full GC列印一行資訊。下面舉例說明：

1	[GC 246656K->243120K(376320K),  0.0929090 secs]

2	[Full GC 243120K->241951K(629760K),  1.5589690 secs]

每行開始首先是GC的類型（可以是“GC”或者“Full GC”），然後是在GC之前和GC之後已使用的堆空間，再然後是目前的堆容量，最後是GC持續的時間（以秒計）。

第一行的意思就是GC将已使用的堆空間從246656K減少到243120K，目前的堆容量（譯者注：GC發生時）是376320K，GC持續的時間是0.0929090秒。

簡單模式的GC日志格式是與GC算法無關的，日志也沒有提供太多的資訊。在上面的例子中，我們甚至無法從日志中判斷是否GC将一些對象從young generation移到了old generation。是以詳細模式的GC日志更有用一些。

-XX:PrintGCDetails

如果不是使用-XX:+PrintGC，而是-XX:PrintGCDetails，就開啟了詳細GC日志模式。在這種模式下，日志格式和所使用的GC算法有關。我們首先看一下使用Throughput垃圾收集器在young generation中生成的日志。為了便于閱讀這裡将一行日志分為多行并使用縮進。

1

[GC

2	[PSYoungGen: 142816K->10752K(142848K)] 246648K->243136K(375296K),  0.0935090 secs

3

]

4	[Times: user= 0.55 sys= 0.10 , real= 0.09 secs]

我們可以很容易發現：這是一次在young generation中的GC，它将已使用的堆空間從246648K減少到了243136K，用時0.0935090秒。此外我們還可以得到更多的資訊：所使用的垃圾收集器（即PSYoungGen）、young generation的大小和使用情況（在這個例子中“PSYoungGen”垃圾收集器将young generation所使用的堆空間從142816K減少到10752K）。

既然我們已經知道了young generation的大小，是以很容易判定發生了GC，因為young generation無法配置設定更多的對象空間：已經使用了142848K中的142816K。我們可以進一步得出結論，多數從young generation移除的對象仍然在堆空間中，隻是被移到了old generation：通過對比綠色的和藍色的部分可以發現即使young generation幾乎被完全清空（從142816K減少到10752K），但是所占用的堆空間仍然基本相同（從246648K到243136K）。

詳細日志的“Times”部分包含了GC所使用的CPU時間資訊，分别為作業系統的使用者空間和系統空間所使用的時間。同時，它顯示了GC運作的“真實”時間（0.09秒是0.0929090秒的近似值）。如果CPU時間（譯者注：0.55秒+0.10秒）明顯多于”真實“時間（譯者注：0.09秒），我們可以得出結論：GC使用了多線程運作。這樣的話CPU時間就是所有GC線程所花費的CPU時間的總和。實際上我們的例子中的垃圾收集器使用了8個線程。

接下來看一下Full GC的輸出日志

1

[Full GC

2	[PSYoungGen: 10752K->9707K(142848K)]

3	[ParOldGen: 232384K->232244K(485888K)] 243136K->241951K(628736K)

4	[PSPermGen: 3162K->3161K(21504K)],  1.5265450 secs

5

]

除了關于young generation的詳細資訊，日志也提供了old generation和permanent generation的詳細資訊。對于這三個generations，一樣也可以看到所使用的垃圾收集器、堆空間的大小、GC前後的堆使用情況。需要注意的是顯示堆空間的大小等于young generation和old generation各自堆空間的和。以上面為例，堆空間總共占用了241951K，其中9707K在young generation，232244K在old generation。Full GC持續了大約1.53秒，使用者空間的CPU執行時間為10.96秒，說明GC使用了多線程（和之前一樣8個線程）。

對不同generation詳細的日志可以讓我們分析GC的原因，如果某個generation的日志顯示在GC之前，堆空間幾乎被占滿，那麼很有可能就是這個generation觸發了GC。但是在上面的例子中，三個generation中的任何一個都不是這樣的，在這種情況下是什麼原因觸發了GC呢。對于Throughput垃圾收集器，在某一個generation被過度使用之前，GC ergonomics（參考本系列第6節）決定要啟動GC。

Full GC也可以通過顯式的請求而觸發，可以是通過應用程式，或者是一個外部的JVM接口。這樣觸發的GC可以很容易在日志裡分辨出來，因為輸出的日志是以“Full GC(System)”開頭的，而不是“Full GC”。

對于Serial垃圾收集器，詳細的GC日志和Throughput垃圾收集器是非常相似的。唯一的差別是不同的generation日志可能使用了不同的GC算法（例如：old generation的日志可能以Tenured開頭，而不是ParOldGen）。使用垃圾收集器作為一行日志的開頭可以友善我們從日志就判斷出JVM的GC設定。

對于CMS垃圾收集器，young generation的詳細日志也和Throughput垃圾收集器非常相似，但是old generation的日志卻不是這樣。對于CMS垃圾收集器，在old generation中的GC是在不同的時間片内與應用程式同時運作的。GC日志自然也和Full GC的日志不同。而且在不同時間片的日志夾雜着在此期間young generation的GC日志。但是了解了上面介紹的GC日志的基本元素，也不難了解在不同時間片内的日志。隻是在解釋GC運作時間時要特别注意，由于大多數時間片内的GC都是和應用程式同時運作的，是以和那種獨占式的GC相比，GC的持續時間更長一些并不說明一定有問題。

正如我們在第7節中所了解的，即使CMS垃圾收集器沒有完成一個CMS周期，Full GC也可能會發生。如果發生了GC，在日志中會包含觸發Full GC的原因，例如衆所周知的”concurrent mode failure“。

為了避免過于冗長，我這裡就不詳細說明CMS垃圾收集器的日志了。另外，CMS垃圾收集器的作者做了詳細的說明（在這裡），強烈建議閱讀。

-XX:+PrintGCTimeStamps和-XX:+PrintGCDateStamps

使用-XX:+PrintGCTimeStamps可以将時間和日期也加到GC日志中。表示自JVM啟動至今的時間戳會被添加到每一行中。例子如下：

1	0.185 : [GC 66048K->53077K(251392K),  0.0977580 secs]

2	0.323 : [GC 119125K->114661K(317440K),  0.1448850 secs]

3	0.603 : [GC 246757K->243133K(375296K),  0.2860800 secs]

如果指定了-XX:+PrintGCDateStamps，每一行就添加上了絕對的日期和時間。

1	2014 - 01 -03T12: 08 : 38.102 - 0100 : [GC 66048K->53077K(251392K),  0.0959470 secs]

2	2014 - 01 -03T12: 08 : 38.239 - 0100 : [GC 119125K->114661K(317440K),  0.1421720 secs]

3	2014 - 01 -03T12: 08 : 38.513 - 0100 : [GC 246757K->243133K(375296K),  0.2761000 secs]

如果需要也可以同時使用兩個參數。推薦同時使用這兩個參數，因為這樣在關聯不同來源的GC日志時很有幫助。

-Xloggc

預設的GC日志時輸出到終端的，使用-Xloggc:也可以輸出到指定的檔案。需要注意這個參數隐式的設定了參數-XX:+PrintGC和-XX:+PrintGCTimeStamps，但為了以防在新版本的JVM中有任何變化，我仍建議顯示的設定這些參數。

可管理的JVM參數

一個常常被讨論的問題是在生産環境中GC日志是否應該開啟。因為它所産生的開銷通常都非常有限，是以我的答案是需要開啟。但并不一定在啟動JVM時就必須指定GC日志參數。

HotSpot JVM有一類特别的參數叫做可管理的參數。對于這些參數，可以在運作時修改他們的值。我們這裡所讨論的所有參數以及以“PrintGC”開頭的參數都是可管理的參數。這樣在任何時候我們都可以開啟或是關閉GC日志。比如我們可以使用JDK自帶的jinfo工具來設定這些參數，或者是通過JMX用戶端調用

HotSpotDiagnostic MXBean的

setVMOption方法來設定這些參數。