本系列的最后一部分是有關垃圾收集（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方法來設置這些參數。