Poison

OutOfMemoryError

关于 JVM 应用的 OOM,首先可以阅读 Oracle 的文档:3.2 Understand the OutOfMemoryError Exception,根据我的经验,大部分都是开发人员的代码问题导致,而关于出现了 OOM 是否应该及时终止应用在 Oracle 的文档中好像也没有明确的说明,但是在 Stack Overflow 上有不少讨论,如:Can the JVM recover from an OutOfMemoryError without a restart,最高票的回答表明 OOM 发生后不是一定要及时终止应用,但是建议终止应用,因为 OOM 后应用可能存在不一致的状态。

从我的经验来看,立即触发的 OOM 异常对线上服务的影响并不大,因为不会阻塞线程,对我们线上服务有影响的主要是 java.lang.OutOfMemoryError: GC Overhead limit exceeded,关于此异常的描述如下:

After a garbage collection, if the Java process is spending more than approximately 98% of its time doing garbage collection and if it is recovering less than 2% of the heap and has been doing so far the last 5 (compile time constant) consecutive garbage collections, then a java.lang.OutOfMemoryError is thrown.

OOM 触发前长时间的 FullGC 导致了应用无响应,从而导致下游请求超时,比如我们线上曾有服务使用 Ehcache 作为应用本地缓存,而未配置本地缓存的内存占用上限,在上线一段时间后,服务先是出现 CPU 升高,在持续很久后触发了 OOM,最后经过堆转储分析,定位原因为 Ehcache 底层用于缓存的 map 几乎占用了所有内存,而业务上的原因为缓存的键设置不合理,导致了缓存了大量利用率低的数据,从而最终触发了 java.lang.OutOfMemoryError: GC Overhead limit exceeded

在我们的线上 JVM 参数配置中,一直包含有这两个参数:-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/shared/heapdump.hprof,用于 OOM 时发起堆转储,且在此基础上我们还集成了用于监控的 Java Agent,会在 OOM 触发的堆转储文件生成后发送告警至监控系统通知开发人员分析 OOM 的原因并进行修复,其实在一段时间内,我为了保证应用的正确性还曾配置过参数 -XX:+ExitOnOutOfMemoryError 上线,但是随后不久即发现问题,即使我们的 docker container 会在 failure 时自动重启,当业务代码存在导致 OOM 的 bug 时,极有可能将线上该组业务的所有实例全部触发 OOM,然后所有实例都在重启,而重启是需要时间的,那么在这段时间内,服务就不可用了,这在互联网的业务中是不可接受的,比如我遇到的一个 tomcat 的 bug: part.getString will cause OOM without checking maxPostSize, checking maxPostSize first will avoid OOM caused by huge string,该 bug 在客户端 POST 了一个巨大的字符串时会导致服务端触发 OOM,这还不是应用开发人员的 bug,而是 tomcat 中存在的,当客户端请求足够多时,就会使整组业务服务器全部 OOM,而如果配置了 -XX:+ExitOnOutOfMemoryError,该组应用在重启期间就不可用了,且如果客户端依然在请求的话,后端 JVM 会陷入 OOM -> 应用终止 -> 应用重启 的循环,所以后期我们又移除掉了 -XX:+ExitOnOutOfMemoryError 配置,回到开始的配置,出现 OOM 后仅发起堆转储,并通知至监控系统,由开发人员定位原因并修复后重新发布应用,在修复问题之前,虽然应用会触发 OOM,但是应用是部分可用的,等于我们在正确性与可用性之间做了 trade off,选择牺牲正确性来保证服务的可用性。

