JVM實用參數 GC日誌

原文章地址：http://blog.panaihua.com/archives/151

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方法來設置這些參數。

原文章地址：http://blog.panaihua.com/archives/151