Heroku JVM 调优

Question

我已经在Heroku上为Play2框架编写了一个应用程序，但出现了内存问题。

2013-03-21T01:28:35+00:00 heroku[web.1]: Process running mem=543M(106.1%)
2013-03-21T01:28:35+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)

我本地使用相同的JVM设置和内存限制（512MB）对它进行了分析，但几乎在我在Heroku发送请求时立即耗尽了堆空间。

JAVA_OPTS:    -Xmx384m -Xss512k -XX:+UseCompressedOops

如果我能够分析发生了什么问题，那么我就没有任何问题，但是java-agent对我不起作用。

我还没有遇到我见过的任何内存泄漏。我知道我创建的每个对象都只使用一次，因此我可以使我的young gen大而我的old gen小。我尝试了不同的JVM值，但似乎找不到正确的组合，无法在没有正确分析的情况下让它正常工作。

我已经阅读了所有关于Heroku调优的文档，但没有结果。有人对此有任何想法，或者可以指引我方向吗？

编辑

虽然我仍然无法使远程监视正常工作，但这里是我本地测试系统在1个完整垃圾回收之前和之后的一些转储信息。

{Heap before GC invocations=1747 (full 0):
 PSYoungGen      total 42496K, used 42496K [0x00000000f5560000, 0x00000000fded0000, 0x0000000100000000)
  eden space 42176K, 100% used [0x00000000f5560000,0x00000000f7e90000,0x00000000f7e90000)
  from space 320K, 100% used [0x00000000fde80000,0x00000000fded0000,0x00000000fded0000)
  to   space 640K, 0% used [0x00000000fdd90000,0x00000000fdd90000,0x00000000fde30000)
 PSOldGen        total 106176K, used 105985K [0x00000000e0000000, 0x00000000e67b0000, 0x00000000f5560000)
  object space 106176K, 99% used [0x00000000e0000000,0x00000000e67804c8,0x00000000e67b0000)
 PSPermGen       total 43712K, used 43684K [0x00000000d5a00000, 0x00000000d84b0000, 0x00000000e0000000)
  object space 43712K, 99% used [0x00000000d5a00000,0x00000000d84a9338,0x00000000d84b0000)
2013-03-21T14:09:36.827-0700: [GC [PSYoungGen: 42496K->384K(41536K)] 148481K->106450K(147712K), 0.0027940 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
Heap after GC invocations=1747 (full 0):
 PSYoungGen      total 41536K, used 384K [0x00000000f5560000, 0x00000000fde90000, 0x0000000100000000)
  eden space 41152K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000f7d90000)
  from space 384K, 100% used [0x00000000fdd90000,0x00000000fddf0000,0x00000000fddf0000)
  to   space 640K, 0% used [0x00000000fddf0000,0x00000000fddf0000,0x00000000fde90000)
 PSOldGen        total 106176K, used 106066K [0x00000000e0000000, 0x00000000e67b0000, 0x00000000f5560000)
  object space 106176K, 99% used [0x00000000e0000000,0x00000000e6794968,0x00000000e67b0000)
 PSPermGen       total 43712K, used 43684K [0x00000000d5a00000, 0x00000000d84b0000, 0x00000000e0000000)
  object space 43712K, 99% used [0x00000000d5a00000,0x00000000d84a9338,0x00000000d84b0000)
}
{Heap before GC invocations=1748 (full 1):
 PSYoungGen      total 41536K, used 384K [0x00000000f5560000, 0x00000000fde90000, 0x0000000100000000)
  eden space 41152K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000f7d90000)
  from space 384K, 100% used [0x00000000fdd90000,0x00000000fddf0000,0x00000000fddf0000)
  to   space 640K, 0% used [0x00000000fddf0000,0x00000000fddf0000,0x00000000fde90000)
 PSOldGen        total 106176K, used 106066K [0x00000000e0000000, 0x00000000e67b0000, 0x00000000f5560000)
  object space 106176K, 99% used [0x00000000e0000000,0x00000000e6794968,0x00000000e67b0000)
 PSPermGen       total 43712K, used 43684K [0x00000000d5a00000, 0x00000000d84b0000, 0x00000000e0000000)
  object space 43712K, 99% used [0x00000000d5a00000,0x00000000d84a9338,0x00000000d84b0000)