除了 JVM 的 OOM 问题,我们在部分 Linux 机器上还发现因物理内存不足而导致的 Linux oom-killer 将 JVM 进程 kill 掉然后 docker container 重启的问题,该问题起初由定时任务没有被执行的现象暴露出来,随后定位原因为 oom-killer 将 JVM 进程 kill 掉导致,以下是一段 Linux oom-killer kill 掉 JVM 进程的日志:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: aliyun-service invoked oom-killer: gfp_mask=0x14200ca(GFP_HIGHUSER_MOVABLE), nodemask=(null), order=0, oom_score_adj=0
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: aliyun-service cpuset=/ mems_allowed=0
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: CPU: 0 PID: 1191 Comm: aliyun-service Not tainted 4.15.0-139-generic #143-Ubuntu
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Hardware name: Alibaba Cloud Alibaba Cloud ECS, BIOS 8c24b4c 04/01/2014
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Call Trace:
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: dump_stack+0x6d/0x8b
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: dump_header+0x71/0x282
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: oom_kill_process+0x21f/0x450
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: out_of_memory+0x116/0x4e0
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: __alloc_pages_slowpath+0xa53/0xe00
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: __alloc_pages_nodemask+0x29a/0x2c0
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: alloc_pages_current+0x6a/0xe0
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: __page_cache_alloc+0x81/0xa0
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: filemap_fault+0x414/0x730
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: ? filemap_map_pages+0x22d/0x390
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: ext4_filemap_fault+0x31/0x50
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: __do_fault+0x5b/0x111
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: __handle_mm_fault+0xdf1/0x1290
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: handle_mm_fault+0xcc/0x240
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: __do_page_fault+0x281/0x4b0
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: do_page_fault+0x2e/0xe0
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: ? async_page_fault+0x2f/0x50
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: do_async_page_fault+0x51/0x80
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: async_page_fault+0x45/0x50
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: RIP: 0023:0x8049ec0
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: RSP: 002b:000000000a03bf70 EFLAGS: 00010246
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: RAX: 0000000008a7a008 RBX: 0000000005430468 RCX: 00000000b768a268
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: RDX: 000000000004ec93 RSI: 000000000a02c000 RDI: 000000000a00e010
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: RBP: 000000000a03bf68 R08: 0000000000000000 R09: 0000000000000000
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Mem-Info:
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: active_anon:212659 inactive_anon:1247 isolated_anon:0
active_file:12 inactive_file:18 isolated_file:2
unevictable:0 dirty:0 writeback:0 unstable:0
slab_reclaimable:9128 slab_unreclaimable:7572
mapped:5 shmem:1377 pagetables:1369 bounce:0
free:12233 free_pcp:0 free_cma:0
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Node 0 active_anon:850636kB inactive_anon:4988kB active_file:48kB inactive_file:72kB unevictable:0kB isolated(anon):0kB isolated(file)
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Node 0 DMA free:4432kB min:744kB low:928kB high:1112kB active_anon:8784kB inactive_anon:4kB active_file:4kB inactive_file:0kB unevicta
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: lowmem_reserve[]: 0 924 924 924 924
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Node 0 DMA32 free:44500kB min:44308kB low:55384kB high:66460kB active_anon:841852kB inactive_anon:4984kB active_file:48kB inactive_fil
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: lowmem_reserve[]: 0 0 0 0 0
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Node 0 DMA: 91*4kB (UME) 87*8kB (UE) 77*16kB (UME) 33*32kB (UM) 17*64kB (UM) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 4436
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Node 0 DMA32: 624*4kB (UME) 461*8kB (UMEH) 199*16kB (UMEH) 150*32kB (EH) 114*64kB (ME) 80*128kB (UMEH) 28*256kB (UMH) 9*512kB (UMH) 1*
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: 1413 total pagecache pages
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: 0 pages in swap cache
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Swap cache stats: add 0, delete 0, find 0/0
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Free swap = 0kB
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Total swap = 0kB
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: 262014 pages RAM
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: 0 pages HighMem/MovableOnly
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: 9889 pages reserved
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: 0 pages cma reserved
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: 0 pages hwpoisoned
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 232] 0 232 24445 901 212992 0 0 systemd-journal
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 260] 0 260 11654 598 122880 0 -1000 systemd-udevd
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 473] 100 473 20023 185 188416 0 0 systemd-network
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 487] 101 487 17699 176 172032 0 0 systemd-resolve
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 583] 0 583 42599 1945 217088 0 0 networkd-dispat
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 588] 0 588 7832 72 110592 0 0 cron
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 589] 0 589 71882 206 196608 0 0 accounts-daemon
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 592] 0 592 17662 193 176128 0 0 systemd-logind
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 596] 0 596 7085 54 98304 0 0 atd
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 601] 102 601 65761 301 167936 0 0 rsyslogd
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 603] 103 603 12516 160 139264 0 -900 dbus-daemon
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 636] 0 636 189338 5137 266240 0 -999 containerd
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 652] 108 652 26431 119 118784 0 0 chronyd
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 678] 0 678 3991 35 77824 0 0 agetty
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 683] 0 683 4047 33 77824 0 0 agetty
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 748] 0 748 18077 187 180224 0 -1000 sshd
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 924] 0 924 213726 10808 495616 0 -500 dockerd
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 1190] 0 1190 201397 1339 61440 0 0 aliyun-service
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 1411] 0 1411 4452 83 61440 0 0 assist_daemon
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 4283] 0 4283 28344 289 86016 0 -998 containerd-shim
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [ 4308] 0 4308 722971 169001 1974272 0 0 java
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [19972] 0 19972 10662 211 106496 0 0 AliYunDunUpdate
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [20019] 0 20019 38703 4107 335872 0 0 AliYunDun
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: [23809] 0 23809 43124 14200 372736 0 0 AliSecureCheckA
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Out of memory: Kill process 4308 (java) score 672 or sacrifice child
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: Killed process 4308 (java) total-vm:2891884kB, anon-rss:676004kB, file-rss:0kB, shmem-rss:0kB
Jul 02 15:00:57 iZm5ea5suhdnpk1633jyhkZ kernel: oom_reaper: reaped process 4308 (java), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB

关于 Linux oom-killer 的介绍可以参考文章:Linux Out-Of-Memory Killer,大致是说 Linux 内核会在配置启用了 oom-killer 机器上当内存不足时选择一个最的进程进行 kill 以释放内存空间,在选择需要被 kill 的进程时遵循一些规则,如:

  • 内核需要保证自身运行所需的内存
  • 尝试回收大量的内存
  • 不要 kill 掉使用少量内存的进程
  • 尽可能少的 kill 进程
  • 一些细粒度的算法将会提高用户想要杀死的进程的牺牲优先级

根据以上的规则,将计算出各个进程的 oom_score,然后使用该 oom_score 乘以进程占用的内存,最后具有较大值的进程将极有可能会被 oom-killer 终止。

Reference

Understand the OutOfMemoryError Exception
8u92 Update Release Notes
OUTOFMEMORYERROR RELATED JVM ARGUMENTS – HeapHero – Java & Android Heap Dump Analyzer
Chapter 13 Out Of Memory Management
How to Configure the Linux Out-of-Memory Killer
Does JVM terminate itself after OutOfMemoryError - Stack Overflow
HTTPCLIENT-2039 Do not close ConnectionManager in case of Errors - ASF JIRA
OutOfMemoryError