search

liyi-ibm / linux

Linux kernel source tree
Other
0 stars 1 forks source link

page allocation stalls #9

Open liyi-ibm opened 5 years ago

liyi-ibm commented 5 years ago

When free memory is low, applications that allocate memory have to wait until some memory is reclaimed. If the delay is greater than 10 seconds, an allocation stall message is printed.

An upstream patch has been identified that should help reduce overhead and latencies. This patch is currently being backported and tested. commit a983b5ebee57209c99f68c8327072f25e0e6e3da Author: Johannes Weiner hannes@cmpxchg.org Date: Wed Jan 31 16:16:45 2018 -0800

mm: memcontrol: fix excessive complexity in memory.stat reporting

liyi-ibm commented 5 years ago

committed above patch (and dependency) as: aa243dd0b96bc4b9b6edcc1b897da9d81cbd1565, 23da7358b6004be24533ce340bfea6ca413b63f6, 848ed2ab5f4969753ec0b3be230827af52ab12ea

liyi-ibm commented 5 years ago

Note: in page allocation stalls we still see many available memory, but the memory cannot be reclaimed.

In another case, there is OOM followed by stall, the stall happens because out-of-memory:

[Wed Dec  5 22:03:18 2018] collect_kprobe.: page allocation stalls for 14860ms, order:0, mode:0x15080c0(GFP_KERNEL_ACCOUNT|__GFP_ZERO), nodemask=(null)
[Wed Dec  5 22:03:18 2018] collect_kprobe. cpuset=/ mems_allowed=0,8
[Wed Dec  5 22:03:18 2018] CPU: 44 PID: 6412 Comm: collect_kprobe. Not tainted 4.14.49-memctrl #1
[Wed Dec  5 22:03:18 2018] Call Trace:
[Wed Dec  5 22:03:18 2018] [c000001fdd04b950] [c000000000ad8b14] dump_stack+0xe8/0x154 (unreliable)
[Wed Dec  5 22:03:18 2018] [c000001fdd04b990] [c00000000028d8a8] warn_alloc+0x128/0x1c0
[Wed Dec  5 22:03:18 2018] [c000001fdd04ba40] [c00000000028e3b4] __alloc_pages_nodemask+0x9e4/0x1080
[Wed Dec  5 22:03:18 2018] [c000001fdd04bc30] [c000000000317140] alloc_pages_current+0xa0/0x130
[Wed Dec  5 22:03:18 2018] [c000001fdd04bc70] [c000000000287cc8] __get_free_pages+0x28/0x90
[Wed Dec  5 22:03:18 2018] [c000001fdd04bc90] [c0000000000f8af0] mm_init+0x150/0x2f0
[Wed Dec  5 22:03:18 2018] [c000001fdd04bcd0] [c0000000000fa738] copy_process.isra.31.part.32+0x9a8/0x19f0
[Wed Dec  5 22:03:18 2018] [c000001fdd04bdc0] [c0000000000fb97c] _do_fork+0xdc/0x4b0
[Wed Dec  5 22:03:18 2018] [c000001fdd04be30] [c00000000000c304] ppc_clone+0x8/0xc
[Wed Dec  5 22:03:18 2018] Mem-Info:
[Wed Dec  5 22:03:18 2018] active_anon:1930707 inactive_anon:1789300 isolated_anon:0
 active_file:144 inactive_file:299 isolated_file:0
 unevictable:0 dirty:0 writeback:157 unstable:0
 slab_reclaimable:47303 slab_unreclaimable:201360
 mapped:639 shmem:526 pagetables:9075 bounce:0
 free:8106 free_pcp:27 free_cma:4524
