java - 如何解释导致 OutOfMemoryError 的 G1 GC 日志？

Question

我想知道是否有人能够向我解释如何解释导致 OutOfMemoryError 的一些 G1 GC 日志？

我知道堆转储是找出实际使用堆的最佳选择，但我无法获取它，因为它包含无法离开客户端站点的 protected 信息。我只有应用程序日志(包括来自 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 分钟内，每个年轻 GC 和完整 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 日志:

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

• 使用的 tenured 是恒定的(图表底部的深洋红色线)。
• Young GC 每隔几分钟就会暂停一次，清理所有年轻对象(图表顶部的灰线)。
• 为每一代分配的大小是恒定的。
• 年轻 GC 后的堆使用量约为 1155M。

然后在 2015/05/28 04:52:59 事情变成了梨形:

• 终身职位突然开始增长。
• 当年轻的 GC 运行时，伊甸园空间只有 51M。
• Full GC 开始发生。
• 前 3 次完整的 GC 似乎没问题，它们将堆使用量减少到 1158M-1170M(非常接近正常的 1155M)。
• 最终的 full GC 从使用了 1158M 开始，之后仍然是 1158M。

屏幕截图中的“内存”选项卡显示:

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 日志的哪个位置找到已使用的永久内存？
2. 什么会导致已用永久内存出现如此显着的峰值，从而导致 GC？只有 2000 万幸存者，所以在最坏的情况下，这些人不会都终身享有吗？
3. 这是否可以用庞大的对象分配来解释？
4. 为什么在(显然)使用的堆很少时触发最后一次完整 GC，然后它什么也没清理？
5. 如果分配了 3891M 堆，但只使用了 1158M，那么为什么会出现 OOME？

Answer 1

你的内存不足发生在 StringBuilder.append 期间 - 请记住，每次你附加一个字符串并且 StringBuilder 内的缓冲区太小以至于它扩展容量时，它会尝试分配双倍的缓冲区构建器中 String 的当前长度加 2 或新长度(如果更大)。 (参见 AbstractStringBuilder.java 的源代码)

例如，如果您的字符串构建器已经有 100 个字符并且已满，那么您再向其添加 10 个字符，它将扩展为:

100*2+2 = 202，大于10。

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

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