Scala演员应用程序的奇怪垃圾收集行为

Question

我有一个应用程序，使用了相当多的演员：确切地说，25,000个。它使用Scala 2.7.7，并在jdk6_u18上运行。它基本上监听和处理市场数据，并且几乎没有状态。

它每天早上8:02启动，在一个小时内就会因为OutOfMemoryError而崩溃。 "啊哈"你说，"你有一个内存泄漏！"但是当我重新启动它时，它从来没有再在一天中的其他时间崩溃过！这尽管在美国市场在下午2:30开放时增加了GC和CPU开销。

一些轶事发现：

• 它在Solaris上运行。当我以前在Linux上运行它时，它根本没有崩溃。
• 我尝试过更改生成堆大小、分配更多内存等。我认为这没有任何区别。
• 当我打开verbose:gc时，收集器的行为似乎有所不同。

出现了一些问题：

1. 为什么该程序在Linux和Solaris之间的表现会不同？
2. 为什么在8.02和8.42启动程序时行为会不同？
3. 我听说actors库存在一些内存泄漏问题。它们是什么，何时修复，我如何发现是否存在类似的问题？（在jhat中寻找的内容）
4. 有人知道可能发生了什么吗？

我现在正在尝试使用G1来查看是否有任何区别。我明天会更新这个问题！

G1输出的一些详细信息: 启用verbose:gc选项

我想我刚才抓住了它：

600.290: [Full GC 255M->144M(256M), 1.5772616 secs]
602.084: [GC pause (young) 227M->145M(256M), 0.0556769 secs]
602.418: [Full GC 254M->144M(256M), 1.6415216 secs]
604.279: [GC pause (young) 227M->145M(256M), 0.0415157 secs]
604.602: [Full GC 255M->145M(256M), 1.6041762 secs]
606.422: [GC pause (young) 227M->145M(256M), 0.0237441 secs]
606.710: [Full GC 254M->145M(256M), 1.6022185 secs]

然后稍后一点（你可以看到完全GC时间更长，回收的内存更少）

849.084: [Full GC 254M->176M(256M), 1.9658754 secs]
851.191: [GC pause (young) 228M->176M(256M), 0.0218611 secs]
851.414: [Full GC 254M->176M(256M), 1.9352357 secs]
853.492: [GC pause (young) 228M->176M(256M), 0.0224688 secs]
853.716: [Full GC 254M->176M(256M), 1.9339705 secs]
855.793: [GC pause (young) 228M->176M(256M), 0.0215707 secs]
856.009: [Full GC 254M->176M(256M), 1.9805797 secs]
858.137: [GC pause (young) 228M->176M(256M), 0.0223224 secs]

使用verbose:gc输出的一些G1信息

又好了！*叹气*

303.656: [GC暂停（年轻代）225M->93M（256M），0.1680767秒] 308.060: [GC暂停（年轻代）226M->94M（256M），0.1793724秒] 312.746: [GC暂停（年轻代）227M->93M（256M），0.1674851秒] 316.162: [GC暂停（年轻代）227M->95M（256M），0.1826145秒] 320.147: [GC暂停（年轻代）226M->94M（256M），0.1656664秒] 325.978: [GC暂停（年轻代）226M->93M（256M），0.1475760秒] 330.176: [GC暂停（年轻代）226M->94M（256M），0.1727795秒]

而且，很久以后仍然没问题！

25882.894: [GC暂停（年轻代） 从224M到125M（256M），用时0.2126515秒] 25884.880: [GC暂停（年轻代） 从224M到126M（256M），用时0.2059802秒] 25887.027: [GC暂停（年轻代） 从224M到125M（256M），用时0.1851359秒] 25889.940: [GC暂停（年轻代） 从223M到126M（256M），用时0.2046496秒] 25891.567: [GC暂停（年轻代） 从224M到126M（256M），用时0.1600574秒]

稍后还会进行一次完整的GC

37180.191: [GC暂停（年轻代）225M->154M（256M），0.1716404秒]
37182.163: [GC暂停（年轻代）（初始标记）225M->153M（256M）37182.326：[GC并发标记开始]，0.1622246秒]
37183.089：[GC并发标记结束，0.7635219秒]
37183.090：[GC重新标记，0.0032547秒]
37183.093：[GC并发计数开始]
37183.297：[GC并发计数结束，0.2043307]
37183.393：[GC清理198M->198M（256M），0.0068127秒]
37183.400：[GC并发清理开始]
37183.400：[GC并发清理结束，0.0000393]
37183.648：[GC暂停（年轻代）222M->153M（256M），0.1483041秒]
37184.235：[GC暂停（部分）171M->91M（256M），0.2520714秒]
37187.223：[GC暂停（年轻代）221M->92M（256M），0.1721220秒]

更新

自从在jdk1.6.0_18上切换到G1垃圾收集器后，该应用程序已经连续三天表现良好。我怀疑Erik关于VM在高吞吐量情况下将对象提升为老年代并陷入“死亡螺旋”的分析是正确的。

- oxbow_lakes

---

你应该首先尝试使用-XX:+HeapDumpOnOutOfMemoryError来收集关于内存中发生OutOfMemoryException时的对象的更多信息。 - stacker