[Wed Dec  5 22:03:18 2018] Node 0 active_anon:64086656kB inactive_anon:60984640kB active_file:6080kB inactive_file:9600kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:16832kB dirty:0kB writeback:5952kB shmem:33216kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 14336kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
[Wed Dec  5 22:03:18 2018] Node 8 active_anon:59478592kB inactive_anon:53530560kB active_file:3136kB inactive_file:9536kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:24064kB dirty:0kB writeback:4096kB shmem:448kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
[Wed Dec  5 22:03:18 2018] Node 0 DMA free:165056kB min:179712kB low:312896kB high:446080kB active_anon:64086656kB inactive_anon:60984640kB active_file:7552kB inactive_file:4928kB unevictable:0kB writepending:0kB present:134217728kB managed:133227968kB mlocked:0kB kernel_stack:43136kB pagetables:285184kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[Wed Dec  5 22:03:18 2018] lowmem_reserve[]: 0 0 0 0
[Wed Dec  5 22:03:18 2018] Node 8 DMA free:353728kB min:180672kB low:314560kB high:448448kB active_anon:59478592kB inactive_anon:53530560kB active_file:15552kB inactive_file:17280kB unevictable:0kB writepending:0kB present:134217728kB managed:133945792kB mlocked:0kB kernel_stack:107600kB pagetables:295616kB bounce:0kB free_pcp:1728kB local_pcp:0kB free_cma:289536kB
[Wed Dec  5 22:03:18 2018] lowmem_reserve[]: 0 0 0 0
[Wed Dec  5 22:03:18 2018] Node 0 DMA: 2583*64kB (UME) 6*128kB (ME) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB 0*16384kB = 166080kB
[Wed Dec  5 22:03:18 2018] Node 8 DMA: 2980*64kB (UMEC) 352*128kB (MEC) 261*256kB (C) 66*512kB (C) 10*1024kB (C) 2*2048kB (C) 0*4096kB 0*8192kB 0*16384kB = 350720kB
[Wed Dec  5 22:03:18 2018] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[Wed Dec  5 22:03:18 2018] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[Wed Dec  5 22:03:18 2018] Node 8 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[Wed Dec  5 22:03:18 2018] Node 8 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[Wed Dec  5 22:03:18 2018] 2898 total pagecache pages
[Wed Dec  5 22:03:18 2018] 763 pages in swap cache
[Wed Dec  5 22:03:18 2018] Swap cache stats: add 71856, delete 71093, find 26068/42083
[Wed Dec  5 22:03:18 2018] Free swap  = 0kB
[Wed Dec  5 22:03:18 2018] Total swap = 524224kB
[Wed Dec  5 22:03:18 2018] 4194304 pages RAM
[Wed Dec  5 22:03:18 2018] 0 pages HighMem/MovableOnly
[Wed Dec  5 22:03:18 2018] 19714 pages reserved
[Wed Dec  5 22:03:18 2018] 209920 pages cma reserved
[Wed Dec  5 22:03:18 2018] 0 pages hwpoisoned
liyi-ibm commented 5 years ago 

