gc日志解析 java gc日志解读

转载

数据小探 2023-09-20 10:35:10

文章标签 gc日志解析 java 老年代 java JVM 文章分类 Java 后端开发

背景

GC日志参数

常用参数

其他参数

GC日志格式

日志分类

Minor GC

Full GC

Minor GC日志解析

Full GC日志解析

GC日志分析工具

GCEasy

其他

结语

背景

这是JVM学习笔记的最后一篇文章，分析一下GC日志，在JVM学习笔记之堆也分析了一次日志，但这次更加详细，不过如果对JVM堆的结构(年轻代、伊甸园区、老年代、元空间等)不熟悉的话，还是建议看看那篇文章。关于java的垃圾回收和垃圾回收器，请参见文章JVM学习之垃圾回收和垃圾回收器

GC日志参数

在文章JVM学习笔记之运行时参数中提到了一些和GC相关的参数，这里摘录如下：

常用参数

-verbose:gc输出gc日志信息，默认到标准输出

-XX:+PrintGC表示打开简化的GC日志，和上面的指令等同

-XX:+PrintGCDetails在发生垃圾回收时打印详细的GC日志，并在进程退出时输出当前内存各区域的分配情况

-XX:+PrintGCTimeStamps输出GC发生的时间戳，需要和-XX:+PrintGCDetails配合使用

-XX:+PrintGCDateStamps输出GC发生的时间戳，以日期的格式，需要和-XX:+PrintGCDetails配合使用

-XX:+PrintHeapAtGC在每一次的GC前和后，都打印堆信息，可以和-XX:+PrintGCDetails、-XX:+PrintGCDateStamps、-XX:+PrintGCTimeStamps配合使用

-Xloggc:<file>把GC日志写入到一个文件中

其他参数

-XX:+TraceClassLoading监控类的加载

-XX:+PrintGCApplicationStoppedTime打印GC时线程停顿时间

-XX:+PrintGCApplicationConcurrentTime垃圾收集之前打印打印应用未中断的执行时间

-XX:+PrintReferenceGC记录回收了多少种不同类型的引用

-XX:+PrintTenuringDistribution每次MinorGC后打印出当前使用的幸存者区中对象的年龄分布

-XX:+UseGCLogFileRotation启用GC日志文件的自动转储

-XX:NumberOfGCLogFiles=1控制GC日志文件的循环数量

-XX:GCLogFileSize=1M控制GC日志文件大小为1m

GC日志格式

日志分类

Minor GC

示例日志如下：格式为[GC(GC原因) [年轻代: 回收前大小->回收后大小(年轻代总大小)] 回收前java堆大小->回收后java堆大小(java堆总大小), GC用时] [Times: MinorGC用户耗时, MinorGC系统耗时, MinorGC实际耗时]

[GC (Allocation Failure) [PSYoungGen: 15620K->2040K(18432K)] 15620K->13630K(59392K), 0.0033045 secs] [Times: user=0.08 sys=0.08, real=0.05 secs]

三个时间的说明：

user: 执行用户态代码的时间，也就是执行GC的CPU时间

sys: 在内核态消耗的时间，也就是在内核执行系统调用或者等待系统事件所使用的CPU时间

real: 程序从开始到结束用的时间，也就是GC的时间，等于(或接近于)(用户时间 + 系统时间) / GC线程数；如果real > user + sys，则说明可能IO负载过重或者CPU不够用

Full GC

示例日志如下，格式为[GC(GC原因) [年轻代: 回收前大小->回收后大小(年轻代总大小)] [老年代: 回收前大小->回收后大小(老年代总大小)] 回收前java堆大小->回收后java堆大小(java堆总大小), [元空间: 回收前大小->回收后大小(元空间总大小)] GC用时] [Times: MinorGC用户耗时, MinorGC系统耗时, MinorGC实际耗时]

[Full GC (Ergonomics) [PSYoungGen: 1730K->0K(18432K)] [ParOldGen: 38565K->40005K(40960K)] 40295K->40005K(59392K), [Metaspace: 3746K->3746K(1056768K)], 0.0115976 secs] [Times: user=0.14 sys=0.02, real=0.01 secs]

Minor GC日志解析

以这一行日志为例：

2021-02-05T19:40:48.862+0800: [GC (Allocation Failure) [PSYoungGen: 13922K->2035K(18432K)] 13922K->11752K(59392K), 0.0719394 secs] [Times: user=0.00 sys=0.00, real=0.07 secs]

2021-02-05T19:40:48.862+0800表示GC发生的时间，GC表示发生了GC(Minor GC)，Allocation Failure表示GC发生的原因——内存空间不够导致的分配失败，PSYoungGen表示年轻代发生的是并行GC，13922K->2035K(18432K)表示此区域GC前占13922K，GC后是2035K，总大小为18432K(伊甸园 + 一个幸存者区)，13922K->11752K(59392K)表示堆空间GC前大小为13922K，GC后为11752K，总大小为59392K(老年代 + 9 * 年轻代 / 10)，年轻代少了11887K，java堆只少了2170K，说明有相当一部分对象(9617K)到了老年代；0.0719394 secs表示此次GC用了0.0719394秒，user=0.00 sys=0.00, real=0.07 secs分别表示用户态时间0s，内核态0s，总时间0.07s

Full GC日志解析

以这一行日志为例：

2021-02-05T19:40:57.474+0800: [Full GC (Allocation Failure) [PSYoungGen: 14572K->14572K(18432K)] [ParOldGen: 40864K->40810K(40960K)] 55436K->55382K(59392K), [Metaspace: 3745K->3745K(1056768K)], 0.0112977 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]

2021-02-05T19:40:57.474+0800表示GC发生的时间，Full GC表示发生了Full GC，Allocation Failure表示GC发生的原因——内存空间不够导致的分配失败，以年轻代部分为例：PSYoungGen表示年轻代发生的是并行GC，14572K->14572K(18432K)表示此区域GC前占14572K，GC后也是14572K(这是OOM前最后一次GC，所以没有回收什么东西)，总大小为18432K(伊甸园 + 一个幸存者区)，55436K->55382K(59392K)表示堆空间GC前大小为55436K，GC后为55382K，总大小为59392K(老年代 + 9 * 年轻代 / 10)；0.0112977 secs表示此次GC用了0.0112977秒，user=0.16 sys=0.00, real=0.01 secs分别表示用户态时间0.16s，内核态0s，总时间0.01s