请帮助解释OOM-Killer

Question

我们正在测试我们的java应用程序，它被OOM Killer杀死了，下面是日志。

有几点:这是一个java web应用程序。它以190克堆运行。服务器是一个240克的总内存EC2实例。我们在JDK 11中尝试了新的、实验性的ZGC。当应用程序没有加载时，运行在一个类似prod的测试env中。应用程序确实有一些由计划触发的处理，可以是内存和CPU密集型的，但是这些处理经常运行，而且没有失败。

应用程序代码与我们在生产中的应用程序代码没有明显的变化。我们也成功地对此进行了负载测试，包括12个小时的浸泡测试，没有问题.

现在是OOM-杀手日志。完整的日志在下面，但我发现很奇怪的一件事是这一行：

Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.571217] Killed process 4973 (java) total-vm:17181703924kB, anon-rss:9740kB, file-rss:0kB, shmem-rss:0kB

vm的总大小约为17 17。这对我来说很奇怪，因为我们的应用程序根本不可能正常地要求这样做。我怀疑我们可能遇到了一些ZGC或ZGC+our代码错误，但希望确保我读对了。

我非常感谢任何帮助，完整的日志，以供参考：

Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.158902] java invoked oom-killer: gfp_mask=0x14200ca(GFP_HIGHUSER_MOVABLE), nodemask=(null),  order=0, oom_score_adj=0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.166556] java cpuset=/ mems_allowed=0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.168975] CPU: 15 PID: 4974 Comm: java Not tainted 4.14.55-62.37.amzn1.x86_64 #1
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.173353] Hardware name: Xen HVM domU, BIOS 4.2.amazon 08/24/2006
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.177219] Call Trace:
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.178806]  dump_stack+0x5c/0x82
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.180848]  dump_header+0x94/0x21c
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.183087]  ? get_page_from_freelist+0x525/0xba0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.185945]  oom_kill_process+0x213/0x410
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.188518]  out_of_memory+0x296/0x4c0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.190748]  __alloc_pages_slowpath+0x9ef/0xdd0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.193653]  __alloc_pages_nodemask+0x207/0x220
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.196455]  alloc_pages_vma+0x7c/0x1e0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.198924]  shmem_alloc_page+0x65/0xa0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.201277]  ? __radix_tree_insert+0x35/0x1f0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.204022]  ? __vm_enough_memory+0x23/0x130
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.206639]  shmem_alloc_and_acct_page+0x72/0x1b0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.209513]  shmem_getpage_gfp+0x14b/0xb40
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.212102]  ? __set_page_dirty+0xc0/0xc0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.214705]  shmem_fallocate+0x32d/0x440
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.217182]  vfs_fallocate+0x13f/0x260
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.219525]  SyS_fallocate+0x43/0x80
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.221657]  do_syscall_64+0x67/0x100
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.223944]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.227002] RIP: 0033:0x7fcc064ab1f9
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.229295] RSP: 002b:00007fcc071df800 EFLAGS: 00000246 ORIG_RAX: 000000000000011d
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.233706] RAX: ffffffffffffffda RBX: 0000002f80000000 RCX: 00007fcc064ab1f9
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.237896] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000005
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.242203] RBP: 00007fcc071df860 R08: 0000000000000005 R09: 0000000000000000
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.246538] R10: 0000002f80000000 R11: 0000000000000246 R12: 0000000000001000
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.250675] R13: 0000002f80000000 R14: 00007fcc00030d18 R15: 0000002f80000000
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.254948] Mem-Info:
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.256313] active_anon:46337469 inactive_anon:15816944 isolated_anon:0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.256313]  active_file:362 inactive_file:1424 isolated_file:0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.256313]  unevictable:0 dirty:87 writeback:0 unstable:0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.256313]  slab_reclaimable:146831 slab_unreclaimable:12432
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.256313]  mapped:49788503 shmem:61099090 pagetables:297088 bounce:0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.256313]  free:264623 free_pcp:31 free_cma:0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.276739] Node 0 active_anon:185857908kB inactive_anon:62759744kB active_file:1448kB inactive_file:5696kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:199154012kB dirty:348kB writeback:0kB shmem:244396360kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? yes
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.293799] Node 0 DMA free:15904kB min:4kB low:16kB high:28kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15988kB managed:15904kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.308882] lowmem_reserve[]: 0 1928 245809 245809
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.311710] Node 0 DMA32 free:976000kB min:528kB low:2500kB high:4472kB active_anon:0kB inactive_anon:1017428kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:2080768kB managed:1995880kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.327796] lowmem_reserve[]: 0 0 243881 243881
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.330558] Node 0 Normal free:66588kB min:67048kB low:316780kB high:566512kB active_anon:187190988kB inactive_anon:60409332kB active_file:1448kB inactive_file:5696kB unevictable:0kB writepending:0kB present:253755392kB managed:249734404kB mlocked:0kB kernel_stack:7280kB pagetables:1188352kB bounce:0kB free_pcp:124kB local_pcp:120kB free_cma:0kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.348446] lowmem_reserve[]: 0 0 0 0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.350789] Node 0 DMA: 0*4kB 0*8kB 0*16kB 1*32kB (U) 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15904kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.358404] Node 0 DMA32: 1*4kB (M) 1*8kB (U) 2*16kB (UM) 2*32kB (UE) 1*64kB (U) 1*128kB (U) 2*256kB (UE) 3*512kB (UME) 3*1024kB (UME) 2*2048kB (UM) 236*4096kB (M) = 976172kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.367499] Node 0 Normal: 2527*4kB (UME) 778*8kB (UME) 293*16kB (UME) 104*32kB (UME) 51*64kB (UME) 24*128kB (UME) 5*256kB (UM) 2*512kB (UM) 1*1024kB (U) 3*2048kB (UME) 8*4096kB (M) = 72924kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.377787] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.382919] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.387847] 61100730 total pagecache pages
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.390368] 0 pages in swap cache
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.392264] Swap cache stats: add 0, delete 0, find 0/0
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.395429] Free swap  = 0kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.397195] Total swap = 0kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.398971] 63963037 pages RAM
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.400873] 0 pages HighMem/MovableOnly
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.403102] 1026490 pages reserved
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.405255] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.410245] [ 2730]     0  2730     2833      194      11       3        0         -1000 udevd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.415382] [ 2848]     0  2848     2812      165      10       3        0         -1000 udevd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.420563] [ 2849]     0  2849     2812      161      10       3        0         -1000 udevd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.425740] [ 3137]     0  3137    27285       57      21       3        0             0 lvmetad
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.430993] [ 3146]     0  3146     6799       48      18       3        0             0 lvmpolld
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.436187] [ 3354]     0  3354     2353      121      10       3        0             0 dhclient
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.441499] [ 3410]     0  3410    13251       98      27       3        0         -1000 auditd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.446792] [ 3431]     0  3431    61878      132      23       3        0             0 rsyslogd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.452140] [ 3451]     0  3451    23291      114      15       3        0             0 irqbalance
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.457538] [ 3461]     0  3461     1630       25       9       3        0             0 rngd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.462533] [ 3478]    81  3478     5461       58      15       3        0             0 dbus-daemon
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.468050] [ 3513]     0  3513     1099       35       8       3        0             0 acpid
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.473222] [ 3609]     0  3609    20134      207      42       3        0         -1000 sshd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.478262] [ 3622]     0  3622    28967      266      60       3        0             0 sshd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.483118] [ 3624]   500  3624    28967      265      59       3        0             0 sshd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.488272] [ 3625]   500  3625    28850      113      13       3        0             0 bash
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.493403] [ 3658]    38  3658    29129      204      29       3        0             0 ntpd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.498490] [ 3702]     0  3702    22395      432      45       3        0             0 sendmail
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.503845] [ 3712]    51  3712    20259      374      40       3        0             0 sendmail
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.509091] [ 3724]     0  3724    30411      149      14       3        0             0 crond
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.514018] [ 3738]     0  3738     4797       42      13       3        0             0 atd
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.518902] [ 3773]     0  3773     1090       24       8       3        0             0 mingetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.524491] [ 3775]     0  3775     1627       31       9       3        0             0 agetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.529721] [ 3778]     0  3778     1090       24       8       3        0             0 mingetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.535029] [ 3781]     0  3781     1090       24       8       3        0             0 mingetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.540245] [ 3783]     0  3783     1090       24       8       3        0             0 mingetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.545404] [ 3785]     0  3785     1090       24       8       3        0             0 mingetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.550610] [ 3787]     0  3787     1090       25       8       3        0             0 mingetty
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.556012] [ 4948]   500  4948    28285       60      12       3        0             0 start_server.sh
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.561798] [ 4973]   500  4973 4295425981     2435      71       5        0             0 java
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.566936] Out of memory: Kill process 4973 (java) score 0 or sacrifice child
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.571217] Killed process 4973 (java) total-vm:17181703924kB, anon-rss:9740kB, file-rss:0kB, shmem-rss:0kB
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.578364] oom_reaper: reaped process 4973 (java), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB

