Decoding oom-killer to find the fragmentation

Question

This is a 59GB RAM system that's hitting OOM-Kills with plenty of recoverable memory around. This one is stubborn.

kthreadd invoked oom-killer: gfp_mask=0x26080c0, order=2, oom_score_adj=0
kthreadd cpuset=/ mems_allowed=0
CPU: 3 PID: 2 Comm: kthreadd Not tainted 4.4.0-1083-aws #93-Ubuntu
Hardware name: Xen HVM domU, BIOS 4.2.amazon 08/24/2006
 0000000000000286 ecc5681d66b270c1 ffff880f7b54fad0 ffffffff81407501
 ffff880f7b54fc88 ffff88010f19e040 ffff880f7b54fb40 ffffffff81214a0a
 0000000000000000 ffff880f7884ea80 ffff8804fa62a940 ffff880f7b54fb28
Call Trace:
 [<ffffffff81407501>] dump_stack+0x63/0x82
 [<ffffffff81214a0a>] dump_header+0x5a/0x1c3
 [<ffffffff8139e754>] ? apparmor_capable+0xc4/0x1b0
 [<ffffffff81198f7b>] oom_kill_process+0x20b/0x3d0
 [<ffffffff811993a9>] out_of_memory+0x219/0x460
 [<ffffffff8119f3c3>] __alloc_pages_slowpath.constprop.88+0x943/0xaf0
 [<ffffffff8119f7f8>] __alloc_pages_nodemask+0x288/0x2a0
 [<ffffffff810b803d>] ? attach_task_cfs_rq+0x3d/0x80
 [<ffffffff810a5220>] ? kthread_create_on_node+0x1e0/0x1e0
 [<ffffffff8119f8ab>] alloc_kmem_pages_node+0x4b/0xc0
 [<ffffffff810a5220>] ? kthread_create_on_node+0x1e0/0x1e0
 [<ffffffff81081ab9>] copy_process+0x1d9/0x1c30
 [<ffffffff8183c201>] ? __schedule+0x301/0x810
 [<ffffffff8183c20d>] ? __schedule+0x30d/0x810
 [<ffffffff8183c201>] ? __schedule+0x301/0x810
 [<ffffffff8183c20d>] ? __schedule+0x30d/0x810
 [<ffffffff810836a0>] _do_fork+0x80/0x360
 [<ffffffff8183c241>] ? __schedule+0x341/0x810
 [<ffffffff810839a9>] kernel_thread+0x29/0x30
 [<ffffffff810a5ce8>] kthreadd+0x148/0x190
 [<ffffffff810a5ba0>] ? kthread_create_on_cpu+0x60/0x60
 [<ffffffff81841565>] ret_from_fork+0x55/0x80
 [<ffffffff810a5ba0>] ? kthread_create_on_cpu+0x60/0x60
Mem-Info:
active_anon:6852345 inactive_anon:67572 isolated_anon:0
 active_file:4085952 inactive_file:4062216 isolated_file:32
 unevictable:913 dirty:54748 writeback:25758 unstable:0
 slab_reclaimable:434984 slab_unreclaimable:13452
 mapped:2572311 shmem:164039 pagetables:50287 bounce:0
 free:84572 free_pcp:8 free_cma:0
