用 verbose GC 分析内存问题

    本文针对的是 WebSphere Portal 版本 6.0 或更高版本（和 5.1 或更高版本），其上运行的是 Java™ Software Development Kit (SDK) 1.4.2。为了获得最佳调优，建议使用 SDK 的最新服务发布，对于这里所讨论的调优，至少使用一个新于 SR13 的服务发布。

垃圾收集可简单定义为 JavaTM Virtual Machine (JVM) 释放不再被进程引用或使用的对象的 heap 的行为，heap 是指内存中的一个预先定义的部分，可用来管理 Java 应用程序内的资源。

这个过程有三个主要阶段：mark、sweep 和 compact：

• 在 mark 阶段，heap 内的所有对象均以一个 bit “标记”。然后检查这些对象看它们是否仍被引用，如果如此，这个 bit 即被删除。
• 在 sweep 阶段，JVM 遍历整个 heap 并删除仍具有标记 bit 的所有对象；这些对象不再被引用或使用。
• compact 阶段只在一个完整的 GC 中才会运行，在这个阶段，GC 会试图将 heap 内的所有对象重新分配到 heap 内的一个更为紧缩、更为连续的较小空间。

---

监视 heap 使用情况的最好的方法是分析这个 verbose GC 的输出。

首先要确保该 verbose GC 在服务器上已被启用：

1. 从 IBM WebSphere Application Server 管理控制台，导航到 Application Servers - WebSphere_Portal - Java and Process Management - Process Definition - Java Virtual Machine。
2. 确保选中 Verbose garbage collection 旁的复选框，然后重启此服务器。
3. 现在，应该可以看到类似于如下的条目被写入到 native_stderr.log 文件：
   <AF[177]: Allocation Failure. need 528 bytes, 3602594 ms since last AF>
<AF[177]: managing allocation failure, action=1 (0/585421800) (29966688/30811672)>
<GC(177): GC cycle started Fri Sep 21 23:48:29 2007
<GC(177): freed 218620376 bytes, 40% free (248587064/616233472), in 459 ms>
<GC(177): mark: 422 ms, sweep: 37 ms, compact: 0 ms>
<GC(177): refs: soft 0 (age >= 32), weak 11, final 7424, phantom 0>
<AF[177]: completed in 460 ms>


现在，让我们将之前的日志条目细分成几个部分并分别加以分析。

首先是：

<AF[177]: Allocation Failure. need 528 bytes, 3602594 ms since last AF>

通过这个条目，我们能够知道有一个分配失败，当 heap 内没有足够的连续空间可以分配给对象时，就会发生分配失败。对象是 verbose GC 输出中最为常见的。在本例中，它是一个 528 字节的小对象。

从此行可以看出，自我们上次运行了一个 GC 循环后已经过去了一段时间，3602594 ms。

接下来，我们研究最后一行：

<AF[177]: completed in 460 ms>

此行告诉我们在 GC 上花费的时间的数量。使用这个数字，我们就能够获得我们最近一次用在 GC 内的比率并找出我们花在 GC 和非实际工作上的时间比例；比如：

460/3602594 = .000127% of the time was spent in GC

在一个健康的服务器内，花在 GC 内的时间应该少于 13%，理想的是 7-10% 左右。

回到第二行：

<AF[177]: managing allocation failure, action=1 (0/585421800) (29966688/30811672)>

首先注意到的一点是 “action=”。对于一个分配失败，有七种不同的动作可以发生：

• action=0 表示 pinnedFreeList 已用尽。
• action=1 表示进行的是一个抢占式的垃圾收集循环。
• action=2 表示一个完全的分配失败。
• action=3 表示发生了一个 heap 拓展。
• action=4 表示所有已知的软引用均已清除。
• action=5 表示对临时 heap 进行了临时偷用。
• action=6 表示空闲空间非常低。

这些动作的顺序代表了严重程度的等级；最严重的情况是服务器的内存完全用完（action=6）。

在本例中，我们用的是 action=1。在这类 GC 内，只运行 GC 的 mark 和 sweep 阶段。

此行还包括了：

(0/585421800) (29966688/30811672)

此行特定于 AIX® JVM。正如您看到的，这里有两个基础数字，如果二者加起来，就表示 heap 被扩展到的大小。其中一个较小，会被自动用于大型对象的分配。

注意：大型对象指的是大于 64 K 的对象。

所有其他对象均被放在 heap 的其他部分。如果大型对象部分已满且有另一个大型对象请求分配，那么这个对象就被放在 heap 的另一个主要部分上。这个对象可以是其他多平台 JVM 内的一个有用的调优参数，称为 -Xloratio。

下一行是：

<GC(177): GC cycle started Fri Sep 21 23:48:29 2007

此行报告了 GC 循环开始的时间以及我们所处的是哪个循环，即 GC(177)。这是自 JVM 开启以来运行的第 177 个 GC。

随后的一行：

<GC(177): freed 218620376 bytes, 40% free (248587064/616233472), in 459 ms>

表明在此 GC 循环期间，有多少字节被释放，在本例中，JVM 能够释放 218620376 字节。

并且，我们还能看出这个 heap 现在有 40% 是空闲的，即在这个 heap 总共 616,233,472 字节中有 248,587,064 字节是空闲的：

(248587064/616233472)

最后，这个 GC 循环的完成花了 459 ms。

这一行非常有用，因为它告诉我们这个 heap 有多少是空闲的，而且有一些对象正在被清理且不会占用这个 heap。

接下来的一行是：