更新:看起来17 TB虚拟内存(在应用程序运行期间也可以在top中看到)并不是一个真正的问题。

我们安装了一个简单的应用程序，除了启用了ZGC之外，还有默认设置，同样的事情也发生了。看起来ZGC不考虑堆大小分配4 TB的地址空间，并且会多次映射相同的物理地址，所以这显然是正常的。我发现没有人讨论这件事，这是令人惊讶的。

当我们试图关闭应用程序时，OOM-Killer似乎正在参与进来。考虑到我们无论如何都要关闭它，我并不特别担心。

再次感谢大家的帮助。

Answer 1

内存不足。

12月18日23:24:59 ip-10-0-3-36内核：775.566936内存不足:杀死进程4973 (java)得分0或牺牲孩子

来自同一原木(ps)；

775.561798 500 4973 4295425981 2435 71 5 0 0 java

4295425.981是大约4TB。而行总数-vm:17181703924kB显示了一个17 vm。

您能调试内存分配例程吗？至于我，您的应用程序在某个地方出现了一个糟糕的循环，必须获取所有可用的重新源，以及交换空间。

Answer 2

Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.214705]  shmem_fallocate+0x32d/0x440
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.217182]  vfs_fallocate+0x13f/0x260
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.219525]  SyS_fallocate+0x43/0x80
Dec 18 23:24:59 ip-10-0-3-36 kernel: [  775.221657]  do_syscall_64+0x67/0x100

