GC日志

Posted ken-jl

tags:

篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了GC日志相关的知识,希望对你有一定的参考价值。

阅读GC日志是处理Java虚拟机内存问题的基础技能,它只是一些人为确定的规则,没有太多技术含量。因此增加本节内容来讲解如何理解GC日志。

每一种收集器的日志形式都是由它们自身的实现所决定的,换而言之,每个收集器的日志格式都可以不一样。但虚拟机设计者为了方便用户阅读,将各个收集器的日志都维持一定的共性,例如以下两段典型的GC日志分析。

日志分析实例一

33.125: [GC [DefNew: 3324K->152K(3712K), 0.0025925 secs] 3324K->152K(11904K), 0.0031680 secs]  

100.667: [Full GC [Tenured: 0K->210K(10240K), 0.0149142 secs] 4603K->210K(19456K), [Perm : 2999K->2999K(21248K)], 0.0150007 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]  

最前面的数字“33.125:”和“100.667:”代表了GC发生的时间,这个数字的含义是从Java虚拟机启动以来经过的秒数。

GC日志开头的“[GC”和“[Full GC”说明了这次垃圾收集的停顿类型,而不是用来区分新生代GC还是老年代GC的。如果有“Full”,说明这次GC是发生了Stop-The-World的,例如下面这段新生代收集器ParNew的日志也会出现“[Full GC”(这一般是因为出现了分配担保失败之类的问题,所以才导致STW)。如果是调用System.gc()方法所触发的收集,那么在这里将显示“[Full GC (System)”。

[Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000288 secs] 

接下来的“[DefNew”、“[Tenured”、“[Perm”表示GC发生的区域,这里显示的区域名称与使用的GC收集器是密切相关的,例如上面样例所使用的Serial收集器中的新生代名为“Default New Generation”,所以显示的是“[DefNew”。如果是ParNew收集器,新生代名称就会变为“[ParNew”,意为“Parallel New Generation”。如果采用Parallel Scavenge收集器,那它配套的新生代称为“PSYoungGen”,老年代和永久代同理,名称也是由收集器决定的。

后面方括号内部的“3324K->152K(3712K)”含义是“GC前该内存区域已使用容量-> GC后该内存区域已使用容量 (该内存区域总容量)”。而在方括号之外的“3324K->152K(11904K)”表示“GC前Java堆已使用容量 -> GC后Java堆已使用容量 (Java堆总容量)”。

再往后,“0.0025925 secs”表示该内存区域GC所占用的时间,单位是秒。有的收集器会给出更具体的时间数据,如“[Times: user=0.01 sys=0.00, real=0.02 secs]”,这里面的user、sys和real与Linux的time命令所输出的时间含义一致,分别代表用户态消耗的CPU时间、内核态消耗的CPU事件和操作从开始到结束所经过的墙钟时间(Wall Clock Time)。CPU时间与墙钟时间的区别是,墙钟时间包括各种非运算的等待耗时,例如等待磁盘I/O、等待线程阻塞,而CPU时间不包括这些耗时,但当系统有多CPU或者多核的话,多线程操作会叠加这些CPU时间,所以读者看到user或sys时间超过real时间是完全正常的。

日志分析实例二

JVM的GC日志的主要参数包括如下几个:

-XX:+PrintGC 输出GC日志

-XX:+PrintGCDetails 输出GC的详细日志

-XX:+PrintGCTimeStamps 输出GC的时间戳(以基准时间的形式)

-XX:+PrintGCDateStamps 输出GC的时间戳(以日期的形式,如 2013-05-04T21:53:59.234+0800)

-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息

-Xloggc:../logs/gc.log 日志文件的输出路径

做了如下的设置

-XX:+PrintGCDetails -Xloggc:../logs/gc.log -XX:+PrintGCTimeStamps  

 

以后打印出来的日志为:

0.756: [Full GC (System) 0.756: [CMS: 0K->1696K(204800K), 0.0347096 secs] 11488K->1696K(252608K), [CMS Perm : 10328K->10320K(131072K)], 0.0347949 secs] [Times: user=0.06 sys=0.00, real=0.05 secs]  

1.728: [GC 1.728: [ParNew: 38272K->2323K(47808K), 0.0092276 secs] 39968K->4019K(252608K), 0.0093169 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]  

2.642: [GC 2.643: [ParNew: 40595K->3685K(47808K), 0.0075343 secs] 42291K->5381K(252608K), 0.0075972 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  

4.349: [GC 4.349: [ParNew: 41957K->5024K(47808K), 0.0106558 secs] 43653K->6720K(252608K), 0.0107390 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  

5.617: [GC 5.617: [ParNew: 43296K->7006K(47808K), 0.0136826 secs] 44992K->8702K(252608K), 0.0137904 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  

7.429: [GC 7.429: [ParNew: 45278K->6723K(47808K), 0.0251993 secs] 46974K->10551K(252608K), 0.0252421 secs]  

我们取倒数第二条记录分析一下各个字段都代表了什么含义

5.617(时间戳): [GC(Young GC) 5.617(时间戳): [ParNew(使用ParNew作为年轻代的垃圾回收期): 43296K(年轻代垃圾回收前的大小)->7006K(年轻代垃圾回收以后的大小)(47808K)(年轻代的总大小), 0.0136826 secs(回收时间)] 44992K(堆区垃圾回收前的大小)->8702K(堆区垃圾回收后的大小)(252608K)(堆区总大小), 0.0137904 secs(回收时间)] [Times: user=0.03(Young GC用户耗时) sys=0.00(Young GC系统耗时), real=0.02 secs(Young GC实际耗时)] 

我们再对数据做一个简单的分析

从最后一条GC记录中我们可以看到 Young GC回收了 45278-6723=38555K的内存

Heap区通过这次回收总共减少了 46974-10551=36423K的内存。

38555-36423=2132K说明通过该次Young GC有2132K的内存被移动到了Old Gen,

 

我们来验证一下

在最后一次Young GC的回收以前 Old Gen的大小为8702-7006=1696

回收以后Old Gen的内存使用为10551-6723=3828

Old Gen在该次Young GC以后内存增加了3828-1696=2132K 与预计的相符

 

以上是关于GC日志的主要内容,如果未能解决你的问题,请参考以下文章

GC之七--gc日志分析工具

java gc的日志在哪里看?

GC日志查看和分析

GC日志

JVM实用参数8:GC日志

GC日志