WebSphere troubshooting - 用工具分析 GC Log

要进行gc performance tuning，不得不对gc log进行分析。之前说到了“人肉”的方法，总觉得不够形象，无法让不了解的开发人员抑或是技术负责人有个直观的了解，所以本文介绍几个分析GC log的工具。

首先需要下载IBM Support Assistant，下载之后就可以从Update-Tools add on中下载我们需要的工具了，ISA使用方法。ISA把所有的工具集成在一个界面内，省去了设置启动参数的麻烦，同时能保持最及时的更新。分析垃圾回收日志，我主要用“The IBM Monitoring and Diagnostic Tools for Java™ – Garbage Collection and Memory Visualizer”和“IBM Pattern Modeling and Analysis Tool for Java Garbage Collector (PMAT)”这两个工具。我会用实际例子来说明如何使用这个工具。

用Garbage Collection and Memory Visualizer载入native_stderr.log，首先你会看到

点击展开大图

这是一个500分钟的垃圾回收曲线图，可以观察到一天以内的大致情况。总的来说，蓝色的Used heap（after collection）运行在“平行通道”内，没有走“上升通道”（炒股的朋友应该知道上升通道的图形是咋样的）。所以在Report这个标签内，可以看到“The memory usage of the application does not indicate any obvious leaks.”。

Report中的Summary是需要关注的，它向我们显示了GC发生的次数，所用的policy（optthruput），平均停顿时间248ms，平均间隔时间3.37分钟，还有垃圾回收的速率（垃圾产生多并非不好，反而是吞吐率高的一种表现）。

让我们再切回Line plot视图，现在可以框选某一个时间段进行放大，同时在右边Axes中选择X轴的坐标系，默认的是相对时间，以分钟为单位，适用于你的应用程序总在启动N个小时后出现问题。如果是每天固定时间发生性能问题，那么应该选用绝对时间。

默认的曲线开启了Heap size和Used heap（after collection），你可以根据需要，在VGC Pause Date和VGC Date、VGC Heap Data中勾选你需要查看的曲线。比如你觉得程序响应时间很长，那么可以勾选上Intervals between garbage collection triggers和Pause time，看看上一条曲线是否和下面一条靠的“太近”。

 

 

通过在Tabbed data查看表格模式的回收信息（同样可以勾选上节提到的内容来增加列），我们看到GC reason都是af。通过查看Free heap before collection，我们发觉有些af发生的时候，堆中剩余空间其实还很多

我覆盖上Compact times曲线，发现十分吻合，原来这时候是堆中的碎片太多，所以导致即使剩余空间很大，但是没有连续空间分配给新的请求，这时候就发生了压缩（Compact）。加了Unuseable heap due to fragmentatiion的第二副图可以更明显的看到这一点。进一步的，可以根据第一列的collection id去查看引起压缩的requested_bytes，是否是需要比较大的空间（比如大于64K），然后结合一下所有requested_bytes中大对象的数量，确定是否需要调整LOA大小。

你会发现还有些曲线是灰色不能选择状态，那是因为根据我现在的gc policy，关于gencon模式下的nursery和tenured曲线在这个模式下是没有的。

总的来说，运用不同的曲线组合，合适的缩放比例，不同的日志显示方法对照，我们可以验证gc是否符合我之前说过的一些“最优原则”——回收的间隔是否大大大于持续时间，整个回收时间是否在整个运行时间的5%以下，压缩的次数是否仅占一小部分（太多的话要考虑设置-Xk -Xp和调整LOA）……Report标签中的Tuning recommendation是你需要参考的内容，但不要一上来就根据它的提示去优化。

下一个例子就是一个有问题的垃圾回收日志。

整个垃圾回收曲线，当中有一个Excessive GC引发的OutOfMemory

The concurrent collector will throw an OutOfMemoryError if too much time is being spent in garbage collection: if more than 98% of the total time is spent in garbage collection and less than 2% of the heap is recovered, an OutOfMemoryError will be thrown. This feature is designed to prevent applications from running for an extended period of time while making little or no progress because the heap is too small.

