用 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 在服务器上已被启用：

从 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。

接下来的一行是：

<GC(177): mark: 422 ms, sweep: 37 ms, compact: 0 ms>

这一行对于我们稍候为了使 GC 运行得更快而进行的 GC 配置调优非常有用（参见 -Xgcpolicy:optavgpause），但现在，我们只需知道：

这一行显示了每个循环运行的时长。mark 阶段 422 ms，sweep 阶段 37 ms，compact 阶段 0 ms。

此外，通过如下两点，我们可以知道这不是一个完整的 GC：

compact 阶段的完成花了 0 ms。
action=1 表明这是在完整 GC 运行之前的一个抢占式的 GC。

最后要研究的一行是：

<GC(177): refs: soft 0 (age >= 32), weak 11, final 7424, phantom 0>

我们必须首先理解这个 GC 不仅管理对象，而且还会维护对实际对象的一个单独的引用对象。这些引用与创建时的四个查询中的一个相关，并且这种相关性在日后不能更改。这四个查询在 mark 阶段按如下顺序标记：

Soft
Weak
Final
Phantom

Soft 和 weak 引用在引用不复存在时可被清除。如果一个 finalizer（Final 查询）与一个 soft 或 weak 引用相关，那么只有当这个 soft 或 weak 引用删除后，这个 finalizer 才会在所运行的下一个 GC pass 上被删除。

以上所述就是在 Java SDK 1.4.2 上的默认 GC 策略内能看到的一些主要行。有了这些基础，让我们接下来探索 JVM 是如何工作的。

JVM 的开始部分一般是一些用来启动进程的可选命令行参数。这些参数是添加到 WebSphere Application Server 管理控制台内的原生 JVM 参数。

如下是一个基本命令，它会在 Java 进程开始时执行：

Java –Xmx1024M –Xms256M –Xverbosegc programToRun

其中的命令行参数

–Xmx1024M –Xms256M –Xverbosegc

表明启动时如下事情会发生：

heap 最大为 1024 M (–Xmx1024M)
heap 最小为 256 M (–Xms256M)
使用了 Verbose GC (–Xverbosegc)

有一点非常重要，那就是即便我们为 JVM 分配了 1024 M，正如我们在上述的 verbose GC 片段内所做的那样，但这并不意味着我们一定会使用或我们永远不会使用这全部的 1024 M。例如，在这个 verbose 片段，我们只使用了 616,233,472 字节。

JVM 先是被分配最少的 256 M 并将该空间付诸使用。如图 1 所示，整个 heap 的 1024 M 被放置起来备用（整个条），只有最初的 256 M 被分配使用，如图中阴影区域所示。

图 1. heap 的示意图

由于只有 256 M 可用，因此 JVM 会先用运行程序 programToRun 所需的这些对象填充这最初的 256 M。这些对象会被逐渐添加到这个空间，直到没有足够的连续空间能满足将下一个对象放在 heap 上的要求（参见图 2）。

图 2. 加载了不同大小的对象后的 Heap

这时，下一个对象开始请求这个 heap 上的空间，但已经没有足够的连续空间能够满足这一请求（参见图 3）。

图 3. 请求对象的示意图

这个请求发生时，JVM 以 action=1 运行一个 GC，示意图会发生变化，如图 4 所示。

图 4. JVM 以 action=1 运行 GC （请注意未用对象已被删除）

成为：

因此，此时该请求可被满足：

有时，对象可能无法被移动或清除；这些对象一般是类对象和仍在使用的对象。假设，这时有两个与之前的那个请求类似的请求进来，但是 heap 上却再没有对象可被删除（参见图 5）。

图 5. 使用中的 heap 的当前表示

在本例中，这个 GC 会运行一个 action=2，以试图运行一个 compaction 阶段。在 compaction 阶段，heap 上的对象会被整合以便将所有空闲空间收集起来满足当前的请求。

heap 的示意图这时应该类似图 6。

图 6. 紧缩了的 heap

这时，下一个请求就可以被处理了（参见图 7）。

图 7. heap 的进展

了解了 GC 动作 1 和 2 之后，我们现在可以来看看即便运行了动作 1 和 2 后仍没有足够空间可以分配给下一个对象时，该如何做。

如果我们继续处理我们的 heap 时，就会发生这种空间缺乏的情况，因为我们已经假设并非所有对象都能被清除（参见图 8）。

图 8. 紧缩了的 heap 且分配空间已满

