http://www.cnblogs.com/chy2055/p/5124040.html
原文地址：https://blog.codecentric.de/en/2014/01/useful-jvm-flags-part-8-gc-logging/
作者：PATRICK PESCHLOW，譯者：Greenster 校對(duì)：梁海艦
-XX:+PrintGC
1
[GC 246656K->243120K(376320K), 0.0929090 secs]
2
[Full GC 243120K->241951K(629760K), 1.5589690 secs]
簡(jiǎn)單模式的GC日志格式是與GC算法無(wú)關(guān)的，日志也沒(méi)有提供太多的信息。在上面的例子中，我們甚至無(wú)法從日志中判斷是否GC將一些對(duì)象從young generation移到了old generation。所以詳細(xì)模式的GC日志更有用一些。
-XX:PrintGCDetails
如果不是使用-XX:+PrintGC，而是-XX:PrintGCDetails，就開(kāi)啟了詳細(xì)GC日志模式。在這種模式下，日志格式和所使用的GC算法有關(guān)。我們首先看一下使用Throughput垃圾收集器在young generation中生成的日志。為了便于閱讀這里將一行日志分為多行并使用縮進(jìn)
[GC
[PSYoungGen: 142816K->10752K(142848K)] 246648K->243136K(375296K),
0,0935090 secs
]
[Times: user=0,55 sys=0,10, real=0,09 secs]
既然我們已經(jīng)知道了young generation的大小，所以很容易判定發(fā)生了GC，因?yàn)閥oung generation無(wú)法分配更多的對(duì)象空間：已經(jīng)使用了142848K中的142816K。我們可以進(jìn)一步得出結(jié)論，多數(shù)從young generation移除的對(duì)象仍然在堆空間中，只是被移到了old generation：通過(guò)對(duì)比綠色的和藍(lán)色的部分可以發(fā)現(xiàn)即使young generation幾乎被完全清空（從142816K減少到10752K），但是所占用的堆空間仍然基本相同（從246648K到243136K）。
詳細(xì)日志的“Times”部分包含了GC所使用的CPU時(shí)間信息，分別為操作系統(tǒng)的用戶(hù)空間和系統(tǒng)空間所使用的時(shí)間。同時(shí)，它顯示了GC運(yùn)行的“真實(shí)”時(shí)間（0.09秒是0.0929090秒的近似值）。如果CPU時(shí)間（譯者注：0.55秒+0.10秒）明顯多于”真實(shí)“時(shí)間（譯者注：0.09秒），我們可以得出結(jié)論：GC使用了多線程運(yùn)行。這樣的話CPU時(shí)間就是所有GC線程所花費(fèi)的CPU時(shí)間的總和。實(shí)際上我們的例子中的垃圾收集器使用了8個(gè)線程。
接下來(lái)看一下Full GC的輸出日志:
[Full GC
[PSYoungGen: 10752K->9707K(142848K)]
[ParOldGen: 232384K->232244K(485888K)] 243136K->241951K(628736K)
[PSPermGen: 3162K->3161K(21504K)],
1,5265450 secs
]
[Times: user=10,96 sys=0,06, real=1,53 secs]
Full GC也可以通過(guò)顯式的請(qǐng)求而觸發(fā)，可以是通過(guò)應(yīng)用程序，或者是一個(gè)外部的JVM接口。這樣觸發(fā)的GC可以很容易在日志里分辨出來(lái)，因?yàn)檩敵龅娜罩臼且浴癋ull GC(System)”開(kāi)頭的，而不是“Full GC”。
對(duì)于Serial垃圾收集器，詳細(xì)的GC日志和Throughput垃圾收集器是非常相似的。唯一的區(qū)別是不同的generation日志可能使用了不同的GC算法（例如：old generation的日志可能以Tenured開(kāi)頭，而不是ParOldGen）。使用垃圾收集器作為一行日志的開(kāi)頭可以方便我們從日志就判斷出JVM的GC設(shè)置。
對(duì)于CMS垃圾收集器，young generation的詳細(xì)日志也和Throughput垃圾收集器非常相似，但是old generation的日志卻不是這樣。對(duì)于CMS垃圾收集器，在old generation中的GC是在不同的時(shí)間片內(nèi)與應(yīng)用程序同時(shí)運(yùn)行的。GC日志自然也和Full GC的日志不同。而且在不同時(shí)間片的日志夾雜著在此期間young generation的GC日志。但是了解了上面介紹的GC日志的基本元素，也不難理解在不同時(shí)間片內(nèi)的日志。只是在解釋GC運(yùn)行時(shí)間時(shí)要特別注意，由于大多數(shù)時(shí)間片內(nèi)的GC都是和應(yīng)用程序同時(shí)運(yùn)行的，所以和那種獨(dú)占式的GC相比，GC的持續(xù)時(shí)間更長(zhǎng)一些并不說(shuō)明一定有問(wèn)題。
-XX:+PrintGCTimeStamps和-XX:+PrintGCDateStamps
使用-XX:+PrintGCTimeStamps可以將時(shí)間和日期也加到GC日志中。表示自JVM啟動(dòng)至今的時(shí)間戳?xí)惶砑拥矫恳恍兄?。例子如下?/p>
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，每一行就添加上了絕對(duì)的日期和時(shí)間。
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]
如果需要也可以同時(shí)使用兩個(gè)參數(shù)。推薦同時(shí)使用這兩個(gè)參數(shù)，因?yàn)檫@樣在關(guān)聯(lián)不同來(lái)源的GC日志時(shí)很有幫助。
-Xloggc
缺省的GC日志時(shí)輸出到終端的，使用-Xloggc:也可以輸出到指定的文件。需要注意這個(gè)參數(shù)隱式的設(shè)置了參數(shù)-XX:+PrintGC和-XX:+PrintGCTimeStamps，但為了以防在新版本的JVM中有任何變化，我仍建議顯示的設(shè)置這些參數(shù)
可管理的JVM參數(shù)
一個(gè)常常被討論的問(wèn)題是在生產(chǎn)環(huán)境中GC日志是否應(yīng)該開(kāi)啟。因?yàn)樗a(chǎn)生的開(kāi)銷(xiāo)通常都非常有限，因此我的答案是需要開(kāi)啟。但并不一定在啟動(dòng)JVM時(shí)就必須指定GC日志參數(shù)。
HotSpot JVM有一類(lèi)特別的參數(shù)叫做可管理的參數(shù)。對(duì)于這些參數(shù)，可以在運(yùn)行時(shí)修改他們的值。我們這里所討論的所有參數(shù)以及以“PrintGC”開(kāi)頭的參數(shù)都是可管理的參數(shù)。這樣在任何時(shí)候我們都可以開(kāi)啟或是關(guān)閉GC日志。比如我們可以使用JDK自帶的jinfo工具來(lái)設(shè)置這些參數(shù)，或者是通過(guò)JMX客戶(hù)端調(diào)用HotSpotDiagnostic MXBean的setVMOption方法來(lái)設(shè)置這些參數(shù)。
