System unable to allocate memory even though memory is available

Question

I'm running Gentoo on my server, and I've just upgraded from kernel 4.4.39 to 4.9.6, with the kernel configuration essentially unchanged. My system log is filling up with error reports such as the following:

[50547.483577] ksoftirqd/0: page allocation failure: order:0, mode:0x2280020(GFP_ATOMIC|__GFP_NOTRACK)
[50547.483605] CPU: 0 PID: 3 Comm: ksoftirqd/0 Not tainted 4.9.6-gentoo-r1 #2
[50547.483608] Hardware name:    /LakePort, BIOS 6.00 PG 02/20/2009
[50547.483613]  f5473bd0 c13e692e c17a9870 00000000 f5473c00 c10d03a7 c17a79dc 02280020
[50547.483626]  f5473c08 f5473c10 c17a9870 f5473be4 f5282d37 00000008 00000000 00000030
[50547.483638]  f5473cbc c10d0769 02280020 c17a9870 00000000 f5473c34 00000000 e5dca054
[50547.483652] Call Trace:
[50547.483670]  [<c13e692e>] dump_stack+0x47/0x69
[50547.483679]  [<c10d03a7>] warn_alloc+0xf7/0x120
[50547.483686]  [<c10d0769>] __alloc_pages_nodemask+0x329/0xb40
[50547.483697]  [<c1107114>] new_slab+0x2a4/0x460
[50547.483704]  [<c1108e62>] ___slab_alloc.constprop.81+0x392/0x540
[50547.483713]  [<c159fe11>] ? __build_skb+0x21/0x100
[50547.483721]  [<c1109027>] __slab_alloc.constprop.80+0x17/0x30
[50547.483727]  [<c11090c2>] kmem_cache_alloc+0x82/0xb0
[50547.483733]  [<c159fe11>] ? __build_skb+0x21/0x100
[50547.483738]  [<c159fe11>] __build_skb+0x21/0x100
[50547.483744]  [<c159ffda>] __netdev_alloc_skb+0x9a/0xe0
[50547.483751]  [<c1017774>] ? nommu_map_page+0x34/0x60
[50547.483771]  [<f81f64be>] e1000_alloc_rx_buffers+0x18e/0x1f0 [e1000e]
[50547.483788]  [<f81f3d54>] e1000_clean_rx_irq+0x244/0x3f0 [e1000e]
[50547.483804]  [<f81fa176>] e1000e_poll+0x96/0x2d0 [e1000e]
[50547.483810]  [<c11098f1>] ? kmem_cache_free_bulk+0x1c1/0x280
[50547.483817]  [<c15ad7ca>] net_rx_action+0x16a/0x270
[50547.483825]  [<c1043df7>] __do_softirq+0xb7/0x1a0
[50547.483832]  [<c169b108>] ? __schedule+0x138/0x510
[50547.483839]  [<c1043ef8>] run_ksoftirqd+0x18/0x40
[50547.483846]  [<c105c01c>] smpboot_thread_fn+0xfc/0x160
[50547.483851]  [<c105bf20>] ? sort_range+0x30/0x30
[50547.483857]  [<c1058ac3>] kthread+0xa3/0xc0
[50547.483863]  [<c1058a20>] ? kthread_park+0x50/0x50
[50547.483868]  [<c169ef43>] ret_from_fork+0x1b/0x28
[50547.483872] Mem-Info:
[50547.483887] active_anon:20896 inactive_anon:4650 isolated_anon:0
                active_file:120066 inactive_file:528731 isolated_file:115
                unevictable:1558 dirty:2365 writeback:0 unstable:0
                slab_reclaimable:135114 slab_unreclaimable:6440
                mapped:16650 shmem:7338 pagetables:452 bounce:0
                free:4552 free_pcp:30 free_cma:0