2013-03-21T14:09:36.830-0700: [Full GC [PSYoungGen: 384K->0K(41536K)] [PSOldGen: 106066K->13137K(52224K)] 106450K->13137K(93760K) [PSPermGen: 43684K->43684K(87936K)], 0.0666250 secs] [Times: user=0.06 sys=0.01, real=0.07 secs] 
Heap after GC invocations=1748 (full 1):
 PSYoungGen      total 41536K, used 0K [0x00000000f5560000, 0x00000000fde90000, 0x0000000100000000)
  eden space 41152K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000f7d90000)
  from space 384K, 0% used [0x00000000fdd90000,0x00000000fdd90000,0x00000000fddf0000)
  to   space 640K, 0% used [0x00000000fddf0000,0x00000000fddf0000,0x00000000fde90000)
 PSOldGen        total 52224K, used 13137K [0x00000000e0000000, 0x00000000e3300000, 0x00000000f5560000)
  object space 52224K, 25% used [0x00000000e0000000,0x00000000e0cd4528,0x00000000e3300000)
 PSPermGen       total 87936K, used 43684K [0x00000000d5a00000, 0x00000000dafe0000, 0x00000000e0000000)
  object space 87936K, 49% used [0x00000000d5a00000,0x00000000d84a9338,0x00000000dafe0000)
}

编辑

这是我能得到的东西--虽然不多，但这就是在100个请求之后发生的事情，随着一切开始恶化，您可以看到web.2已经在此转储中交换

2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=load_avg_1m val=0.41
2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=memory_total val=246.95 units=MB
2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=memory_rss val=246.91 units=MB
2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=memory_cache val=0.05 units=MB
2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=memory_swap val=0.00 units=MB
2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=memory_pgpgin val=72259 units=pages
2013-03-21T22:24:23+00:00 heroku[web.1]: source=heroku.13369226.web.1.d615093e-77a3-42b1-8da1-a228bd7582a1 measure=memory_pgpgout val=9039 units=pages
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=load_avg_1m val=0.30
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=memory_total val=532.83 units=MB
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=memory_rss val=511.86 units=MB
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=memory_cache val=0.04 units=MB
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=memory_swap val=20.93 units=MB
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=memory_pgpgin val=145460 units=pages
2013-03-21T22:24:25+00:00 heroku[web.2]: source=heroku.13369226.web.2.cb423d08-dd15-41c1-9843-95bcdc269111 measure=memory_pgpgout val=14414 units=pages
2013-03-21T22:24:25+00:00 heroku[web.2]: Process running mem=532M(104.1%)
2013-03-21T22:24:25+00:00 heroku[web.2]: Error R14 (Memory quota exceeded)
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=load_avg_1m val=1.83
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=memory_total val=400.66 units=MB
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=memory_rss val=400.61 units=MB
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=memory_cache val=0.05 units=MB
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=memory_swap val=0.00 units=MB
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=memory_pgpgin val=113336 units=pages
2013-03-21T22:24:29+00:00 heroku[web.4]: source=heroku.13369226.web.4.25274242-a3af-4d2e-9da3-44e5e0a45c09 measure=memory_pgpgout val=10767 units=pages
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=load_avg_1m val=0.25
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=memory_total val=397.70 units=MB
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=memory_rss val=397.64 units=MB
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=memory_cache val=0.05 units=MB
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=memory_swap val=0.00 units=MB
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=memory_pgpgin val=112163 units=pages
2013-03-21T22:24:29+00:00 heroku[web.3]: source=heroku.13369226.web.3.2132f01f-94b1-4151-8fa8-09cdb2774919 measure=memory_pgpgout val=10353 units=pages

- MichaelM

---