Node 0 DMA free:15900kB min:16kB low:20kB high:24kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15988kB managed:15900kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
lowmem_reserve[]: 0 1953 61390 61390 61390
Node 0 DMA32 free:255200kB min:2132kB low:2664kB high:3196kB active_anon:1722736kB inactive_anon:0kB active_file:4kB inactive_file:4kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:2080768kB managed:2000228kB mlocked:0kB dirty:0kB writeback:0kB mapped:8kB shmem:0kB slab_reclaimable:16304kB slab_unreclaimable:1292kB kernel_stack:128kB pagetables:3640kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
lowmem_reserve[]: 0 0 59437 59437 59437
Node 0 Normal free:67188kB min:65432kB low:81788kB high:98148kB active_anon:25686644kB inactive_anon:270288kB active_file:16343804kB inactive_file:16248860kB unevictable:3652kB isolated(anon):0kB isolated(file):128kB present:61865984kB managed:60863752kB mlocked:3652kB dirty:218992kB writeback:103032kB mapped:10289236kB shmem:656156kB slab_reclaimable:1723632kB slab_unreclaimable:52516kB kernel_stack:7104kB pagetables:197508kB unstable:0kB bounce:0kB free_pcp:36kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:6116 all_unreclaimable? no
lowmem_reserve[]: 0 0 0 0 0
Node 0 DMA: 1*4kB (U) 1*8kB (U) 1*16kB (U) 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15900kB
Node 0 DMA32: 688*4kB (ME) 522*8kB (UME) 401*16kB (UME) 256*32kB (UM) 147*64kB (UM) 68*128kB (UME) 34*256kB (UME) 18*512kB (UM) 11*1024kB (UME) 7*2048kB (UME) 42*4096kB (M) = 255200kB
Node 0 Normal: 16723*4kB (UMEH) 2*8kB (H) 1*16kB (H) 4*32kB (H) 4*64kB (H) 1*128kB (H) 2*256kB (H) 1*512kB (H) 0*1024kB 0*2048kB 0*4096kB = 68460kB
Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
8312802 total pagecache pages
0 pages in swap cache
Swap cache stats: add 0, delete 0, find 0/0
Free swap  = 0kB
Total swap = 0kB
15990685 pages RAM
0 pages HighMem/MovableOnly
270715 pages reserved
0 pages cma reserved
0 pages hwpoisoned
[ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
[  450]     0   450    36775    25135      75       3        0             0 systemd-journal
[  493]     0   493    25742       45      17       4        0             0 lvmetad
[  522]     0   522    10921     1129      22       3        0         -1000 systemd-udevd
[ 1112]     0  1112     4030      709      11       3        0             0 dhclient
[ 1260]     0  1260     1099      296       8       3        0             0 acpid
[ 1264]     0  1264    68648      596      36       4        0             0 accounts-daemon
[ 1266]     0  1266     1305       28       8       3        0             0 iscsid
[ 1267]     0  1267     1430      877       9       3        0           -17 iscsid
[ 1280]   107  1280    10757      327      25       3        0          -900 dbus-daemon
[ 1291]     0  1291    77264      529      20       3        0             0 lxcfs
[ 1293]     0  1293     6511      396      19       3        0             0 atd
[ 1295]   104  1295    65157     1015      29       4        0             0 rsyslogd
[ 1303]     0  1303     5024      268      14       3        0             0 systemd-logind
[ 1305]     0  1305     6932      506      18       3        0             0 cron
[ 1307]     0  1307   231489     3444      53       6        0             0 amazon-ssm-agen
[ 1344]     0  1344    69278      683      38       4        0             0 polkitd
[ 1406]     0  1406     3343       36      11       3        0             0 mdadm
[ 1468]     0  1468    16378      441      36       3        0         -1000 sshd
[ 1497]     0  1497     4901      283      14       3        0             0 irqbalance
[ 1509]   112  1509    27509      459      26       4        0             0 ntpd
[ 1519]     0  1519     9672      634      23       3        0             0 monit
[ 1637]     0  1637   233876     7156      63      25        0             0 node
[ 3023]     0  3023  1475808   143142     402       9        0             0 java
[ 3117]     0  3117   193826      912      43       4        0             0 collectd
[ 3328]     0  3328     3664      343      11       3        0             0 agetty
[ 3329]     0  3329     3618      392      12       3        0             0 agetty
[ 7107]   114  7107 249623716  9115398   48941     947        0             0 java
[20376]     0 20376   314931    18408     124      34        0             0 node
[20400]     0 20400    36161     1469      50       5        0             0 tsauditd
[20492]     0 20492    77044     8287      52       3        0             0 tsfim
[29823]     0 29823   199481     6601      54       6        0          -900 snapd
Out of memory: Kill process 7107 (java) score 583 or sacrifice child
Killed process 7107 (java) total-vm:998494864kB, anon-rss:26292036kB, file-rss:10168536kB

gfp_mask=0x26080c0 decodes to:

• 2: GFP_KSWAPD_RECLAIM
• 6: GFP_DIRECT_RECLAIM + GFP_NOTRACK
• 0:
• 8: GFP_ZERO
• 0:
• C: GFP_FS + GFP_IO
• 0: Memory zone Normal

Which tells me that the allocation problems are in the Normal memory zone, and I don't have to look at either DMA or DMA32. Nice. Two reclaim flags are used, which should tell the memory allocator to go ahead and reclaim memory to satisfy this request. GFP_FS and GFP_IO might be a hint that this particular request may be mmap somehow, but I can't tell.

The overall Mem-Info shows a system with about 26GB in active_anon memory (active_anon:6852345), plus another 32GBish in active and inactive caches (active_file:4085952 and inactive_file:4062216 respectively) that should be reclaimable. On the surface, this looks like there is plenty of memory to go around, but we still hit the killer. So we're probably facing a fragmentation issue.

Looking at the zone info...

Node 0 Normal
free:67188kB min:65432kB low:81788kB high:98148kB
active_anon:25686644kB inactive_anon:270288kB
active_file:16343804kB inactive_file:16248860kB
unevictable:3652kB isolated(anon):0kB isolated(file):128kB
present:61865984kB managed:60863752kB mlocked:3652kB
dirty:218992kB writeback:103032kB mapped:10289236kB shmem:656156kB
slab_reclaimable:1723632kB slab_unreclaimable:52516kB
kernel_stack:7104kB pagetables:197508kB unstable:0kB
bounce:0kB free_pcp:36kB local_pcp:0kB free_cma:0kB
writeback_tmp:0kB pages_scanned:6116
all_unreclaimable? no

We get numbers pretty close to the top-line Mem-Info numbers. Which is to be expected. The DMA32 zone has some usage in it, but is much smaller than Normal.

Looking at the page-size info for Normal...

Node 0 Normal:
16723*4kB (UMEH)
2*8kB (H)
1*16kB (H)
4*32kB (H)
4*64kB (H)
1*128kB (H)
2*256kB (H)
1*512kB (H)
0*1024kB 0*2048kB 0*4096kB
= 68460kB

(The decodes for the UMEH characters) I suspect my clue is in here, but I'm not seeing it. Nearly all of the memory usage is in the 4kB bucket, which suggests fragmentation. In this case, the DMA32 bucket is actually larger by a fair piece. I guess I don't understand what these lines are telling me.

Are the gfp mask flags indicating this is a memmapped write of some kind?

Where is the fragmentation here?

Answer 1

You were actually really close to running out of memory. This line

Node 0 Normal free:67188kB min:65432kB

tells that the minimum limit is 65432 kB and your system had 67188 kB of free RAM while OOM Killer was triggered.

In addition, it seems that the memory was heavily fragmented because you didn't have the required free blocks (you were asking for the last 16 kB block that the system had) and that triggered another logic in the kernel that may trigger OOM Killer due fragmentation even if you are not below the minimum RAM yet.

The way to avoid this situation is to reduce RAM usage or add swap.

Increasing /proc/sys/vm/extfrag_threshold could reduce fragmentation, too, but you were so close to minimum RAM limit already that it was only a matter of time when OOM Killer gets triggered.

I'd recommend adding a bit of swap (I'm using 1.5 GB of zram as my swap with my 32 GB system with zero normal swap) to allow kernel to relocate pages (it's my understanding that kernel cannot relocate all allocated pages without using swap in the process which increases RAM fragmentation as a result).