JVM GC日志分析及Gc日志分析工具

 

一、 GC日志分析

GC日志是一個很重要的工具，它准確記錄了每一次的GC的執行時間和執行結果；

通過分析GC日志可以調優堆設置和GC設置，或者改進應用程序的對象分配模式，

開啟的JVM啟動參數如下：-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

 

 

1.GC日志格式

 

GC日志格式為
$發生時間:[$是否STW $發生時間: [$內存區域: $該區域GC前大小->$該區域GC后大小($該區域總容量), $該區域GC耗時] $GC前堆大小->$GC后堆大小($堆總容量), $GC總耗時][$GC總耗時]

G1 日志：

2020-06-19T12:29:28.627+0000: 188884.482: [GC pause (G1 Evacuation Pause) (young), 0.0118605 secs] //GC 表示是一次YGC（Young GC）

[Parallel Time: 5.8 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 188884481.8, Avg: 188884481.8, Max: 188884481.8, Diff: 0.0]
[Ext Root Scanning (ms): Min: 2.1, Avg: 2.4, Max: 2.9, Diff: 0.8, Sum: 9.5]
[Update RS (ms): Min: 0.4, Avg: 0.7, Max: 0.8, Diff: 0.5, Sum: 2.8]
[Processed Buffers: Min: 3, Avg: 17.5, Max: 33, Diff: 30, Sum: 70]
[Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.7]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 2.2, Avg: 2.4, Max: 2.5, Diff: 0.3, Sum: 9.6]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 3.2, Max: 6, Diff: 5, Sum: 13]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.2]
[GC Worker Total (ms): Min: 5.7, Avg: 5.7, Max: 5.7, Diff: 0.0, Sum: 22.8]
[GC Worker End (ms): Min: 188884487.5, Avg: 188884487.5, Max: 188884487.5, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.4 ms]
[Other: 5.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 4.4 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.6 ms]
[Eden: 1778.0M(1778.0M)->0.0B(1778.0M) Survivors: 14.0M->14.0M Heap: 3975.2M(7168.0M)->2197.3M(7168.0M)]
[Times: user=0.04 sys=0.00, real=0.02 secs]

　　

2.常見的Young GC、Full GC日志含義如下：

Young gc 日志：

ParNew GC 日志

 

 示例：

2017-05-01T14:20:34.306+0800: 44.642: [GC2017-05-01T14:20:34.306+0800: 44.642: [ParNew: 327680K->40960K(368640K), 0.0883899 secs] 327680K->60854K(1007616K), 0.0886153 secs] [Times: user=0.56 sys=0.05, real=0.10 secs]

 

 

 

 

 Full GC 日志：

 

 

 

Mixed gc 日志：（只有G1 收集器才有的gc 類型）

 

 二、Gc日志分析工具

免費的GC日志圖形分析工具推薦下面2個：

• GCViewer，下載jar包直接運行
• gceasy，web工具，上傳GC日志在線使用

 

 

GCHisto

http://java.net/projects/gchisto

直接點擊gchisto.jar就可以運行，點add載入gc.log

統計了總共gc次數，youngGC次數，FullGC次數，次數的百分比，GC消耗的時間，百分比，平均消耗時間，消耗時間最小最大值等

• 統計的圖形化表示

• YoungGC,FullGC不同消耗時間上次數的分布圖，勾選可以顯示youngGC或fullGC單獨的分布情況

• 整個時間過程詳細的gc情況，可以對整個過程進行剖析

GCLogViewer

http://code.google.com/p/gclogviewer/

gclogviewer是一個支持jdk 6的gc log可視化工具。

GCLogViewer支持：

1. 支持根據gc log生成GC的趨勢圖；
2. 生成調優建議所需的數據趨勢圖。
3. 整個過程gc情況的趨勢圖，還顯示了gc類型，吞吐量，平均gc頻率，內存變化趨勢等。

Tools里還能比較不同gc日志:

HPjmeter

• 獲取地址 http://www.hp.com/go/java
• 參考文檔 http://www.javaperformancetuning.com/tools/hpjtune/index.shtml

工具很強大，但只能打開由以下參數生成的GC log， -verbose:gc -Xloggc:gc.log,添加其他參數生成的gc.log無法打開。

GCViewer

http://www.tagtraum.com/gcviewer.html

這個工具用的挺多的，但只能在JDK1.5以下的版本中運行，1.6以后沒有對應。

garbagecat

http://code.google.com/a/eclipselabs.org/p/garbagecat/wiki/Documentation

其它監控方法

• Jvisualvm

Jvisualvm動態分析jvm內存情況和gc情況，插件：visualGC

jvisualvm還可以heapdump出對應hprof文件（默認存放路徑：監控的服務器 /tmp下），利用相關工具，比如HPjmeter可以對其進行分析

grep Full gc.log粗略觀察FullGC發生頻率

jstat –gcutil [pid] [intervel] [count]

• jmap

jmap -histo pid可以觀測對象的個數和占用空間

jmap -heap pid可以觀測jvm配置參數，堆內存各區使用情況

• jprofiler,jmap dump出來用MAT分析

如果要分析的dump文件很大的話，就需要很多內存，很容易crash。

所以在啟動時，我們應該加上一些參數： Java –Xms512M –Xmx1024M –Xss8M

參考資料：

探秘Java虛擬機——內存管理與垃圾回收http://sunbean.blog.51cto.com/972509/768034

 

http://xstarcd.github.io/wiki/Java/JVM_GC.html