码迷,mamicode.com
首页 > 其他好文 > 详细

GC日志格式及分析、heapdump文件获取

时间:2015-02-10 23:01:53      阅读:928      评论:0      收藏:0      [点我收藏+]

标签:

==仅方便后续参考==

GC日志配置

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:servers/%SERVER_NAME%_gc.log -XX:+HeapDumpOnOutOfMemoryError
注意,%SERVER_NAME%是win格式,linux下为${SERVER_NAME}。

JVM的GC日志的主要参数包括如下几个:
-XX:+PrintGC 输出简单GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳(相对JVM启动时间的秒数)
-XX:+PrintGCDateStamps 输出GC的时间戳(以日期的形式,如 2013-05-04T21:53:59.234+0800)
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的输出路径

gcutil使用

$ jstat -gc 17970 2000 20 (每隔2秒监控一次,共20次)
$ jstat -gcutil 17970 1000 10 (按百分比显式)

手工触发 Java heap dump

1、命令:jmap -dump:format=b,file=a.hprof <pid>

file:保存路径及文件名
pid:进程编号
2、在应用启动时配置参数 -XX:+HeapDumpOnOutOfMemoryError,当应用抛出OutOfMemoryError时自动生成dump文件。

例子(转载)

-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:../logs/gc.log
输出的格式:
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]
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实际耗时)]

我们再对数据做一个简单的分析
7.429: [GC 7.429: [ParNew: 45278K->6723K(47808K), 0.0251993 secs] 46974K->10551K(252608K), 0.0252421 secs]
从这条GC记录中我们可以看到:
Young GC回收了 45278-6723 =38555K的内存
Heap区通过这次回收总共减少了 46974-10551=36423K的内存。
38555-36423=2132K说明通过该次Young GC有2132K的内存被移动到了Old Gen,

-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
我们来验证一下
在最后一次Young GC的回收以前 Old Gen的大小为8702-7006=1696
回收以后Old Gen的内存使用为10551-6723=3828
Old Gen在该次Young GC以后内存增加了3828-1696=2132K 与预计的相符

[root@localhost ~]# jstat -gcutil 3517 5000
S0 S1 E O P YGC YGCT FGC FGCT GCT
0.00 0.00 35.84 34.48 33.22 5 0.687 2 0.683 1.370
0.00 0.00 36.27 34.48 33.22 5 0.687 2 0.683 1.370
0.00 0.00 36.38 34.48 33.23 5 0.687 2 0.683 1.370
0.00 0.00 36.81 34.48 33.23 5 0.687 2 0.683 1.370
0.00 0.00 37.15 34.48 33.23 5 0.687 2 0.683 1.370
0.00 0.00 38.11 34.48 33.23 5 0.687 2 0.683 1.370
0.00 0.00 38.25 34.48 33.23 5 0.687 2 0.683 1.370

其中3517为进程号,5000表示每5000毫秒刷一次,如果要限制次数后面可以继续加数字 例如jstat -gcutil 3517 5000 10 表示刷10次
S0:年轻代中第一个survivor(幸存区)已使用的占当前容量百分比
S1:年轻代中第二个survivor(幸存区)已使用的占当前容量百分比
E:年轻代中Eden(伊甸园)已使用的占当前容量百分比
O:old代已使用的占当前容量百分比
P:perm代已使用的占当前容量百分比
YGC:从应用程序启动到采样时年轻代中gc次数
YGCT:从应用程序启动到采样时年轻代中gc所用时间(s)
FGC:从应用程序启动到采样时old代(全gc)gc次数
FGCT:从应用程序启动到采样时old代(全gc)gc所用时间(s)
GCT:从应用程序启动到采样时gc用的总时间(s)

GC日志格式及分析、heapdump文件获取

标签:

原文地址:http://www.cnblogs.com/forrestajun/p/gc.html

(0)
(0)
   
举报
评论 一句话评论(0
登录后才能评论!
© 2014 mamicode.com 版权所有  联系我们:gaon5@hotmail.com
迷上了代码!