 | 级别: 初级 Jack Shirazi (jack@JavaPerformanceTuning.com), 董事, JavaPerformanceTuning.com
Kirk Pepperdine (kirk@JavaPerformanceTuning.com), 首席技术官, JavaPerformanceTuning.com
2004 年 5 月 01 日 您的应用程序是否经常出现 out-of-memory 错误？用户是否感受到响应时间有些不稳定？应用程序是否在相当长的时间内变得没有响应？应用程序的性能是否显得迟缓了？如果对任何一个问题的回答是肯定的，那么您很可能遇到了垃圾收集的问题了。先别进行优化，且听听 JavaPerformanceTuning.com 的 Jack Shirazi 和 Kirk Pepperdine 来解释如何识别垃圾收集问题，并由此帮助您回答这个问题：您知道垃圾收集器在干什么吗？ 许多开发人员认为，内存管理至多是开发业务逻辑的主要任务之外的一项不重要的工作 —— 直到业务逻辑不能像预期的或者测试时那样执行得好。出现这种情况时，就需要知道哪里出错了及其原因，这意味着要理解应用程序如何与底层计算资源（特别是内存）进行交互。理解应用程序如何利用内存的最好方式是观察垃圾收集器的行动。 为什么我的应用程序不连贯了？ Java 虚拟机中最大的一个性能问题是应用程序线程与同时运行的 GC 的互斥性。垃圾收集器要完成其工作，需要在一段时间内防止所有其他线程访问它正在处理的堆空间（内存）。按 GC 的术语，这段时间称为“stop-the-world”，并且，正如其名字所表明的，在垃圾收集器努力工作时，应用程序有一个急刹车。幸运的是，这种暂停通常是很短的，很难察觉到，但是很容易想像，如果应用程序在随机的时刻出现随机且较长时间的暂停，对应用程序的响应性和吞吐能力会有破坏性的影响。 不过 GC 只是应用程序出现不连贯和停顿的一个原因。那么如何确定 GC 对产生这些问题是否负有责任呢？要回答这个问题，我们需要测量垃圾收集器的工作强度，并当在系统中进行改变时继续这些测量，以定量地确定所做的改变是否有所期望的效果。 我需要多少内存？ 普遍接受的信念是，在系统中添加内存将解决许多性能问题。虽然这个原则对于 JVM 来说经常是正确的，但是太多好东西可能对性能是有害的。因此技巧在于 Java 应用程序需要多少内存就给它多少，但是绝不多给。问题是，应用程序需要多少内存？对于应用程序不连贯的情况，我们需要观察垃圾收集行为以了解看它做的是否比所需要的更多。这些观察将告诉我们所做的改变是否有所期望的效果。
| 回页首 |
|
测量 GC 的活动 生成 GC 日志的标准方式是使用 -verbose:gc 旗标，设置这个旗标后，垃圾收集器会在每次运行时生成它所做的事情的汇总，一般是写入到控制台（通过标准输出或者标准错误）。许多 VM 支持一个允许 verbose GC 输出转向到一个文件的选项。例如，在 Sun 的 1.4 JVM 中，可以使用开关 -Xloggc:filename 将 GC 输出写到文件中。对于 HP JVM，要使用 -Xverbosegc=file 开关。在本文中，我们将分析 Sun 1.4.2 和 IBM 1.4.1 JVM 捕获的 verbose GC 输出。 使用这个方法监视内存使用的一个最大好处是它对应用程序的性能的影响很小。不幸的是，这个解决方案并不完美，因为这些日志文件可能变得特别大，而维护它们可能需要重新启动 JVM。尽管如此，这种技术在生产环境中仍然是可行的，因为它可以帮助诊断只在这种环境中才列出的性能问题。 更深入观察 GC -verbose:gc 旗标生成的输出根据 JVM 厂商而不同，不同的垃圾收集器选项会报告特定于该实现的信息。例如，由 IBM JVM 生成的输出比由 Sun JVM 生成的输出冗长得多，而 Sun 的输出更适合于由工具读取。就是说，每一个 GC 日志传达基本信息 —— 使用了多少内存、恢复了多少内存、GC 周期用了多少时间，以及在收集期间是否采取了其他行动。从这些基本测量中，我们可以推断出有助于更好地理解所发生的事情的细节。我们要计算的统计如下所示：
- 考虑的运行时的持续时间
- 收集总数
- 收集频率
- 收集所用最长时间
- 收集所用总时间
- 收集所用平均时间
- 收集的平均间隔
- 分配的字节总数
- 每次收集每秒分配的字节数
- 恢复的字节总数
- 每次收集每秒恢复的字节总数
理解了暂停时间，我们就可以理解 GC 对应用程序不响应是否负有部分或者全部责任了。一种实现这一任务的方法是将详细（verbose） GC 日志中的 GC 活动与系统采集的其他日志（如 Web 服务器日志中的请求 backlog）相对应。几乎可以肯定最长的 GC 暂停会导致整个系统响应可感觉的下降，所以知道什么时候响应下降是很有用的，这样就可以将 GC 活动与应用程序吞吐相关联起来。 另一种可能的竞争因素是堆内存分配和恢复的比率，称为 churn。产生大量立即释放的对象的应用程序通常会受到 churn 的拖累。更高的 churn 比率对垃圾收集器加以很大压力，创造了更多的内存资源竞争，这又可导致更长的暂停或者可怕的 OutOfMemoryError 。 了解应用程序是否遭遇这些问题的一个方法是测量所考虑的整个运行时期间 GC 所占用的总时间。有了这种计算，我们就可以了解 GC 做的是否比它所应该做的更多。让我们推导出进行这种判断所需要的公式。
| 回页首 |
|
Sun GC 日志记录 清单 1 是由 Sun 1.4.2_03 JVM 以 -Xloggc:filename 运行默认的标记-清除收集器所生成的日志记录的例子。可以看到，日志项非常精确地记录了每次所做的事情。
清单 1. 使用 -Xloggc:filename 旗标的 GC 日志记录
69.713: [GC 11536K->11044K(12016K), 0.0032621 secs]
69.717: [Full GC 11044K->5143K(12016K), 0.1429698 secs]
69.865: [GC 5958K->5338K(11628K), 0.0021492 secs]
69.872: [GC 6169K->5418K(11628K), 0.0021718 secs]
69.878: [GC 6248K->5588K(11628K), 0.0029761 secs]
69.886: [GC 6404K->5657K(11628K), 0.0017877 secs]
|
首先注意到的可能是每一项日志记录是写在一组方括号内的。其他 GC 算法，如并发收集器， 可能将一些值分解为更细的信息。如果是这种情况，这些被分解的值会由包围在嵌入的一组方括号中的细节所替代，这使工具可以更容易地处理详细 GC 输出。 我们的研究首先从分析清单 1 中标记为 69.713 的记录开始。这个标记是 JVM 开始后的秒数和毫秒数的时间戳。在这个例子中，JVM 在这个 GC 周期开始之前运行了 69.713 秒。从左到右的字段为：执行的收集的类型、GC 之前的堆使用、总的堆能力和 GC 事件的持续时间。从这个描述中我们可以看出第一个 GC 事件是一个小的收集。在 GC 开始之前，使用了 11536 Kb 的堆空间。在完成时，使用了 11044 Kb，堆能力为 12016 Kb，而整个收集用了 .0032621 秒。下一个事件，一个完全的 GC，在 69.717 秒时或者上一个小 GC 事件之后 0.003 秒时开始。注意，如果将小 GC 事件的持续时间加到其开始时间上，就会看到它在完全的 GC 开始之前不到 1毫秒结束。因此我们可以得出结论：小收集没有恢复足够的空间，这种失败触发了完全的 GC。对应用程序来说，这像是一个持续了 0.1462319 秒的事件。让我们继续确定如何计算其他值。 GC 日志记录的参数确定 我们通过确定每个 GC 日志记录中的值的参数来开始分析： R(n) = T(n): [ <GC> HB->HE(HC), D] n | 清单中记录的索引，1 是第一个，m 是最后一个 | R(n) | GC 记录 | T(n) | 第 n 个 GC 发生的时间 | HB | GC 之前堆的数量 | HE | GC 之后使用的堆数量 | HC | 堆空间的总量 | D | GC 周期的持续时间 |
有了这些定义，我们现在可以推导出用于计算前面描述的值的公式。
| 回页首 |
|
基本值 我们要计算的第一个值是日志所覆盖的运行时整个持续时间。如果要考虑每一项记录，那么就要分析最后一项记录的时间戳。因为清单 1 只表示全部日志记录的一部分，我们需要从最后一项中提取出第一个时间戳。尽管对这个例子来说，这个数字足够精确，但是为了绝对准确，需要加上最后 GC 的持续时间。其原因是时间戳是在 GC 开始时记录的，而记录表示在记录了时间戳以后发生的事情。 剩余值是取记录中相应的值的总和计算的。值得注意的是恢复的字节可以通过分析记录中测量的关系而计算，而分配的字节可以通过分析前后记录测量之间的关系计算。例如，如果考虑在时间戳 69.872 和 69.878 之间发现的记录对，可以用第一个记录中 GC 之后占用的内存数量减去第二个记录在 GC 之前占用的字节数量计算在新的一代（generation）中分配的字节数量： 6248 Kb - 5418 Kb = 830 Kb 。下面表 1 展示了其他值的公式。 要找出最长的 GC 暂停，我们只需要查看持续时间并寻找 D(n) （记录 n 的持续时间）的最大值。 表 1. 统计公式 | 统计 | 计算（时间单位调整为秒） | | 运行时持续时间 | RT = (T(M) + D(M)) - T(1) | | 小收集的总数 | TMC = Sum( R(n)) 其中 GC(n) = GC | | 完全收集的总数 | TFC = Sum( R(n)) 其中 GC(n) = Full | | 收集频率（小收集） | CFM = TMC / RT | | 收集频率（完全） | CFF = TFC / RT | | 收集的时间（最长的小收集） | MAX(D(n)) for all n 其中 GC(n) = GC | | 收集的时间（最长的完全收集） | MAX(D(n)) for all n 其中 GC(n) = Full | | 小收集的时间（总数） | TTMC = Sum(D(n)) for all n 其中 GC(n) = GC | | 完全收集的时间（总数） | TTFC Sum(D(n)) for all n 其中 GC(n) = Full | | 收集的时间（总数） | TTC = TTMC + TTFC | | 小收集的时间（平均） | ATMC = TTMC / RT | | 完全收集的时间（平均） | ATFC = TTFC / RT | | 收集的时间（平均） | ATC = TTC / RT | | 收集间隔（平均） | Sum( T(n+1) - T(n)) / (TMC + TFC) for all n | | 分配的字节（总数） | TBA = Sum(HB(n+1) - HE(n)) 对于所有 n | | 分配的字节（每秒） | TBA / RT | | 分配的字节（每次收集） | TBA / (TMC + TFC) | | 小收集恢复的字节（总数） | BRM = Sum(HB(n) - HE(n)) 其中 GC(n) = GC | | 完全收集恢复的字节（总数） | BRF = Sum(HB(n) - HE(n)) 其中 GC(n) = Full | | 恢复的字节（总数） | BRT = BRM + BRF | | 恢复的字节（每次小收集） | BRPM = BRM / TMC | | 恢复的字节（每次完全收集） | BRPF = BRF / TMF | | 恢复的字节（小收集每秒） | BRP = BRM / TTMC | | 恢复的字节（完全收集每秒） | BRF = BRF / TTFC |
可以从公式中看出，我们经常需要分别考虑完全 GC 和小 GC。小 GC 与完全 GC 有根本性的不同，一般来说前者至少比后者要快一个数量级。我们可以通过快速分析清单 1 看出这一点 —— 最长的小收集比完全收集快 50 倍。 下面表 2 显示对清单 1 中的值使用表 1 中的公式的结果。 表 2. Sun GC 日志分析 | 统计 | 计算（时间单位调整为秒） | | 运行时持续时间 | (69.886 + 0.0017877) - 69.713 = 0.1747877 | | 小收集总数 | 5 | | 完全收集总数 | 1 | | 收集频率（小收集） | 5 / 0.1747877 = 28.6 per second | | 收集频率（完全） | 1 / 0.1747877 = 5.27 per second | | 收集时间（最长的小收集） | 0.0032621 | | 收集时间（最长的完全收集） | 0.1429698 | | 小收集的时间（总数） | 0.0123469 | | 完全收集的时间（总数） | 0.1429698 | | 收集的时间（总数） | 0.1553167 | | 小收集的时间（平均） | 7.1% | | 完全收集的时间（平均） | 81.8% | | 收集的时间（平均） | 88.9% | | 收集间隔（平均） | .173/5=0.0346 | | 分配的字节（总数） | 3292 | | 分配的字节（每秒） | 18834 Kb/second | | 分配的字节（每次收集） | 549 Kb | | 小收集恢复的字节（总数） | 3270 Kb | | 完全收集恢复的字节（总数） | 5901 Kb | | 恢复的字节（总数） | 5901 + 3270 = 9171 Kb | | 恢复的字节（每次小收集） | 3270/5 = 654 | | 恢复的字节（每次完全收集） | 5901/1 = 5901 | | 恢复的字节（小收集每秒） | 3270/0.0123469 = 264843 Kb/second | | 恢复的字节（完全收集每秒） | 5901/0.1429698 = 41274K/second |
表 2 包含从这些看来简单的日志中推算出的大量信息。取决于所关注的问题，可能不需要计算所有这些值，因为其中一些值比另一些更有用。对于应用程序长时间不响应的情况，要关注的是 GC 持续时间和计数。
| 回页首 |
|
IBM GC 日志记录 与 Sun 日志不同，IBM 日志特别冗长。即使这样，仍然需要一个指导以完全理解所提供的信息。清单 2 是这种 verbose:gc 日志文件的一部分。
清单 2. IBM JVM verbose:gc 输出
<AF[31]: Allocation Failure. need 528 bytes, 969 ms since last AF>
<AF[31]: managing allocation failure, action=1 (0/97133320) (1082224/1824504)>
<GC(31): GC cycle started Wed Feb 25 23:08:41 2004
<GC(31): freed 36259000 bytes, 37% free (37341224/98957824), in 569 ms>
<GC(31): mark: 532 ms, sweep: 37 ms, compact: 0 ms>
<GC(31): refs: soft 0 (age >= 32), weak 0, final 2, phantom 0>
<AF[31]: managing allocation failure, action=3 (37341224/98957824)>
<GC(31): need to expand mark bits for 116324864-byte heap>
<GC(31): expanded mark bits by 270336 to 1818624 bytes>
<GC(31): need to expand alloc bits for 116324864-byte heap>
<GC(31): expanded alloc bits by 270336 to 1818624 bytes>
<GC(31): need to expand FR bits for 116324864-byte heap>
<GC(31): expanded FR bits by 544768 to 3637248 bytes>
<GC(31): expanded heap by 17367040 to 116324864 bytes, 47% free, ratio:0.417>
<AF[31]: completed in 812 ms>
<AF[32]: Allocation Failure. need 528 bytes, 1765 ms since last AF>
<AF[32]: managing allocation failure, action=1 (0/115394264) (930600/930600)>
<GC(32): GC cycle started Wed Feb 25 23:08:43 2004
<GC(32): freed 54489184 bytes, 47% free (55419784/116324864), in 326 ms>
<GC(32): mark: 292 ms, sweep: 34 ms, compact: 0 ms>
<GC(32): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>
<AF[32]: completed in 328 ms>
<AF[33]: Allocation Failure. need 528 bytes, 1686 ms since last AF>
<AF[33]: managing allocation failure, action=1 (0/115510592) (814272/814272)>
<GC(33): GC cycle started Wed Feb 25 23:08:45 2004
<GC(33): freed 56382392 bytes, 49% free (57196664/116324864), in 323 ms>
<GC(33): mark: 285 ms, sweep: 38 ms, compact: 0 ms>
<GC(33): refs: soft 0 (age >= 32), weak 0, final 18, phantom 0>
<AF[33]: completed in 324 ms>
|
清单 2 中有三项 GC 日志记录。我将不会提供完全的说明，而是推荐一篇由 Sam Borman 所写的很好的文章“Sensible Sanitation”（请参阅 参考资料）。对于我们的目的，需要与像对 Sun JVM 的日志那样推算出同样类型的信息。好的方面是有一些计算结果已经是现成的了。例如，如果分析 AF[31] （事件 31 分配失败），将会看到 GC 之间的间隔、恢复的内存数量、事件的持续时间。我们可以根据这些数字计算其他所需要的值。
| 回页首 |
|
这些数字有什么意义 如何看待这些数字取决于所要得到的结果。在许多服务器应用程序中，它归结为缩短暂停时间，这又归结为减少所发生的完全收集的持续时间和次数。下个月，我们将探讨如何用这些信息调优曾经受这个问题困扰的一个真实应用程序。
参考资料 - 您可以参阅本文在 developerWorks 全球站点上的 英文原文.
- 查看 关注性能系列的其他文章 。
- Sam Borman 的“ Sensible Sanitation”讨论了 IBM JVM 垃圾收集器的细节（ developerWorks，2002 年 8 月）。
- Brian Goetz 在 “ Java theory and practice: Garbage collection and performance”（ developerWorks，2004 年 1 月）中讨论了 GC。
- 对于 Sun VM 的权威指导，请阅读 Tuning Garbage Collection with the 1.4.2 Java[tm] Virtual Machine。
- 在 Java 性能调优网站找到 GC 性能提示。
- 阅读 Jack Shirazi 的 Java Performance Tuning, 2nd Edition （O'Reilly）中关于 GC 的所有内容。
- 在 developerWorksJava 技术专区 中可以找到有关 Java 编程各个方面的数百篇文章。
- 请访问 Developer Bookstore，获得技术书籍的完整列表，其中包括数百本 Java 相关主题的书籍。
作者简介 | | | | Jack Shirazi 是 JavaPerformanceTuning.com的董事，也是 Java Performance Tuning, 2nd Edition （O'Reilly） 一书的作者。 |
| | | | Kirk Pepperdine 是 Java Performance Tuning.com 的首席技术官，并且在过去 15 年一直关注对象技术和性能调优。Kirk 是 Ant Developer's Handbook （MacMillan）一书的合著者。 |
|