可以看出，我们所使用的这个 heap 的可用空间已满。在我们的例子中，我们的这个 heap 的 256 M 已满，因为我们只为 heap 分配了 256 M 作为可用空间。请务必记住我们的 heap 的最大可达 1024 M，所以如果发生了这种情况，我们还有更多的空间可用。

在本例中，JVM 执行了一个 action=3 并将这个 heap 扩展了 65,535 字节以便提供更多的 heap 供我们使用（参见图 9），在 verbose GC 中可以看到这种情况。

图 9. 扩展了 65536 字节的系统 heap

成为这个：

现在，处理可以继续。GC 循环会继续，直到所有新分配的 heap 均经历上述相同的动作后，再分配更多的 heap，直到最后全部 1024 M 分配完毕。

从这种方法，我们可以看出，从一个较小的初始 heap 开始，再不断增加 heap 会使 heap 保持紧密和相对健康。

如下所示是来自完整 GC 的一个 verbose GC 的例子，后跟一个 heap 扩展：

<AF[12]: Allocation Failure. need 8208 bytes, 2272 ms since last AF>
<AF[12]: managing allocation failure, action=2 (3255768/52427264)>
  <GC(12): GC cycle started Wed Dec  2 13:55:07 2009
  <GC(12): freed 9836696 bytes, 24% free (13092464/52427264), in 59 ms>
  <GC(12): mark: 50 ms, sweep: 8 ms, compact: 1 ms>
  <GC(12): refs: soft 0 (age >= 32), weak 0, final 102, phantom 0>
<AF[12]: managing allocation failure, action=3 (13092464/52427264)>
  <GC(12): need to expand mark bits for 61602304-byte heap>
  <GC(12): expanded mark bits by 143360 to 962560 bytes>
  <GC(12): need to expand alloc bits for 61602304-byte heap>
  <GC(12): expanded alloc bits by 143360 to 962560 bytes>
  <GC(12): need to expand FR bits for 61602304-byte heap>
  <GC(12): expanded FR bits by 286720 to 1925120 bytes>
  <GC(12): expanded heap by 9175040 to 61602304 bytes, 36% free>
<AF[12]: completed in 75 ms>

理解了 heap 如何增长以及如何为 JVM 所用之后，现在您就能更好地理解进程运行时有多少内存被 JVM 实际使用。

对于一个进程或 portal 在运行时使用多少内存，存在着一些误解。通常，portal 的用户通过 ps avg 命令或 Microsoft® Windows® Task Manager（它显示了系统分配给 Java 进程的内存数量）来决定 Java 进程使用了多少内存。

如您所见，分配给进程 X 数量内存，并不意味着有进程实际使用了这么多数量的内存。

如果 Task Manager 或 “ps avg” 显示 Java 进程使用了 616 M 内存，但如果我们查看这个 verbose GC，就会看到它当前只使用了该数量的 40%：

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

如果在 heap 内仍有空闲内存的情况下收到一个 OUTOFMEMORY 错误，可以通过查看此 verbose GC 来判断是何原因。如下所示的是来自 verbose GC 内的一个内存不足错误的示例输出:

<AF[2474]: Allocation Failure. need 16777232 bytes, 114 ms since lastAF>
<AF[2474]: managing allocation failure, action=2(1026078032/1601894912)>
  <GC(2835): GC cycle started Thu Jul 16 11:21:34 2009
  <GC(2835): freed 5827392 bytes, 64% free (1031905424/1601894912), in 2519 ms>
  <GC(2835): mark: 567 ms, sweep: 24 ms, compact: 1928 ms>
  <GC(2835): refs: soft 0 (age >= 32), weak 0, final 6, phantom 0>
  <GC(2835): moved 1711341 objects, 87482984 bytes, reason=1, used 8 more bytes>
<AF[2474]: managing allocation failure, action=3 (1031905424/1601894912)>
  <GC(2835): need to expand mark bits for 1610611200-byte heap>
  <GC(2835): expanded mark bits by 135168 to 25165824 bytes>
  <GC(2835): need to expand alloc bits for 1610611200-byte heap>
  <GC(2835): expanded alloc bits by 135168 to 25165824 bytes>
  <GC(2835): need to expand FR bits for 1610611200-byte heap>
  <GC(2835): expanded FR bits by 270336 to 50331648 bytes>
  <GC(2835): expanded heap fully by 8716288 to 1610611200 bytes, 64% free>