您的应用程序正在试图在shmem文件系统上调用fallocate。从快速谷歌看来，ZGC使用for来从shm文件系统中获取初始堆内存，并继续使用for来扩展堆。这种错误定位syscall的使用是相当不寻常的，所以这要么是ZGC错误(正如您已经猜到的那样)，要么是其他东西泄漏了大量内存，导致堆扩展失败。

我建议您配置ZGC以避免额外的运行时分配(将Xms和Xmx设置为相同的值)。这可能解决不了你的问题，如果内存泄漏发生是因为一些无关的事情，但至少你有更好的机会找到真正的罪魁祸首。

请注意，您的总体设置有点危险- ZGC显然喜欢拥有大量连续内存，但是如果您在240 g RAM机器上有190 g堆，那么fallocate可能不会有足够大的连续区域。在这种情况下，ZGC将返回到使用进一步的fallocate调用来获取小内存区域(请参阅链接错误报告的描述)，这个问题将再次变得模糊.在JVM中启用hugepages支持(正常的拥抱，而不是透明的拥抱！)并且在引导过程中预先分配hugepage(带有内核参数)--无论如何，使用hugepage对于堆大小来说都是可取的。

Answer 3

因此，这其中的长和短结果是一些本机内存泄漏(即非堆)。我们修补了操作系统，它从实质性的(在几天内就会死掉)变成几乎为零(几个月后就会死)。操作系统补丁注释中有一些关于内存管理的bug修复，但是对于我来说，它的级别太低了，无法了解细节。

仍然有轻微的本机内存泄漏，但不再紧急。我们会继续监视。如果任何补丁进一步解决，我将更新这个答案。