用 HPjtune 分析 GC 日志(一个实际案例的诊断过程)

上次介绍了IBM的两款分析gc log的工具(GCMV和PMAT),这次讲讲HP推出的HPjmeter。HPjmeter集成了以前的HPjtune功能,可以分析在HP机器上产生的垃圾回收日志文件。你可以到Hewlett-Packard Java website免费下载最新的4.0版本,当然会让你填一些信息。

接下来我将分析一个实际生产环境下的日志文件,这个生产系统在启用新的功能后应用访问速度变慢,每个操作都要耗时10s左右,通过对比前后不同的gc信息,希望能从JVM的层面来优化当前的性能。

HP小机(Pa-Risc和安腾平台)使用HP的JDK后,使用-Xloggc:filename或者-Xverbosegc:file=filename参数会生成形如

<GCH: vmrelease=”1.4.2 1.4.2.10-060112-16:07-PA_RISC2.0 PA2.0 (aCC_AP)
……
<GCH: mode=n >
<GCH: ncpu=8 >
<GCH: availswap=33554432 >
<GCH: usedswap=0 >
……
<GC: 2 4  9.625554 1 0 31 48539536 0 286392320 0 0 35782656 0 2409608 715849728 20971424 20971424 20971520 0.279391 0.279391 >
<GC: 2 4  10.879321 2 0 31 9797920 0 286392320 0 0 35782656 2409608 2742416 715849728 25165568 25165568 25165824 0.307422 0.307422 >

的日志,这种格式人肉分析就别想了,它可以在PMAT中以Xverbosegc/hpux文件格式打开,但是图象功能我这里没法使用,只好求助于HP自家的工具——HPjmeter了。

分析过程

用HPjmeter加载日志文件后,会自动打开HPjtune的窗口。首先会看到Heap Usage After GC标签页,这是四月份正常的情况(请先忽略systemgc,这点留待后面分析)

 

April Heap Usage After GC

下面是六月份速度慢的情况:

June Heap Usage After GC

明显能看到Old full(with perm)代表的黄点增多了,从之前的日志文件头我们了解到这个系统所用的JDK为1.4.2 32位版本(64位版本会写明Java VM name = Java HotSpot(TM) 64-Bit Server VM),默认的回收策略是串行收集器,在Old区发生垃圾回收时是Stop the world的full gc,每次full gc耗时基本在10s~12s

Duration 6

切换到”Summary”标签页

GC Summary 4

4月花在gc上的时间占整个JVM运行时间的3.036%,Full GC占整个JVM运行时间的0.993%,应该说是情况良好。

到了6月份,情况却变化很大,时间分别为10.791%8.417%,因为超过了5%的警戒线而显示为红色,而且79%的GC时间花在full gc上。

GC Summary 6

这还是一周的情况,包括了周末和晚间空闲时刻,让我们看看在上班高峰期间的运行情况。

GC Summary 6-4

乖乖,有61%的时间花在gc上,速度不慢才怪了。我们查看当前对应的Heap Usage After GC

June 22 morning

除了开始的少数年轻代中发生的快速Scavenge,大部分都是慢速的Full GC,而且可以看到每次回收后使用的堆空间并没有减小,反而越来越大,有内存泄漏的征兆。不过堆空间并没有一路增长下去直到OutOfMemory,而是像下图般那样反复。

Jun22 Heap Usage After GC

早上和下午两个业务繁忙期全是full gc,性能表现很差,而4月正常的情况应是如此

April 23 Heap Usage After GC

Eden区满了后,经过Scavenge动作一部分对象被转移到了Old区,所以堆中占用空间上升,直到Old区也无法分配了,那么发生full gc,内存又重新回到一个较低的位置,这是正常的情况。现在6月份出现一直Full GC也无法回收,但又没有发生OutOfMemory,可以判断为原来设置的参数无法满足新内容投产后的需求

例如没有使用并行回收,没有发挥8个CPU的效果,没有采用低响应时间的CMS回收模式。

system details hpjtune

同时新系统产生的对象数量也大大增加,从四月一天的500000个增加到900000个(左边四月,右边六月)。

April Cumulative Allocation June Cumulative Allocation

导致每次回收后,从新生代转移到年老区的对象数量也变多,其实它们并非是长存对象,只是新生代暂时无法容纳下它们了。

April Promoted Bytes June Promoted Byte

而且full gc会导致Survivor区里的所有对象都被转移到old区,这造成了恶性循环。(黄色的Full GC后,Survivor里的对象为零)

June22 Survivor After

优化操作

调整目标:尽可能的将短时间存活的对象在年轻代就能被丢弃掉,而不要转移到年老代中;采用并行回收方式增加效率;避免产生不必要的Full GC;或者采用响应时间短的垃圾回收方式。

调整方法:增大年轻代大小,减小SurvivorRatio加大Survivor区(也就是From or To);设置并行回收参数;设置初始堆和最大堆为同样值、设置初始PermSize为一个合理值,避免运行过程中增长;设置回收策略为CMS。

参数设置一:-Xms1500m -Xmx1500m -Xmn800m -XX:SurvivorRatio=4 -XX:PermSize=160m  -XX:+UseParallelGC(-XX:ParallelGCThreads=8我觉得可以不用显示的声明,可以再上述参数设置后分析新的gc log,看一下System Details页面中ParallelGCThreads的数目再做定夺,1.4.2的JDK不能再Old区做并行回收,也是一个遗憾)

参数设置二:-Xms1500m -Xmx1500m -Xmn800m -XX:PermSize=160m  -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:CMSFullGCsBeforeCompaction=5(或者最后一个参数设置为-XX:+UseCMSCompactAtFullCollection)

上述参数的意义可以看《JAVA性能优化—Sun Hotspot JDK JVM参数设置》

后续进展

参数设置后还有一个观察过程,如果效果不佳,那从系统集成的角度,一是更换64位JDK,这样可以设置更大的堆空间(不过WebSphere更换JDK不像Weblogic那么简单,如果没有买过64位WebSphere的话只好作罢);二是启用WebSphere的集群,但这需要ND版本的WAS。

从应用的角度,可以在早上8点做一次heapdump,9点半做一次heapdump,分析一下full gc内存回收不下来的原因,确定不是程序的错误造成的。或者启用-agentlib:hprof参数,用HPjmeter来trace应用的表现、用HPjmeter来直接监控应用的运行情况。不过这两个方法对性能影响较大,要在测试环境下进行。

其它的一些碎碎念

现在我们来说说日志中那么多的systemgc,刚开始看到我大吃一惊,但放大图像后发现这些自行调用的full gc都是下班后做的,应该是另一个应用触发的,对白天的性能影响应该不大。

不过这里还是要再申明一句:自行调用System.gc()函数会损害到JVM的性能,因为这时候是Stop the World的回收,消耗的时间长,但效果并非最佳。你也许会认为你对程序很熟悉,可以在空闲的时间执行system.gc,不会影响到客户访问,但是正如之前所说,full gc后survivor里的所有内容都被转移到了old区长久保存,所以在某个将来,JVM就不得不因为这个原因再做一次不必要的full gc。

IBM JDK下避免主动回收的参数是“-Xdisableexplicitgc”,Sun JDK下的参数是“-XX:+DisableExplicitGC”,注意区别。

 

 

备注:

本文转载自:http://www.hashei.me/2009/07/use-hpjtune-to-analysis-gc-log.html

展开阅读全文

没有更多推荐了,返回首页