<AF[2474]: managing allocation failure, action=4 (1040621712/1610611200)>
<AF[2474]: clearing all remaining soft refs>
  <GC(2836): GC cycle started Thu Jul 16 11:21:35 2009
  <GC(2836): freed 227346312 bytes, 78% free (1267968024/1610611200), in 1600 ms>
  <GC(2836): mark: 370 ms, sweep: 19 ms, compact: 1211 ms>
  <GC(2836): refs: soft 438 (age >= 32), weak 1178, final 70, phantom 0>
  <GC(2836): moved 1359393 objects, 60973368 bytes, reason=1, used 600 more bytes>
<AF[2474]: managing allocation failure, action=6 (1267968024/1610611200)>
JVMDG217: Dump Handler is Processing OutOfMemory - Please Wait.
JVMDG315: JVM Requesting Heap dump file
JVMDG318: Heap dump file written to
/opt/WebSphere/AppServer/heapdump.20090716.112135.19377.phd
JVMDG303: JVM Requesting Java core file
JVMDG304: Java core file written to
/opt/WebSphere/AppServer/javacore.20090716.112144.19377.txt
JVMDG274: Dump Handler has Processed OutOfMemory.
<AF[2474]: Insufficient space in Javaheap to satisfy allocation request>
<AF[2474]: completed in 19738 ms>

如您所见，在这个实例中有足够的空闲内存：

<GC(2836): freed 227346312 bytes, 78% free (1267968024/1610611200), in 1600 ms>

但要求分配空间的对象也相当大：

<AF[2474]: Allocation Failure. need 16777232 bytes, 114 ms since lastAF>

有两种方式可以应对这类内存不足的情况：一个方式是使用 k-cluster (-Xk)，另一种方式是为较大的对象定义一个 heap 段（–Xloratio），其中 loratio 意思是 large object ratio。

-Xkn

此参数为要存储的类对象在 heap 内留出了一个空间。正如在之前的例子中看到的，使用中的引用不能被移动或清除。因此它们被 “钉” 在了 heap 内的这个位置，如果有足够多的对象被钉在了 heap 内的不同位置，那么这个 heap 就会变得破碎。

为了解决这种分裂问题，可以使用参数 –Xkn，它为类对象专门提供了 heap 的一个段。n 的一个比较好的开始值是参数 40,000，即便需要使用 WebSphere Portal Support 进行系统调优分析。

如果我们将这个参数设为 40,000，JVM 就会允许在这个 k-cluster 中最多存储 40,000 个类对象。如果这个 k-cluster 已满，系统会正常继续并会使用 heap 的其余部分进行处理。

为了在管理控制台内将 –Xk 添加给原生的 JVM 参数，需遵循如下步骤：

在 WebSphere Application Server V6.0 上，选择 Servers - Application Servers - server_name - Java and Process Management - Process definition - Java Virtual Machine - Generic JVM Arguments。
或
在 WebSphere Application Server V5.0 and V5.1 上，选择 Servers - Application Servers - server_name - Process Definition - Java Virtual Machine - Generic JVM Arguments。
输入 –Xk40000，保存此配置，然后重启服务器。

–Xloration

此设置允许将 heap 的一个部分留出来供大型对象使用，这里的大型对象指的是大于 64 K 的对象。

正如我们在之前的示意图中看到的，需要为对象分配 heap 上的连续空间。很显然，寻找 528 字节的连续空间要比寻找大于 1,000,000 字节的连续空间简单很多。

如果大型对象均被存于 heap 的特定段内，那么它们可更容易地被分配；并且，较小的对象无需与它们争夺 heap 使用。

通过在 verbose GC 实现后监视这个 GC 可以调优这个参数的值。此参数的值 n，代表的是此时总的 heap 被扩展的百分比。对于本例，我们使用了值 –Xloratio0.2。

当此值被添加到服务器后，可以看到在 verbose GC 输出中多了一个新行，如下所示：

<GC(2): heap layout: (424744560/429495496) (107373880/107373880) /0>

如下所示的是来自启用了 –Xloratio0.2 的 verbose GC 的一个块：

<AF[2]: Allocation Failure. need 536 bytes, 235 ms since last AF>
<AF[2]: managing allocation failure, action=0 (423162736/429495496) 
(107373880/107373880)>
  <GC(2): GC cycle started Sat Aug 15 17:07:25 2009
  <GC(2): heap layout:  (424744560/429495496) (107373880/107373880)  /0>
  <GC(2): freed 1581824 bytes, 99% free (532118440/536869376), in 18 ms>
  <GC(2): mark: 9 ms, sweep: 9 ms, compact: 0 ms>
  <GC(2): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>
