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