为什么我的 Java 应用程序超出 Heroku 内存限制？

Question

我有一个在 heroku 上运行的 Java Web 应用程序，它不断生成“超出内存配额”消息。该应用程序本身很大并且有很多库，但它只收到很少的请求（它只被少数用户使用，所以如果没有用户在线，系统可能几个小时都没有收到一个请求）因此性能不是主要问题。

尽管在我的应用中发生的事情很少，但内存消耗一直很高：

在 heroku 上部署应用程序之前，我使用 docker 容器部署了应用程序，并且从不担心内存设置将所有内容都保留为默认值。整个容器通常消耗大约 300 MB。

我尝试的第一件事是使用-Xmx256m -Xss512k 减少内存消耗，但这似乎没有任何效果。

heroku 手册建议记录一些有关垃圾收集的数据，因此使用以下标志来运行我的应用程序：-Xmx256m -Xss512k -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+UseConcMarkSweepGC。这给了我例如以下输出：

2017-01-11T22:43:39.605180+00:00 heroku[web.1]: Process running mem=588M(106.7%)
2017-01-11T22:43:39.605545+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2017-01-11T22:43:40.431536+00:00 app[web.1]: 2017-01-11T22:43:40.348+0000: [GC (Allocation Failure) 2017-01-11T22:43:40.348+0000: [ParNew
2017-01-11T22:43:40.431566+00:00 app[web.1]: Desired survivor size 4456448 bytes, new threshold 1 (max 6)
2017-01-11T22:43:40.431579+00:00 app[web.1]: - age   1:    7676592 bytes,    7676592 total
2017-01-11T22:43:40.431593+00:00 app[web.1]: - age   2:     844048 bytes,    8520640 total
2017-01-11T22:43:40.431605+00:00 app[web.1]: - age   3:     153408 bytes,    8674048 total
2017-01-11T22:43:40.431772+00:00 app[web.1]: : 72382K->8704K(78656K), 0.0829189 secs] 139087K->78368K(253440K), 0.0830615 secs] [Times: user=0.06 sys=0.00, real=0.08 secs] 
2017-01-11T22:43:41.298146+00:00 app[web.1]: 2017-01-11T22:43:41.195+0000: [GC (Allocation Failure) 2017-01-11T22:43:41.195+0000: [ParNew
2017-01-11T22:43:41.304519+00:00 app[web.1]: Desired survivor size 4456448 bytes, new threshold 1 (max 6)
2017-01-11T22:43:41.304537+00:00 app[web.1]: - age   1:    7271480 bytes,    7271480 total
2017-01-11T22:43:41.304705+00:00 app[web.1]: : 78656K->8704K(78656K), 0.1091697 secs] 148320K->81445K(253440K), 0.1092897 secs] [Times: user=0.10 sys=0.00, real=0.11 secs] 
2017-01-11T22:43:42.589543+00:00 app[web.1]: 2017-01-11T22:43:42.526+0000: [GC (Allocation Failure) 2017-01-11T22:43:42.526+0000: [ParNew
2017-01-11T22:43:42.589562+00:00 app[web.1]: Desired survivor size 4456448 bytes, new threshold 1 (max 6)
2017-01-11T22:43:42.589564+00:00 app[web.1]: - age   1:    6901112 bytes,    6901112 total
2017-01-11T22:43:42.589695+00:00 app[web.1]: : 78656K->8704K(78656K), 0.0632178 secs] 151397K->83784K(253440K), 0.0633208 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
2017-01-11T22:43:57.653300+00:00 heroku[web.1]: Process running mem=587M(106.6%)
2017-01-11T22:43:57.653498+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)

不幸的是，我不是阅读这些日志的专家，但乍一看，该应用程序实际上并没有消耗大量内存，这将是一个问题（或者我是否严重误读了日志？）。

我的Procfile 写着：

web: java $JAVA_OPTS -jar target/dependency/webapp-runner.jar --port $PORT --context-xml context.xml app.war

更新

正如密码指所建议的那样，我 added the Heroku Java agent to my app。由于某种原因，添加 java-agent 后问题不再发生。但现在我有 bean 能够捕捉到这个问题。在以下情况下，除了内存限制仅在短时间内超出：

2017-01-24T10:30:00.143342+00:00 app[web.1]: measure.mem.jvm.heap.used=92M measure.mem.jvm.heap.committed=221M measure.mem.jvm.heap.max=233M
2017-01-24T10:30:00.143399+00:00 app[web.1]: measure.mem.jvm.nonheap.used=77M measure.mem.jvm.nonheap.committed=78M measure.mem.jvm.nonheap.max=0M
2017-01-24T10:30:00.143474+00:00 app[web.1]: measure.threads.jvm.total=41 measure.threads.jvm.daemon=24 measure.threads.jvm.nondaemon=2 measure.threads.jvm.internal=15
2017-01-24T10:30:00.147542+00:00 app[web.1]: measure.mem.linux.vsz=4449M measure.mem.linux.rss=446M

2017-01-24T10:31:00.143196+00:00 app[web.1]: measure.mem.jvm.heap.used=103M measure.mem.jvm.heap.committed=251M measure.mem.jvm.heap.max=251M
2017-01-24T10:31:00.143346+00:00 app[web.1]: measure.mem.jvm.nonheap.used=101M measure.mem.jvm.nonheap.committed=103M measure.mem.jvm.nonheap.max=0M
2017-01-24T10:31:00.143468+00:00 app[web.1]: measure.threads.jvm.total=42 measure.threads.jvm.daemon=25 measure.threads.jvm.nondaemon=2 measure.threads.jvm.internal=15
2017-01-24T10:31:00.153106+00:00 app[web.1]: measure.mem.linux.vsz=4739M measure.mem.linux.rss=503M

