本文针对的是 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 在服务器上已被启用:
- 从 IBM WebSphere Application Server 管理控制台,导航到 Application Servers - WebSphere_Portal - Java and Process Management - Process Definition - Java Virtual Machine。
- 确保选中 Verbose garbage collection 旁的复选框,然后重启此服务器。
- 现在,应该可以看到类似于如下的条目被写入到 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。
接下来的一行是: