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