是的 - 我已经完成了这个任务，但我在运行256Mb堆转储文件上的jhat时遇到了困难！ - oxbow_lakes

你尝试过其他分析器工具，例如：http://www.alphaworks.ibm.com/tech/heapanalyzer 吗？还有一些其他SO问题中推荐的工具。 - stacker

当你从Linux切换到Solaris时，你是否无意中从32位切换到64位？ 这可能会产生意想不到的巨大差异。 - Erik Engbrecht

嗨，Erik - 不是的，它们都是32位的。主要区别在于Linux系统上的JVM比我在Solaris上尝试过的版本要旧得多（1.6.0_03），后者版本为1.6.0_13和1.6.0_18。 - oxbow_lakes

@stacker - 我明天可能会看一下这样的东西。即使使用1.5G的内存运行jhat，我也无法分析我的256M堆！ - oxbow_lakes

Answer 1

你有什么理由认为你的堆空间会慢慢增长？在这两个示例中，它似乎是在增长。我经常做的一件事是减少我的堆空间，试图使问题更加严重。但是，256M大约是Scala的下限。

我之前注意到的一件事是：如果你有短暂存在的对象因为压力过大而从伊甸园代出来，它可能会逐渐消耗掉你的空间。当出现活动突发（也许你早上出现了爆发？）并且你的伊甸园空间不足时，就可能会发生这种情况。Scala通常和特别是演员会大量使用小型短期对象，似乎有这个神奇的阈值，一旦你跨越它，一切都会往下走。所以一个运行没问题，下一个就会崩溃。

我之前还注意到的一件事是，适用于OSX / x86的GC设置通常在Sparc / Solaris上效果不佳，反之亦然。如果你在CoolThreads上，请将GC配置为每个调度程序/池线程具有一个GC线程。

这带来另一个问题-确保调度程序不会肆意地创建新线程。有时候会这样做。我会说你应该几乎总是手动设置线程上限。我不知道它有多相关，但actors默认使用的fork-join调度程序的一个有趣的事实是，它旨在用于短期的CPU绑定任务。在线程中进行IO将破坏它的假设。当然，它仍然应该工作，但...

祝你好运！我已经失去了许多，许多天来解决这些问题。

看看这里的一些选项：http://java.sun.com/performance/reference/whitepapers/tuning.html 看起来你正在使用并发标记清除收集器。尝试设置：

-XX:+UseParallelGC

- Erik Engbrecht

---

嗨，Erik - 不是的 - 我添加了第三个跟踪。第二个示例非常稳定，在6小时后仍然很强大。完整的GC会将内存降至100Mb以下，然后它会慢慢地回升到150Mb，然后再次进行完整的GC。 - oxbow_lakes

我已将演员线程池的最大池大小设置为8。你提到早上短暂的创作爆发可能是正确的，但我还不能完全理解它。当市场在早上8点开盘时，显然会有消息的增加。这些保持大致恒定，直到美国在下午2:30开盘时，活动量翻倍。我想到了一些类似于“我的应用程序无法快速增加堆”的想法，所以我将Xms/mx都设置为256Mb，并安排应用程序在8:02am启动，但这并没有起作用。如果转移到G1不成功，我将考虑更改旧GC中的Eden比例。 - oxbow_lakes

GC（垃圾回收）性能取决于HotSpot对代码执行的优化情况，可能会有很大的差异。如果您正在使用高负载的冷VM，然后逐渐减少负载，这可能会给它带来压力。当美国市场开放时，VM可能已经热了起来，能够更好地处理负载。 - Erik Engbrecht

我曾经寻找过关于在特定情况下使用好的虚拟机选项的技巧，但并没有取得太大的成功。普遍意见似乎是“不要使用任何定制选项；让虚拟机自行决定该做什么”。 - oxbow_lakes

@Erik - 我有其他基于actor的应用，它们可以在小于10Mb的堆上正常运行。你能详细说明一下“Scala需要256Mb”的含义吗？ - oxbow_lakes

我发现Scala需要更多的内存才能更好地运行。256M并不是一个科学的数字，而是我发现如果我不想被调整设置所困扰，将堆大小设置为512m或者经常是1g会更好。这样可以给HotSpot更多的空间来呼吸。 - Erik Engbrecht

Answer 2

此时，我想知道是否值得尝试用Lift或Akka替换您的演员？虽然我认为这不太可能是它们的错误，但它们可能无法触发导致崩溃的任何问题。

- Daniel C. Sobral

---

@oxbow 我能说什么呢？我很懒。;-) - Daniel C. Sobral

Answer 3

依照我的观察，堆布局是错误的。老年代空间从开始的93MB到高负载时的176MB不等。从日志中可以看出，您的生成速率平均约为50MB/秒。因此，如果您在176MB处进行2秒的全垃圾回收时，将没有年轻代空间来创建新对象。

我的建议：

• 检查幸存者空间设置-您的老年代增长到了176M。

• 减少新生代空间-显然，这不是您想要的

• 将NewSize明确设置为所需值，比如128M

• 增加总堆大小以促进对象而不是进行全垃圾回收

• 您的暂停时间非常长：gc 80mb>50ms，~120mb>150ms。尝试使用CMS，我相信它会更快（但请进行基准测试）

- Alexander Ashitkin