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

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，这点留待后面分析）

 

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

明显能看到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

切换到”Summary”标签页

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

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

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

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

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

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

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

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

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

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

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

优化操作

调整目标 ：尽可能的将短时间存活的对象在年轻代就能被丢弃掉，而不要转移到年老代中；采用并行回收方式增加效率；避免产生不必要的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