[Wed Dec  5 22:03:19 2018] Node 8 active_anon:59477376kB inactive_anon:53530560kB active_file:27520kB inactive_file:14848kB unevictable:0kB isolated(anon):0kB isolated(file):128kB mapped:30400kB dirty:11264kB writeback:10432kB shmem:448kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no```

Active/inactive file memory is shrunk down to almost nothing, and anon can't be reclaimed because no swap.
Reclaimable slab is a bit bigger, but reclaimable slab doesn't mean it can be reclaimed right now.
Looks pretty out of memory.
liyi-ibm commented 5 years ago

If stall not caused by OOM, there are free swap, and there are many inactive file memory:

Nov 21 14:39:31 tdw-9-10-28-232 kernel: java: page allocation stalls for 16180ms, order:0, mode:0x14200ca(GFP_HIGHUSER_MOVABLE), nodemask=(null)
Nov 21 14:39:31 tdw-9-10-28-232 kernel: java cpuset=/ mems_allowed=0,8
Nov 21 14:39:31 tdw-9-10-28-232 kernel: CPU: 77 PID: 129639 Comm: java Tainted: G        W       4.14.49-3.ppc64le #1
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Call Trace:
Nov 21 14:39:31 tdw-9-10-28-232 kernel: [c00020081ae578f0] [c000000000acb99c] dump_stack+0xb0/0xf4 (unreliable)
Nov 21 14:39:31 tdw-9-10-28-232 kernel: [c00020081ae57930] [c000000000283e28] warn_alloc+0x128/0x1c0
Nov 21 14:39:31 tdw-9-10-28-232 kernel: [c00020081ae579e0] [c000000000284934] __alloc_pages_nodemask+0x9e4/0x1080
Nov 21 14:39:31 tdw-9-10-28-232 kernel: [c00020081ae57bd0] [c00000000030e878] alloc_pages_vma+0xa8/0x2a0
Nov 21 14:39:31 tdw-9-10-28-232 kernel: [c00020081ae57c40] [c0000000002d2730] __handle_mm_fault+0xef0/0x1ee0
Nov 21 14:39:31 tdw-9-10-28-232 kernel: [c00020081ae57d20] [c0000000002d3848] handle_mm_fault+0x128/0x200
Nov 21 14:39:31 tdw-9-10-28-232 kernel: [c00020081ae57d60] [c00000000006498c] __do_page_fault+0x1cc/0x8c0
Nov 21 14:39:31 tdw-9-10-28-232 kernel: [c00020081ae57e30] [c00000000000aca4] handle_page_fault+0x18/0x38
Nov 21 14:39:31 tdw-9-10-28-232 kernel: warn_alloc_show_mem: 4 callbacks suppressed
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Mem-Info:
Nov 21 14:39:31 tdw-9-10-28-232 kernel: active_anon:1420266 inactive_anon:642206 isolated_anon:0#012 active_file:263518 inactive_file:607740 isolated_file:231#012 unevictable:0 dirty:547 writeback:0 unstable:0#012 slab_reclaimable:89790 slab_unreclaimable:182653#012 mapped:2629 shmem:11995 pagetables:6249 bounce:0#012 free:5572 free_pcp:860 free_cma:44
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Node 0 active_anon:44499968kB inactive_anon:19903296kB active_file:7169536kB inactive_file:15138624kB unevictable:0kB isolated(anon):0kB isolated(file):6400kB mapped:105536kB dirty:16128kB writeback:0kB shmem:527488kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Node 8 active_anon:46397056kB inactive_anon:21197888kB active_file:9695616kB inactive_file:23756736kB unevictable:0kB isolated(anon):0kB isolated(file):8384kB mapped:62720kB dirty:18880kB writeback:0kB shmem:240192kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Node 0 DMA free:179584kB min:179712kB low:312896kB high:446080kB active_anon:44461568kB inactive_anon:20003904kB active_file:7169536kB inactive_file:15053248kB unevictable:0kB writepending:4864kB present:134217728kB managed:133228160kB mlocked:0kB kernel_stack:149648kB pagetables:223296kB bounce:0kB free_pcp:26304kB local_pcp:0kB free_cma:0kB
Nov 21 14:39:31 tdw-9-10-28-232 kernel: lowmem_reserve[]: 0 0 0 0
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Node 8 DMA free:177024kB min:180672kB low:314560kB high:448448kB active_anon:46378112kB inactive_anon:21287744kB active_file:9683072kB inactive_file:23644288kB unevictable:0kB writepending:6720kB present:134217728kB managed:133945792kB mlocked:0kB kernel_stack:95584kB pagetables:176640kB bounce:0kB free_pcp:28736kB local_pcp:0kB free_cma:2816kB
Nov 21 14:39:31 tdw-9-10-28-232 kernel: lowmem_reserve[]: 0 0 0 0
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Node 0 DMA: 2126*64kB (UME) 432*128kB (UME) 6*256kB (M) 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB 0*16384kB = 192896kB
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Node 8 DMA: 921*64kB (UMEHC) 834*128kB (UMEHC) 112*256kB (UMH) 0*512kB 0*1024kB 0*2048kB 0*4096kB 0*8192kB 0*16384kB = 194368kB
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Node 8 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Node 8 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Nov 21 14:39:31 tdw-9-10-28-232 kernel: 883380 total pagecache pages
Nov 21 14:39:31 tdw-9-10-28-232 kernel: 1 pages in swap cache
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Swap cache stats: add 2, delete 1, find 0/0
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Free swap  = 524096kB
Nov 21 14:39:31 tdw-9-10-28-232 kernel: Total swap = 524224kB
Nov 21 14:39:31 tdw-9-10-28-232 kernel: 4194304 pages RAM
Nov 21 14:39:31 tdw-9-10-28-232 kernel: 0 pages HighMem/MovableOnly
Nov 21 14:39:31 tdw-9-10-28-232 kernel: 19711 pages reserved
Nov 21 14:39:31 tdw-9-10-28-232 kernel: 209920 pages cma reserved
Nov 21 14:39:31 tdw-9-10-28-232 kernel: 0 pages hwpoisoned