放大出问题的地方的曲线

根据ID查看原始文件

<af type=”tenured” id=”1030″ timestamp=”Tue Nov 04 14:57:26 2008″ intervalms=”11.440″>
<minimum requested_bytes=”216″ />
<time exclusiveaccessms=”0.322″ />
<tenured freebytes=”0″ totalbytes=”1342177280″ percent=”0″ >
<soa freebytes=”0″ totalbytes=”1342177280″ percent=”0″ />
<loa freebytes=”0″ totalbytes=”0″ percent=”0″ />
</tenured>
<gc type=”global” id=”1031″ totalid=”1031″ intervalms=”11.837″>
<compaction movecount=”3301258″ movebytes=”196674784″ reason=”low free space (less than 4%)” />
<refs_cleared soft=”0″ weak=”15″ phantom=”7″ />
<finalization objectsqueued=”40″ />
<timesms mark=”1753.108″ sweep=”10.302″ compact=”1858.390″ total=”3622.032″ />
<tenured freebytes=”519040″ totalbytes=”1342177280″ percent=”0″ >
<soa freebytes=”519040″ totalbytes=”1342177280″ percent=”0″ />
<loa freebytes=”0″ totalbytes=”0″ percent=”0″ />
</tenured>
</gc>
<warning details=”excessive gc activity detected” />
<tenured freebytes=”518352″ totalbytes=”1342177280″ percent=”0″ >
<soa freebytes=”518352″ totalbytes=”1342177280″ percent=”0″ />
<loa freebytes=”0″ totalbytes=”0″ percent=”0″ />
</tenured>
<time totalms=”3623.033″ />
</af>

<af type=”tenured” id=”1031″ timestamp=”Tue Nov 04 14:57:30 2008″ intervalms=”3.715″>
<minimum requested_bytes=”120″ />
<time exclusiveaccessms=”0.232″ />
<tenured freebytes=”0″ totalbytes=”1342177280″ percent=”0″ >
<soa freebytes=”0″ totalbytes=”1342177280″ percent=”0″ />
<loa freebytes=”0″ totalbytes=”0″ percent=”0″ />
</tenured>
<gc type=”global” id=”1032″ totalid=”1032″ intervalms=”4.385″>
<compaction movecount=”3170275″ movebytes=”192337800″ reason=”compact to aid heap contraction” />
<contraction type=”tenured” amount=”67108352″ newsize=”1275068928″ timetaken=”0.001″ reason=”excess free space following gc” />
<refs_cleared soft=”0″ weak=”0″ phantom=”0″ />
<finalization objectsqueued=”9″ />
<timesms mark=”245.373″ sweep=”12.272″ compact=”482.748″ total=”745.486″ />
<tenured freebytes=”1022923992″ totalbytes=”1275068928″ percent=”80″ >
<soa freebytes=”1022923992″ totalbytes=”1275068928″ percent=”80″ />
<loa freebytes=”0″ totalbytes=”0″ percent=”0″ />
</tenured>
</gc>

考虑到垃圾回收频率也较高，每次请求的空间都不大，所以我讲垃圾回收模式改为了gencon，之后没有OutOfMemory发生。不过我那份回收日志没有留下来，否则应该在文件Compare file中导入修改后生成的日志，进行比较，确定修改的结果。

注意事项：对于IBM JDK，直接勾选“详细垃圾回收”即可，但是对于HP 或者Sun JDK，最好使用-Xverbosegclog:file_name（生成能解析的XML格式）来指定一下，否则默认文件中会包含其它信息，工具讲无法以图像显示，还要自己修改文件，比较麻烦的。

IBM Pattern Modeling and Analysis Tool for Java Garbage Collector (PMAT)这个工具大同小异，个人使用它只是觉得提供的优化建议可以和上述工具互补，比如它会计算一个适合的-Xk -Xp值出来。

对于HP-UX上生成的垃圾回收日志，我们还可以用HPjmeter下的HPjtune来分析。

 

 

备注：

本文转载自：http://www.hashei.me/2009/06/gc-performance-tuning-with-isa.html