1. 程式人生 > >JVM實用引數 GC日誌

JVM實用引數 GC日誌

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