快速解讀GC日志

本文是 Plumbr 發行的 Java垃圾收集指南 的部分內容。文中將介紹GC日志的輸出格式, 以及如何解讀GC日志, 從中提取有用的信息。我們通過 -XX:+UseSerialGC 選項,指定JVM使用串行垃圾收集器, 並使用下面的啟動參數讓 JVM 打印出詳細的GC日志:

-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps
-Xloggc:/log/gc.log
-XX:+UseGCLogFileRotation 
-XX:NumberOfGCLogFiles=3 
-XX:GCLogFileSize=1024k

這樣配置以后，發生GC時輸出的日志就類似於下面這種格式(為了顯示方便,已手工折行):

2015-05-26T14:45:37.987-0200: 151.126: 
  [GC (Allocation Failure) 151.126:
    [DefNew: 629119K->69888K(629120K), 0.0584157 secs]
    1619346K->1273247K(2027264K), 0.0585007 secs] 
  [Times: user=0.06 sys=0.00, real=0.06 secs]

2015-05-26T14:45:59.690-0200: 172.829: 
  [GC (Allocation Failure) 172.829: 
    [DefNew: 629120K->629120K(629120K), 0.0000372 secs]
    172.829: [Tenured: 1203359K->755802K(1398144K), 0.1855567 secs]
    1832479K->755802K(2027264K),
    [Metaspace: 6741K->6741K(1056768K)], 0.1856954 secs]
  [Times: user=0.18 sys=0.00, real=0.18 secs]

上面的GC日志暴露了JVM中的一些信息。事實上，這個日志片段中發生了 2 次垃圾回收事件(Garbage Collection events)。其中一次清理的是年輕代(Young generation), 而第二次處理的是整個堆內存。下面我們來看，如何解讀第一次GC事件，發生在年輕代中的小型GC(Minor GC):

2015-05-26T14:45:37.987-0200¹:151.126²:[GC³(Allocation Failure⁴)
151.126: [DefNew⁵:629119K->69888K⁶(629120K)⁷
, 0.0584157 secs]1619346K->1273247K⁸(2027264K)⁹,0.0585007 secs¹⁰]
[Times: user=0.06 sys=0.00, real=0.06 secs]¹¹

1. 2015-05-26T14:45:37.987-0200 – GC事件(GC event)開始的時間點.
2. 151.126 – GC時間的開始時間,相對於JVM的啟動時間,單位是秒(Measured in seconds).
3. GC – 用來區分(distinguish)是 Minor GC 還是 Full GC 的標志(Flag). 這里的 GC 表明本次發生的是 Minor GC.
4. Allocation Failure – 引起垃圾回收的原因. 本次GC是因為年輕代中沒有任何合適的區域能夠存放需要分配的數據結構而觸發的.
5. DefNew – 使用的垃圾收集器的名字. DefNew 這個名字代表的是: 單線程(single-threaded), 采用標記復制(mark-copy)算法的, 使整個JVM暫停運行(stop-the-world)的年輕代(Young generation) 垃圾收集器(garbage collector).
6. 629119K->69888K – 在本次垃圾收集之前和之后的年輕代內存使用情況(Usage).
7. (629120K) – 年輕代的總的大小(Total size).
8. 1619346K->1273247K – 在本次垃圾收集之前和之后整個堆內存的使用情況(Total used heap).
9. (2027264K) – 總的可用的堆內存(Total available heap).
10. 0.0585007 secs – GC事件的持續時間(Duration),單位是秒.
11. [Times: user=0.06 sys=0.00, real=0.06 secs] – GC事件的持續時間,通過多種分類來進行衡量:
    
    • user – 此次垃圾回收, 垃圾收集線程消耗的所有CPU時間(Total CPU time).
    • sys – 操作系統調用(OS call) 以及等待系統事件的時間(waiting for system event)
    • real – 應用程序暫停的時間(Clock time). 由於串行垃圾收集器(Serial Garbage Collector)只會使用單個線程, 所以 real time 等於 user 以及 system time 的總和.

通過上面的分析, 我們可以計算出在垃圾收集期間, JVM 中的內存使用情況。在垃圾收集之前, 堆內存總的使用了 1.54G (1,619,346K)。其中, 年輕代使用了 614M(629,119k)。可以算出老年代使用的內存為: 967M(990,227K)。

下一組數據( -> 右邊)中蘊含了更重要的結論, 年輕代的內存使用在垃圾回收后下降了 546M(559,231k), 但總的堆內存使用(total heap usage)只減少了 337M(346,099k). 通過這一點,我們可以計算出, 有 208M(213,132K) 的年輕代對象被提升到老年代(Old)中。

這個GC事件可以用下面的示意圖來表示, 上方表示GC之前的內存使用情況, 下方表示結束后的內存使用情況:

如果你想學習更多, 請查看完整的 Java垃圾收集指南, 本示例是從其中抽取的。

原文鏈接: Understanding Garbage Collection Logs

翻譯日期: 2015年10月18日

翻譯人員: 鐵錨 http://blog.csdn.net/renfufei