[50547.483899] Node 0 active_anon:83584kB inactive_anon:18600kB active_file:480264kB inactive_file:2114924kB unevictable:6232kB isolated(anon):0kB isolated(file):460kB mapped:66600kB dirty:9460kB writeback:0kB shmem:29352kB writeback_tmp:0kB unstable:0kB pages_scanned:29 all_unreclaimable? no
[50547.483911] DMA free:3356kB min:68kB low:84kB high:100kB active_anon:0kB inactive_anon:0kB active_file:3360kB inactive_file:0kB unevictable:0kB writepending:16kB present:15988kB managed:15912kB mlocked:0kB slab_reclaimable:8908kB slab_unreclaimable:184kB kernel_stack:8kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[50547.483913] lowmem_reserve[]: 0 834 3265 3265
[50547.483932] Normal free:1376kB min:3660kB low:4572kB high:5484kB active_anon:0kB inactive_anon:0kB active_file:227508kB inactive_file:96kB unevictable:0kB writepending:4104kB present:892920kB managed:855240kB mlocked:0kB slab_reclaimable:531548kB slab_unreclaimable:25576kB kernel_stack:1784kB pagetables:0kB bounce:0kB free_pcp:120kB local_pcp:120kB free_cma:0kB
[50547.483933] lowmem_reserve[]: 0 0 19444 19444
[50547.483951] HighMem free:13476kB min:512kB low:3176kB high:5840kB active_anon:83584kB inactive_anon:18600kB active_file:249396kB inactive_file:2114740kB unevictable:6232kB writepending:5340kB present:2488904kB managed:2488904kB mlocked:6232kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:1808kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[50547.483952] lowmem_reserve[]: 0 0 0 0
[50547.483960] DMA: 17*4kB (UM) 15*8kB (U) 32*16kB (UE) 23*32kB (UME) 14*64kB (UME) 8*128kB (UM) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3356kB
[50547.483989] Normal: 105*4kB (ME) 122*8kB (UM) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1396kB
[50547.484013] HighMem: 2049*4kB (UM) 111*8kB (UM) 25*16kB (UM) 12*32kB (M) 8*64kB (UM) 3*128kB (M) 3*256kB (UM) 4*512kB (M) 0*1024kB 0*2048kB 0*4096kB = 13580kB
[50547.484030] 657546 total pagecache pages
[50547.484030] 0 pages in swap cache
[50547.484030] Swap cache stats: add 0, delete 0, find 0/0
[50547.484030] Free swap  = 0kB
[50547.484030] Total swap = 0kB
[50547.484030] 849453 pages RAM
[50547.484030] 622226 pages HighMem/MovableOnly
[50547.484030] 9439 pages reserved

If I'm reading it correctly, the kernel is trying and failing to allocate a single 4KB page, despite there being 16 MB of totally free memory, and 2+ GB of disk cache that could easily be freed.

Running cat /proc/buddyinfo shows that memory is badly fragmented, but fragmentation shouldn't be an issue when allocating a single page. It might be a symptom of whatever the underlying problem is, though. Any idea what's going on?

Solution

Your problem is shown in this line:

[50547.483932] Normal free:1376kB min:3660kB low:4572kB high:5484kB active_anon:0kB inactive_anon:0kB active_file:227508kB inactive_file:96kB unevictable:0kB writepending:4104kB present:892920kB managed:855240kB mlocked:0kB slab_reclaimable:531548kB slab_unreclaimable:25576kB kernel_stack:1784kB pagetables:0kB bounce:0kB free_pcp:120kB local_pcp:120kB free_cma:0kB

The 2 important values are free and min. The kernel is the only thing allowed to make the system go below the min value. And when that does happen, userspace essentially freezes until it gets back above min. And if the OOM killer is enabled, it's free to start killing processes.

You can use the sysctl param vm.min_free_kbytes to control this.

See this article for a good explanation on the subject.

Comments

[Mark]

Further investigation indicates that I'm probably hitting this kernel bug: OOM but no swap used.

[Mark]

For anyone else who's experiencing this issue, the bug appears to have been fixed somewhere between 4.9.12 and 4.9.18.