Please help interpret OOM-Killer
We were testing our java application and it was killed by the OOM Killer, logs below.
A couple of points: this is a java web application. It runs with a 190G heap. The server is a 240G total memory EC2 instance. We were trying the new, experimental ZGC in JDK 11. At the time the application was not under load, running in a prod-like test env. The application does have some processing that is schedule-triggered and can be memory and CPU intensive, but these run often and have not failed.
The application code has not significantly changed from what we have in production. We have successfully load-tested this as well, including a 12 hour soak test without problem.
Now to the OOM-Killer logs. The full logs are below, but one thing I find very odd is this line:
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
The total vm size is ~ 17 terabytes. This is bizarre to me, as there's no way our app would ever even try to ask for this normally. I suspect maybe we've encountered some ZGC or ZGC+our code bug, but want to make sure I'm reading this right.
I greatly appreciate any help, full logs for reference:
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
Update:
It looks like the 17 TB virtual memory (also visible in top during application run) is not really a problem.
We setup a simple Spring Boot hello world application, with default settings except for ZGC enabled, and the same thing happened. It looks like ZGC allocates 4 TB of address space regardless of heap size, and will also map the same physical address multiple times, so this is, apparently, normal. I can find no one discussing it, which is surprising.
The OOM-Killer appears to be getting involved when we try to shut down the application. Given that we're trying to shut it down anyways, I'm not particularly concerned.
Again, appreciate everyone's assistance.
Out of memory.
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
From the same log (ps);
[ 775.561798] [ 4973] 500 4973 4295425981 2435 71 5 0 0 java
4295425.981 is around 4TB. and the line total-vm:17181703924kB show around a 17TB.
Can you debug your memory allocation routine ? as for me your application got a bad loop somewhere and must take all the ressource available, and the swap available too.
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
Your application process is trying to invoke fallocate on shmem filesystem. From quick googling it looks like ZGC uses fallocate to grab initial heap memory from shm filesystem and proceeds to use fallocate for expanding heap. Such use of fallocate syscall is rather unusual, so either this is a ZGC bug (as you already suspected) or something else is leaking lots of memory, which causes heap expansion to fail.
I suggest, that you configure ZGC to avoid additional runtime allocations (set Xms and Xmx to same value). This might not solve your problem, if the memory leak happens because of something unrelated, but at least you would have a better chance to find the real culprit.
Note, that your overall setup is somewhat dangerous — ZGC apparently likes to have a lot of contiguous memory, but if you have 190G heap on 240G RAM machine, there might not be a sufficiently big contiguous region to fallocate from. In that case ZGC will fall back to picking up small memory regions with further fallocate calls (see description of linked bug report), and the issue will get obscured again... Enable hugepages support in JVM (normal hugepages, not transparent hugepages!) and preallocate hugepages during boot (with kernel argument) — using hugepages is advisable for your heap sizes anyway.