<AF[2]: completed in 18 ms>

其中的一行（如下所示）表示我们如何能调优这个值 n，因为我们现在可以看到 heap 的布局了：

<GC(2): heap layout: (424744560/429495496) (107373880/107373880) /0>

第一个比率是 heap 的常规区域（80% 用于常规处理），第二个比率是我们为大型对象分配的 heap 段（20% 分配给大型对象）。

此外还显示了每个部分内的空闲空间数量。从这个输出我们可以看出，整个大型对象段均空闲，表明没有大型对象在使用。

如果这种趋势继续，我们需要将大型对象的 heap 段从 20% 减低到 10%，以留出更多空间给常规处理使用。我们使用 –Xloratio0.1 作为新值，最好以 10% 或 0.1 作为开始值。

为了在管理控制台内将 –Xloratio 添加到原生 JVM 参数，需遵循如下步骤：

在 WebSphere Application Server V6.0 上，选择 Servers - Application Servers - server_name - Java and Process Management - Process definition - Java Virtual Machine - Generic JVM Arguments。
或
在 WebSphere Application Server V5.0 and V5.1 上，选择 Servers - Application Servers - server_name - Process Definition - Java Virtual Machine - Generic JVM Arguments。
输入 –Xloratio0.1，保存此配置，然后重启此服务器。

可以使用多个线程来执行 GC。这个数值应比系统上有的处理器的数量少 1；比如，如果系统上有四个处理器，那么为 GC 应该使用三个线程。要获得这个值，我们采用了如下参数：

–Xgcthreadsn
为了在一个四处理器系统上设置三个线程，需在管理控制台内将 –Xgcthreads 参数添加到原生 JVM 参数，遵循如下步骤：

在 WebSphere Application Server V6.0 上，选择 Servers - Application Servers - server_name - Java and Process Management - Process definition - Java Virtual Machine - Generic JVM Arguments。
或
在 WebSphere Application Server V5.0 and V5.1 上，选择 Servers - Application Servers - server_name - Process Definition - Java Virtual Machine - Generic JVM Arguments。
输入 –Xgcthreads3，保存此配置，然后重启服务器。

Post SR12

能改善 GC 性能的另一个方法是启用并发 mark 参数。正如从 verbose GC 的输出中能够看出的，GC 循环的 mark 阶段花费了大多数时间。比如：

<AF[1640]: Allocation Failure. need 536 bytes, 154266 ms since last AF>
<AF[1640]: managing allocation failure, action=1 (0/879124880) 
(215122200/219781232)>
  <GC(1718): GC cycle started Wed Aug 19 13:16:24 2009
  <GC(1718): heap layout:  (308539208/879124880) (215136552/219781232)  /0>
  <GC(1718): freed 308553560 bytes, 47% free (523675760/1098906112), 
  in 684 ms>
  <GC(1718): mark: 607 ms, sweep: 77 ms, compact: 0 ms>
  <GC(1718): refs: soft 1 (age >= 32), weak 19, final 582, phantom 3>
<AF[1640]: completed in 685 ms>

这里，总共 685ms 的时间中，607ms 被花费在 mark 阶段。为了缩短所花费的时间，可以引入如下参数，该参数被证明可以在版本 SR13 或 JDK 的更新版本中工作得很好：

–Xgcpolicy:optavgpause
此参数缩短了花在 mark 上的时间并在 GC 循环未在进行中时仍能保持 mark 阶段运行。

为了将 –Xgcpolicy:optavgpause 参数添加到管理控制台（SR13 或 Java SDK 1.4.2 的更新版本）内的原生 JVM 参数，遵循如下步骤：

在 WebSphere Application Server V6.0 上，选择 Servers - Application Servers - server_name - Java and Process Management - Process definition - Java Virtual Machine - Generic JVM Arguments。
或
在 WebSphere Application Server V5.0 and V5.1 上，选择 Servers - Application Servers - server_name - Process Definition - Java Virtual Machine - Generic JVM Arguments。
输入 –Xgcpolicy:optavgpause，保存此配置，然后重启此服务器。

用 verbose GC 分析内存问题

热门文章

最新文章

相关电子书