121
JVM實用參數（八）GC日誌
作者：PATRICK PESCHLOW，譯者：Greenster 校對：梁海艦
本係列的最後一部分是有關垃圾收集（GC）日誌的JVM參數。GC日誌是一個很重要的工具，它準確記錄了每一次的GC的執行時間和執行結果，通過分析GC日誌可以優化堆設置和GC設置，或者改進應用程序的對象分配模式。
-XX:+PrintGC
參數-XX:+PrintGC（或者-verbose:gc）開啟了簡單GC日誌模式，為每一次新生代（young generation）的GC和每一次的Full GC打印一行信息。下麵舉例說明：
[GC 246656K->243120K(376320K), 0.0929090 secs] [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中生成的日誌。為了便於閱讀這裏將一行日誌分為多行並使用縮進。
[GC
[PSYoungGen: 142816K->10752K(142848K)] 246648K->243136K(375296K), 0.0935090 secs
]
[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的輸出日誌
[Full GC
[PSYoungGen: 10752K->9707K(142848K)]
[ParOldGen: 232384K->232244K(485888K)] 243136K->241951K(628736K)
[PSPermGen: 3162K->3161K(21504K)], 1.5265450 secs
]
除了關於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啟動至今的時間戳會被添加到每一行中。例子如下：
0.185: [GC 66048K->53077K(251392K), 0.0977580 secs] 0.323: [GC 119125K->114661K(317440K), 0.1448850 secs] 0.603: [GC 246757K->243133K(375296K), 0.2860800 secs]
如果指定了-XX:+PrintGCDateStamps，每一行就添加上了絕對的日期和時間。
2014-01-03T12:08:38.102-0100: [GC 66048K->53077K(251392K), 0.0959470 secs] 2014-01-03T12:08:38.239-0100: [GC 119125K->114661K(317440K), 0.1421720 secs] 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方法來設置這些參數。
最後更新：2017-05-23 19:31:54