你能设置-XX：+HeapDumpOnOutOfMemoryError并收集文件进行分析吗？你是真的遇到了OOM还是违反了某种策略？ - Amir Afghani

实际上，这违反了内存使用限制，正如在Heroku输出中所看到的。 - MichaelM

你无法通过JMX或其他方式连接到你部署的应用程序吗？ - Amir Afghani

不，有一个“路由器”会阻止除端口80之外的任何其他传入连接。这就是为什么这么难调试的原因。我找到了一个简单的Java代理程序，可以将一些内存值转储到日志中，但我无法使其正常工作。我打算再花一个小时左右在这个问题上，并在此更新我的发现。 - MichaelM

你解决了这个问题吗？我们遇到了同样的问题。我们将内存选项修复为使用小写的java_opts，以便选项作为@WearyMonkey正确指出的那样传递给java命令。本以为这样就可以解决问题了，但事实并非如此。我们正在记录JVM内存使用情况，而JVM（显然）没有使用该内存，但在运行压力测试一段时间后仍然会出现R14错误。 - evaneus

Answer 1

我有同样的问题。Heroku告诉你机器的内存不足，而不是Java虚拟机的内存不足。实际上，在Heroku Play 2.2部署中存在一个错误，启动脚本读取java_opts而不是JAVA_OPTS。

我通过设置两者来解决了这个问题：

heroku config:add java_opts='-Xmx384m -Xms384m -Xss512k -XX:+UseCompressedOops'
heroku config:add JAVA_OPTS='-Xmx384m -Xms384m -Xss512k -XX:+UseCompressedOops'

如果不设置-Xms，可能会遇到一个错误，说最小值和最大值不兼容。我猜Play2.2使用的默认值高于384m。

要查找您使用的总内存，这是一个有用的等式（Java 8之前）：

最大内存 = [-Xmx] +[-XX:MaxPermSize]+ 线程数 × [-Xss]

- WearyMonkey

---

那么，真正的答案是如果你在日志中没有收到“OutOfMemoryError”错误，那么这是Heroku在抱怨而不是你的VM？调整VM的设置将使Heroku停止抱怨（并将您的应用程序交换到磁盘）？ - mooreds

是的，R14错误意味着Dyno的内存不足，这通常意味着您为JVM分配了太多的内存。 - WearyMonkey

这意味着根据Heroku的说法，应用程序/ dyno正在被交换到磁盘并且内存不足。但是JVM并不认为如此（这就是为什么您必须指定heapsize参数的原因）。我相信这是正确的。 - mooreds

看到我的回答，你就会明白他为什么超出了内存限制；嗯，因为我在其他有内存限制的系统上也遇到过这个问题（例如 AWS t2.nano 主机）。 - BobMcGee

Answer 2

这篇Heroku开发中心文章中有3个诊断工具可能会有所帮助： https://devcenter.heroku.com/articles/java-memory-issues

看一下内存日志代理、详细GC标志和log-runtime-metrics(https://devcenter.heroku.com/articles/log-runtime-metrics)。这些应该会给你更多的可见性。

- j_simone

---

我已经阅读了这份文档并在本地日志记录中使用了VirtualVM，但这对于Heroku无效。我还使用了heroku-agent，但它不会像上面所述那样转储内存数据。此外，Java标准内存转储属性也不会在stdout上显示任何数据。 - MichaelM

Answer 3

你忘记考虑Permgen（JRE 8之前）或Metaspace（JRE-8+）的内存需求了；这是为Java类信息和某些静态信息保留的内存。除堆外，计划再增加100-150MB的内存，看起来你的内存使用量更高。你可以使用-XX:MaxMetaspaceSize标志来限制它，但要注意，如果超过该限制，将会出现错误。

我也有一个服务器，限制为-Xmx384M，结果发现实际内存使用量也约为500 MB（但在更复杂的应用程序下会更高），考虑到Metaspace的因素。它正在运行一个相当复杂的应用程序（Jenkins），因此Metaspace大小最终达到约170 MB，如果堆达到其极限，则使用554 MB的RAM。

- BobMcGee