2017-01-24T10:31:24.163943+00:00 heroku[web.1]: Process running mem=517M(101.2%)
2017-01-24T10:31:24.164150+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)

2017-01-24T10:32:00.143066+00:00 app[web.1]: measure.mem.jvm.heap.used=108M measure.mem.jvm.heap.committed=248M measure.mem.jvm.heap.max=248M
2017-01-24T10:32:00.143103+00:00 app[web.1]: measure.mem.jvm.nonheap.used=108M measure.mem.jvm.nonheap.committed=110M measure.mem.jvm.nonheap.max=0M
2017-01-24T10:32:00.143173+00:00 app[web.1]: measure.threads.jvm.total=40 measure.threads.jvm.daemon=23 measure.threads.jvm.nondaemon=2 measure.threads.jvm.internal=15
2017-01-24T10:32:00.150558+00:00 app[web.1]: measure.mem.linux.vsz=4738M measure.mem.linux.rss=314M

2017-01-24T10:33:00.142989+00:00 app[web.1]: measure.mem.jvm.heap.used=108M measure.mem.jvm.heap.committed=248M measure.mem.jvm.heap.max=248M
2017-01-24T10:33:00.143056+00:00 app[web.1]: measure.mem.jvm.nonheap.used=108M measure.mem.jvm.nonheap.committed=110M measure.mem.jvm.nonheap.max=0M
2017-01-24T10:33:00.143150+00:00 app[web.1]: measure.threads.jvm.total=40 measure.threads.jvm.daemon=23 measure.threads.jvm.nondaemon=2 measure.threads.jvm.internal=15
2017-01-24T10:33:00.146642+00:00 app[web.1]: measure.mem.linux.vsz=4738M measure.mem.linux.rss=313M

在以下情况下，超出限制的时间要长得多：

2017-01-25T08:14:06.202429+00:00 heroku[web.1]: Process running mem=574M(111.5%)
2017-01-25T08:14:06.202429+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2017-01-25T08:14:26.924265+00:00 heroku[web.1]: Process running mem=574M(111.5%)
2017-01-25T08:14:26.924265+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2017-01-25T08:14:48.082543+00:00 heroku[web.1]: Process running mem=574M(111.5%)
2017-01-25T08:14:48.082615+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2017-01-25T08:15:00.142901+00:00 app[web.1]: measure.mem.jvm.heap.used=164M measure.mem.jvm.heap.committed=229M measure.mem.jvm.heap.max=233M
2017-01-25T08:15:00.142972+00:00 app[web.1]: measure.mem.jvm.nonheap.used=121M measure.mem.jvm.nonheap.committed=124M measure.mem.jvm.nonheap.max=0M
2017-01-25T08:15:00.143019+00:00 app[web.1]: measure.threads.jvm.total=40 measure.threads.jvm.daemon=23 measure.threads.jvm.nondaemon=2 measure.threads.jvm.internal=15
2017-01-25T08:15:00.149631+00:00 app[web.1]: measure.mem.linux.vsz=4740M measure.mem.linux.rss=410M
2017-01-25T08:15:09.339319+00:00 heroku[web.1]: Process running mem=574M(111.5%)
2017-01-25T08:15:09.339319+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2017-01-25T08:15:30.398980+00:00 heroku[web.1]: Process running mem=574M(111.5%)
2017-01-25T08:15:30.399066+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2017-01-25T08:15:51.140193+00:00 heroku[web.1]: Process running mem=574M(111.5%)
2017-01-25T08:15:51.140280+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2017-01-25T08:16:00.143016+00:00 app[web.1]: measure.mem.jvm.heap.used=165M measure.mem.jvm.heap.committed=229M measure.mem.jvm.heap.max=233M
2017-01-25T08:16:00.143084+00:00 app[web.1]: measure.mem.jvm.nonheap.used=121M measure.mem.jvm.nonheap.committed=124M measure.mem.jvm.nonheap.max=0M
2017-01-25T08:16:00.143135+00:00 app[web.1]: measure.threads.jvm.total=40 measure.threads.jvm.daemon=23 measure.threads.jvm.nondaemon=2 measure.threads.jvm.internal=15
2017-01-25T08:16:00.148157+00:00 app[web.1]: measure.mem.linux.vsz=4740M measure.mem.linux.rss=410M

对于后面的日志，这里是更大的图景：

（由于我重新启动了服务器，内存消耗下降了）

在首次超过内存限制时，一个 cron 作业（春季计划）会导入 CSV 文件。 CSV 文件以 10,000 行为单位进行处理，因此内存中引用的行数永远不会超过 10,000 行。尽管如此，由于处理了许多批次，因此总体上当然会消耗大量内存。我还尝试手动触发导入以检查是否可以重现内存消耗峰值，但我不能：这并不总是发生。

Answer 1

这不是一个真正的答案，但可能会有所帮助：

我看起来你的堆外内存消耗激增（或可能泄漏）。来源几乎可以肯定是 CSV 处理。这是一篇描述类似问题的好文章。 http://www.evanjones.ca/java-native-leak-bug.html

Answer 2

如果你已经超过了：

进程运行 mem=574M(111.5%)

也许在您的应用程序中减少到 500 以下是不可能的，我的应用程序遇到了类似的问题，现在我的应用程序在 512MB 下可以正常工作。 您可以尝试其中一些选项（我的 docker 示例）：

ENTRYPOINT ["java","-Dserver.port=$PORT","-Xmx268M","-Xss512K","- 
XX:CICompilerCount=2","-Dfile.encoding=UTF-8","- 
XX:+UseContainerSupport","-Djava.security.egd=file:/dev/./urandom","- 
Xlog:gc","-jar","/app.jar"]

当然，Xmx 值必须与您的情况相匹配（可能更多，也可能更少）