記一次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]