如何阅读GC日志分析GC日志

最新推荐文章于 2023-01-04 14:08:36 发布

weixin_34355559

最新推荐文章于 2023-01-04 14:08:36 发布

阅读量116

点赞数

原文链接：https://my.oschina.net/mindfind/blog/877200

版权

2019独角兽企业重金招聘Python工程师标准>>>

查看服务GC日志是处理Java虚拟机内存问题的必备基础技能．

当把-XX:-PrintGCDetails加入到javaopt里以后可以看见如下输出：

[GC[DefNew:34538K->2311K(36352K),0.0232439secs]45898K->15874K(520320K),0.0233874secs]
[FullGC[Tenured:13563K->15402K(483968K),0.2368177secs]21163K->15402K(520320K),[Perm:28671K->28635K(28672K)],0.2371537secs]

他们分别显示了JVM GC的过程，清理出了多少空间。第一行GC使用的是‘普通GC’(MinorCollections)，第二行使用的是‘全GC’(MajorCollections)。他们的区别很大，在第一行最后我们可以看见他的时间是0.0233874秒，而第二行的FullGC的时间是0.2371537秒。第二行的时间是第一行的接近10倍，也就是我们这次调优的重点，减少FullGC的次数，以为FullGC会暂停程序比较长的时间，如果FullGC的次数比较多。程序就会经常性的假死。

注：

GC信息的格式

[GC [<collector>: <starting occupancy1> -> <ending occupancy1>, <pause time1> secs] <starting occupancy3> -> <ending occupancy3>, <pause time3> secs]
<collector> GC为minor收集过程中使用的垃圾收集器起的内部名称.
<starting occupancy1> young generation 在进行垃圾收集前被对象使用的存储空间.
<ending occupancy1> young generation 在进行垃圾收集后被对象使用的存储空间
<pause time1> minor收集使应用暂停的时间长短(秒)
<starting occupancy3> 整个堆(Heap Size)在进行垃圾收集前被对象使用的存储空间
<ending occupancy3> 整个堆(Heap Size)在进行垃圾收集后被对象使用的存储空间
<pause time3> 整个垃圾收集使应用暂停的时间长短(秒),包括major收集使应用暂停的时间(如果发生了major收集).

GC信息的选项
-XX:+PrintGCDetails 显示GC的详细信息
-XX:+PrintGCApplicationConcurrentTime 打印应用执行的时间
-XX:+PrintGCApplicationStoppedTime 打印应用被暂停的时间

GC日志分析示例：

下面是具体一段gc日志，以此为例：

2017-04-11T20:24:08.009+0800: 104422.026: [GC 104422.026: [ParNew: 221707K->6752K(235968K), 0.0177330 secs] 441448K->226493K(2070976K), 0.0178660 secs] [Times: user=0.08 sys=0.00, real=0.02 secs] 
2017-04-11T20:24:15.441+0800: 104429.457: [Full GC (System) 104429.457: [CMS: 219741K->215266K(1835008K), 0.5469450 secs] 244623K->215266K(2070976K), [CMS Perm : 128846K->128831K(262144K)], 0.5470720 secs] [Times: user=0.54 sys=0.00, real=0.55 secs]

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

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

2017-04-11T20:24:08.009+0800: 104422.026: [GC 104422.026: [ParNew: 221707K->6752K(235968K), 0.0177330 secs] 441448K->226493K(2070976K), 0.0178660 secs] [Times: user=0.08 sys=0.00, real=0.02 secs]

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

后面方括号内部的“221707K->6752K(235968K)”含义是“GC前该内存区域已使用容量-> GC后该内存区域已使用容量 (该内存区域总容量)”。而在方括号之外的“441448K->226493K(2070976K)”表示“GC前Java堆已使用容量 -> GC后Java堆已使用容量 (Java堆总容量)”。

ParNew后面的“0.0177330 secs”表示该内存区域GC所占用的时间，单位是秒。

有的收集器会给出更具体的时间数据，如“［Times: user=0.08 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时间是完全正常的。

借阅：

http://blog.csdn.net/kobejayandy/article/details/8496663

转载于:https://my.oschina.net/mindfind/blog/877200