偶看新闻苹果手机如何护眼模式:用HPjtune分析GC日志（一个实际案例的诊断过程）
来源：百度文库 编辑：偶看新闻 时间：2024/04/29 10:01:40
用HPjtune分析GC日志（一个实际案例的诊断过程）
2009年7月2日hashei发表评论阅读评论上次介绍了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参数会生成形如
……
的日志，这种格式人肉分析就别想了，它可以在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”，注意区别。
分类:Websphere系列, 性能优化, 排错标签:gc performance tuning, gc日志分析, 内存优化