记一次OutOfMemory定位过程

时间 2019-12-15

原文原文链接

背景

最近有个项目部署到了AWS，部署方案是ECS+Docker+Javahtml

Launch type	CPU Units	Memory
FARGATE	1024	4G

运行后发现程序表现不符合预期——每当任务繁忙时大量的task会被关闭并启动新的task，关闭缘由都是OutOfMemory，甚至连2个线程的并发能力都没有。java

Details
---
Status reason | OutOfMemoryError: Container killed due to memory usage
Exit Code | 137

Timeline

找了几个典型的case，首先在AWS上垂手可得地复现此问题，而后把数据移植到本地测试，从jvisualvm中观察JVM heap size却一直十分平稳，没有出现OutOfMemory。因为应用主要承担计算任务并有大量的IO操做，故花了几天时间研究怎么减小IO读写，却一无所得，直到昨天意外发现有段代码输出不符合预期git

private static final int MB_UNIT = 1024 * 1024;
public void scheduleTask() {
    try {
        long freeMemory = Runtime.getRuntime().freeMemory();
        LOGGER.info("start batchCalculation usedMemory={}MB freeMemory={}MB", (Runtime.getRuntime().totalMemory() - freeMemory) / MB_UNIT, freeMemory / MB_UNIT);
        
        ...
        
        freeMemory = Runtime.getRuntime().freeMemory();
        LOGGER.info("finish batchCalculation usedMemory={}MB maxMemory={}MB freeMemory={}MB", (Runtime.getRuntime().totalMemory() - freeMemory) / MB_UNIT, Runtime.getRuntime().maxMemory() / MB_UNIT, freeMemory / MB_UNIT);
    } finally {
        MDC.clear();
    }
}

在AWS跑出的结果github

2018-05-30 09:45:00,000 INFO class=c.m.schedule.ScheduledTasks thread=scheduled-task-pool-1 request_id="24da9c0c-e3e5-451f-8b5d-0898c68252cc" service_name=api event_description="start batchCalculation usedMemory=905MB freeMemory=1982MB"
2018-05-30 09:45:10,016 INFO class=c.m.schedule.ScheduledTasks thread=scheduled-task-pool-1 request_id="24da9c0c-e3e5-451f-8b5d-0898c68252cc" service_name=api event_description="finish batchCalculation usedMemory=905MB maxMemory=6651MB freeMemory=1982MB"

其中maxMemory=6651MB明显超过4G。应用使用的JVM参数以下：docker

-XX:+UnlockExperimentalVMOptions -XX:+UseCGroupMemoryLimitForHeap -XX:MaxRAMFraction=1

若上述参数生效，JVM的heap size为容器最大的可用内存(即~4G)。那么多是JDK版本的问题，为了验证猜测，推送了一个新的image到ECS并运行api

ENTRYPOINT exec java -XX:+UnlockExperimentalVMOptions -XX:+UseCGroupMemoryLimitForHeap -XX:MaxRAMFraction=1 -XshowSettings:vm -version

获得结果以下：并发

VM settings:
Max. Heap Size (Estimated): 6.50G
Ergonomics Machine Class: server
Using VM: OpenJDK 64-Bit Server VM
openjdk version "1.8.0_151"
OpenJDK Runtime Environment (build 1.8.0_151-8u151-b12-1~deb9u1-b12)
OpenJDK 64-Bit Server VM (build 25.151-b12, mixed mode)

从上面的结果可知JDK版本(>1.8.0_131)并无问题。既然JDK版本没有问题，JVM Heap size却不符合预期，那么问题应该是ECS或JVM配置，JVM在扩容时以机器的可用内存(6G)为上限，然而ECS已设置task的内存上限为4G，当任务繁忙时，应用尝试申请超过4G的内存，触发了ECS的内存上限条件致使被关闭。因而尝试使用Xmx/Xms参数限制JVM heap size，修改启动命令并从新推送image和部署app

ENTRYPOINT exec java -Xmx3072m -Xms3072m -XshowSettings:vm -jar app.jar

启动后看到VM设置：jvm

VM settings:
Min. Heap Size: 3.00G
Max. Heap Size: 3.00G
Ergonomics Machine Class: server
Using VM: OpenJDK 64-Bit Server VM

开启4个线程并发运行20分钟后一切如常，没有OutOfMemory。对比之下，显然是由于-XX:+UnlockExperimentalVMOptions -XX:+UseCGroupMemoryLimitForHeap -XX:MaxRAMFraction=1没生效。因而再次加入-XX:+PrintGCDetails -XX:+PrintGCDateStamps看看gc详情测试

ENTRYPOINT exec java -XX:+UnlockExperimentalVMOptions -XX:+UseCGroupMemoryLimitForHeap -XX:MaxRAMFraction=1 -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XshowSettings:vm -jar app.jar

使用上述配置从新部署，在task因OutOfMemory被关闭后根据GC日志能够看到Heap size并无超过4G，因此猜想彷佛又不成立

2018-06-01T02:55:17.775+0000: [GC (Allocation Failure) [PSYoungGen: 1507554K->87211K(1993216K)] 2639108K->1237620K(3393024K), 0.2491182 secs] [Times: user=0.29 sys=0.01, real=0.24 secs]
2018-06-01T02:55:36.307+0000: [GC (Allocation Failure) [PSYoungGen: 1564843K->182611K(2011136K)] 2715252K->1384684K(3410944K), 0.6166316 secs] [Times: user=0.61 sys=0.02, real=0.61 secs]

结语

仍然没有验证出OutOfMemory的真实缘由，但采用Xmx/Xms来控制内存显然是能够解决问题的，后期再跟踪(附后续)。

记一次OutOfMemory定位过程

背景

Timeline

结语

参考资料