如何解释 G1 GC 日志以及在 OutOfMemoryError 之前的相关内容？

Question

我想知道有没有人能够解释一下G1 GC日志如何导致OutOfMemoryError？

我知道堆转储是找出实际使用堆的最佳方法，但是由于其中包含不能离开客户端站点的受保护信息，因此我无法获得它。我所拥有的只有应用程序日志（其中包括OOME的堆栈）和G1 GC日志。

完整的G1 GC日志包含很多细节，因此我不会在这里放置它们，除非有人特别需要查看它们。

这些日志来自的具体Java版本为：

> java -version
java version "1.7.0_21"
Java(TM) SE Runtime Environment (build 1.7.0_21-b11)
Java HotSpot(TM) 64-Bit Server VM (build 23.21-b01, mixed mode)

我使用的GC选项来创建GC日志是：

-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails
-Xloggc:log/gc.log

以下是在导致 OOME 的最后 30 分钟内每个 young GC 和 full GC 的所有内存统计信息：

INFO   | jvm 1    | 2015/05/28 04:29:34 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO   | jvm 1    | 2015/05/28 04:33:21 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO   | jvm 1    | 2015/05/28 04:37:09 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO   | jvm 1    | 2015/05/28 04:40:58 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO   | jvm 1    | 2015/05/28 04:44:44 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO   | jvm 1    | 2015/05/28 04:48:30 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO   | jvm 1    | 2015/05/28 04:52:17 | [Eden: 1290M(1290M)->0B(1290M) Survivors: 20M->20M Heap: 2445M(3932M)->1155M(3932M)]
INFO   | jvm 1    | 2015/05/28 04:52:58 | [Eden: 639M(1290M)->0B(1295M) Survivors: 20M->15M Heap: 2278M(3932M)->1635M(3932M)]
INFO   | jvm 1    | 2015/05/28 04:52:59 | [Eden: 51M(1295M)->0B(1300M) Survivors: 15M->10M Heap: 2561M(3932M)->2505M(3932M)]
INFO   | jvm 1    | 2015/05/28 04:52:59 | [Full GC 2505M->1170M(3901M), 1.9469560 secs]
INFO   | jvm 1    | 2015/05/28 04:53:01 | [Eden: 44M(1300M)->0B(1299M) Survivors: 0B->1024K Heap: 1653M(3901M)->1610M(3901M)]
INFO   | jvm 1    | 2015/05/28 04:53:01 | [Eden: 1024K(1299M)->0B(1299M) Survivors: 1024K->1024K Heap: 1610M(3901M)->1610M(3901M)]
INFO   | jvm 1    | 2015/05/28 04:53:02 | [Full GC 1610M->1158M(3891M), 1.4317370 secs]
INFO   | jvm 1    | 2015/05/28 04:53:03 | [Eden: 112M(1299M)->0B(1296M) Survivors: 0B->1024K Heap: 1758M(3891M)->1647M(3891M)]
INFO   | jvm 1    | 2015/05/28 04:53:06 | [Eden: 49M(1296M)->0B(1360M) Survivors: 1024K->1024K Heap: 2776M(4084M)->2728M(4084M)]
INFO   | jvm 1    | 2015/05/28 04:53:06 | [Eden: 0B(1360M)->0B(1360M) Survivors: 1024K->1024K Heap: 2837M(4084M)->2836M(4084M)]
INFO   | jvm 1    | 2015/05/28 04:53:06 | [Full GC 2836M->1158M(3891M), 1.4847750 secs]
INFO   | jvm 1    | 2015/05/28 04:53:08 | [Full GC 1158M->1158M(3891M), 1.5313770 secs]

* 这是一种不同于原始日志的格式，我删除了时间细节，使其更短、更易读。

我还在GCViewer中将原始GC日志制成了图表：

到目前为止，一切似乎都很顺利：

• 用过的老年代内存保持不变（图表底部的深洋红色线条）。
• 每隔几分钟就会发生一次Young GC暂停，清理所有年轻对象（图表顶部的灰线）。
• 每个代的分配大小保持不变。
• Young GC后堆使用量约为1155M。

然后在2015/05/28 04:52:59，情况急转直下：

• 老年代突然开始增长。
• 当Young GC运行时，伊甸园空间中仅有51M。
• 开始出现Full GC。
• 前3次Full GC似乎还好，它们将堆使用量降至1158M-1170M（非常接近正常的1155M）。
• 最后一次Full GC从使用了1158M开始，结束时仍然是1158M。

截图中的Memory选项卡显示：

Tenured heap (usage / alloc. max)    2,836 (104.1%) / 2,723M
Total promotion                                       2,048K

现在简要解释一下发生在 2015/05/28 04:52:59 的事件。在这个时间点上，大量的配置对象被使用 StringBuilder 序列化为一个自定义格式。这导致了一系列的数组复制，最终在 2015/05/28 04:53:09 发生了以下异常。

java.lang.OutOfMemoryError: Java heap space
    at java.util.Arrays.copyOf(Arrays.java:2367)
    at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:130)
    at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:114)
    at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:587)
    at java.lang.StringBuilder.append(StringBuilder.java:214)
    ...

我有几点无法解释：

1. 在GC日志中，您会在哪里找到使用的tenured memory？
2. 是什么导致了使用的tenured memory急剧增加以引发GC？只有20M的幸存者，所以在最坏的情况下，它们都会进入tenured，并且没有更多的空间可以使用了吗？
3. 这可能是由于分配了巨大的对象而引起的吗？
4. 为什么在还有很少使用堆内存时触发了最后一次full GC，之后却没有清理任何内容？
5. 如果分配了3891M的堆内存，但只使用了1158M，则为什么会出现OOME错误？

- steinybot

---

你应该使用 -XX:+PrintGCDetails 运行以获取额外信息，以便 GCViewer 可以处理。 - the8472

@the8472 是的，那就是我所做的。我已经将这些细节添加到问题中了。 - steinybot

我将尝试使用“-XX：+PrintAdaptiveSizePolicy”选项，以查看是否显示了巨大对象分配。 - steinybot

嗯，我不记得Java7的情况，但在Java8中，GC日志会显示触发GC的原因，而我在你的日志中没有看到这一点。分配巨大对象失败通常会在OOME之前进行最后一次GC，并在日志中打印出来。但是这些通常很容易被发现，因为它们通常总是在同一个位置抛出异常，大多数应用程序没有许多调用点会导致巨大的分配。 - the8472

选项为：-XX:+PrintGCCause。你可能应该将完整的日志粘贴到某个地方，以便我们查看。 - the8472

在你的应用程序中打印出你正在序列化的对象数量的日志行可能也很有用，这样当问题发生时，你就可以看到是否有什么奇怪的地方。另一个有用的方法是抓取堆转储（如果可能的话），并使用内存分析工具打开它：它将显示内存中的所有对象及其引用树和默认的内存泄漏分析。 - gmcontessa

Answer 1

您的内存不足问题发生在 StringBuilder.append 中 - 请记住，每次您附加一个字符串并且 StringBuilder 中的缓冲区太小以致于它扩展容量时，它会尝试通过将当前字符串长度加倍再加 2 或新长度（如果更大）来分配双倍缓冲区。 （请参见 AbstractStringBuilder.java 的源代码）

例如，如果您的字符串生成器已经有 100 个字符并且已满，则向其附加另外 10 个字符时，它会扩展为：

100*2+2 = 202，超过了 10。

因此，如果您已经有一个非常长的字符串（10MB），它将尝试创建一个 20MB 的缓冲区，以此类推。

检查您的代码，确保您没有在构建器中创建巨大的字符串。

- sunnychan77