[LU-10133] Multi-page allocation failures in mlx4/mlx5

• Type: Bug
• Resolution: Fixed
• Priority: Major
• Affects Version/s: Lustre 2.11.0
• Labels: soak
• Environment: Soak cluster - lustre-master build 3654 lustre version=2.10.54_13_g84f690e
• Severity: 3
• Assignee: Amir Shehata (Inactive)
• Reporter: Cliff White (Inactive)

Description

I am seeing multiple page allocation failures from soak-clients. Failures seem to be semi-random.
Example:

Oct 17 02:20:07 soak-17 kernel: kworker/u480:1: page allocation failure: order:8, mode:0x80d0
Oct 17 02:20:07 soak-17 kernel: CPU: 9 PID: 58714 Comm: kworker/u480:1 Tainted: G           OE  ------------   3.10.0-693.2.2.el7.x86_64 #1
Oct 17 02:20:07 soak-17 kernel: Hardware name: Intel Corporation S2600GZ ........../S2600GZ, BIOS SE5C600.86B.01.08.0003.022620131521 02/26/2013
Oct 17 02:20:08 soak-17 kernel: Workqueue: rdma_cm cma_work_handler [rdma_cm]
Oct 17 02:20:08 soak-17 kernel: 00000000000080d0 00000000a9e78c95 ffff8803ee9bf848 ffffffff816a3db1
Oct 17 02:20:08 soak-17 kernel: ffff8803ee9bf8d8 ffffffff81188810 0000000000000000 ffff88043ffdb000
Oct 17 02:20:08 soak-17 kernel: 0000000000000008 00000000000080d0 ffff8803ee9bf8d8 00000000a9e78c95
Oct 17 02:20:08 soak-17 kernel: Call Trace:
Oct 17 02:20:08 soak-17 kernel: [<ffffffff816a3db1>] dump_stack+0x19/0x1b
Oct 17 02:20:08 soak-17 kernel: [<ffffffff81188810>] warn_alloc_failed+0x110/0x180
Oct 17 02:20:08 soak-17 kernel: [<ffffffff8169fd8a>] __alloc_pages_slowpath+0x6b6/0x724
Oct 17 02:20:08 soak-17 kernel: [<ffffffff8118cd85>] __alloc_pages_nodemask+0x405/0x420
Oct 17 02:20:08 soak-17 kernel: [<ffffffff81030f8f>] dma_generic_alloc_coherent+0x8f/0x140
Oct 17 02:20:08 soak-17 kernel: [<ffffffff81064341>] x86_swiotlb_alloc_coherent+0x21/0x50
Oct 17 02:20:08 soak-17 kernel: [<ffffffffc02914d3>] mlx4_buf_direct_alloc.isra.6+0xd3/0x1a0 [mlx4_core]
Oct 17 02:20:09 soak-17 kernel: [<ffffffffc029176b>] mlx4_buf_alloc+0x1cb/0x240 [mlx4_core]
Oct 17 02:20:09 soak-17 kernel: [<ffffffffc02940d0>] ? __mlx4_cmd+0x560/0x920 [mlx4_core]
Oct 17 02:20:09 soak-17 kernel: [<ffffffffc061085e>] create_qp_common.isra.31+0x62e/0x10d0 [mlx4_ib]
Oct 17 02:20:09 soak-17 kernel: [<ffffffffc061144e>] mlx4_ib_create_qp+0x14e/0x480 [mlx4_ib]
Oct 17 02:20:09 soak-17 kernel: [<ffffffffc03c9c3a>] ib_create_qp+0x7a/0x2f0 [ib_core]
Oct 17 02:20:09 soak-17 kernel: [<ffffffffc04f66d4>] rdma_create_qp+0x34/0xb0 [rdma_cm]
Oct 17 02:20:09 soak-17 kernel: [<ffffffffc0bd8539>] kiblnd_create_conn+0xbf9/0x1960 [ko2iblnd]
Oct 17 02:20:09 soak-17 kernel: [<ffffffffc0be8649>] kiblnd_cm_callback+0x1429/0x2300 [ko2iblnd]
Oct 17 02:20:09 soak-17 kernel: [<ffffffffc04fa57c>] cma_work_handler+0x6c/0xa0 [rdma_cm]
Oct 17 02:20:09 soak-17 kernel: [<ffffffff810a881a>] process_one_work+0x17a/0x440
Oct 17 02:20:09 soak-17 kernel: [<ffffffff810a94e6>] worker_thread+0x126/0x3c0
Oct 17 02:20:09 soak-17 kernel: [<ffffffff810a93c0>] ? manage_workers.isra.24+0x2a0/0x2a0
Oct 17 02:20:09 soak-17 kernel: [<ffffffff810b098f>] kthread+0xcf/0xe0
Oct 17 02:20:09 soak-17 kernel: [<ffffffff810b08c0>] ? insert_kthread_work+0x40/0x40
Oct 17 02:20:10 soak-17 kernel: [<ffffffff816b4f58>] ret_from_fork+0x58/0x90
Oct 17 02:20:10 soak-17 kernel: [<ffffffff810b08c0>] ? insert_kthread_work+0x40/0x40
Oct 17 02:20:10 soak-17 kernel: Mem-Info:
Oct 17 02:20:10 soak-17 kernel: active_anon:36658 inactive_anon:27590 isolated_anon:6#012 active_file:2710466 inactive_file:345768 isolated_file:10#012 unevictable:0 dirty:14 writeback:0 unstable:0#012 slab_reclaimable:30971 slab_unreclaimable:3983583#012 mapped:10108 shmem:6384 pagetables:3086 bounce:0#012 free:776253 free_pcp:359 free_cma:0
Oct 17 02:20:11 soak-17 kernel: Node 0 DMA free:15784kB min:40kB low:48kB high:60kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15932kB managed:15848kB 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
Oct 17 02:20:11 soak-17 kernel: lowmem_reserve[]: 0 2580 15620 15620
Oct 17 02:20:11 soak-17 kernel: Node 0 DMA32 free:132736kB min:7320kB low:9148kB high:10980kB active_anon:6472kB inactive_anon:8768kB active_file:1063620kB inactive_file:27644kB unevictable:0kB isolated(anon):24kB isolated(file):40kB present:3051628kB managed:2643828kB mlocked:0kB dirty:8kB writeback:0kB mapped:2140kB shmem:116kB slab_reclaimable:9352kB slab_unreclaimable:1306892kB kernel_stack:1152kB pagetables:1196kB unstable:0kB bounce:0kB free_pcp:4kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Oct 17 02:20:11 soak-17 kernel: lowmem_reserve[]: 0 0 13040 13040
Oct 17 02:20:11 soak-17 kernel: Node 0 Normal free:1149812kB min:37012kB low:46264kB high:55516kB active_anon:69848kB inactive_anon:32420kB active_file:4495364kB inactive_file:737992kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:13631488kB managed:13353036kB mlocked:0kB dirty:24kB writeback:0kB mapped:9156kB shmem:248kB slab_reclaimable:54264kB slab_unreclaimable:6303688kB kernel_stack:7248kB pagetables:5096kB unstable:0kB bounce:0kB free_pcp:860kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Oct 17 02:20:12 soak-17 kernel: lowmem_reserve[]: 0 0 0 0
Oct 17 02:20:12 soak-17 kernel: Node 1 Normal free:1805688kB min:45728kB low:57160kB high:68592kB active_anon:70700kB inactive_anon:69172kB active_file:5282880kB inactive_file:617436kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:16777216kB managed:16498508kB mlocked:0kB dirty:24kB writeback:0kB mapped:29136kB shmem:25172kB slab_reclaimable:60268kB slab_unreclaimable:8323752kB kernel_stack:5568kB pagetables:6052kB unstable:0kB bounce:0kB free_pcp:1468kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Oct 17 02:20:13 soak-17 kernel: lowmem_reserve[]: 0 0 0 0
Oct 17 02:20:13 soak-17 kernel: Node 0 DMA: 0*4kB 1*8kB (U) 0*16kB 1*32kB (U) 0*64kB 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15784kB
Oct 17 02:20:13 soak-17 kernel: Node 0 DMA32: 2018*4kB (UEM) 1070*8kB (UEM) 670*16kB (UEM) 685*32kB (UEM) 594*64kB (UEM) 199*128kB (UEM) 80*256kB (M) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 133240kB
Oct 17 02:20:13 soak-17 kernel: Node 0 Normal: 8492*4kB (UEM) 5207*8kB (UEM) 3978*16kB (UEM) 8657*32kB (UEM) 8319*64kB (EM) 1594*128kB (M) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1152744kB
Oct 17 02:20:13 soak-17 kernel: Node 1 Normal: 14583*4kB (UEM) 8566*8kB (UEM) 5482*16kB (UEM) 13112*32kB (UEM) 11765*64kB (UEM) 2443*128kB (UM) 418*256kB (UM) 5*512kB (M) 0*1024kB 0*2048kB 0*4096kB = 1809388kB
Oct 17 02:20:13 soak-17 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Oct 17 02:20:13 soak-17 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Oct 17 02:20:13 soak-17 kernel: Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Oct 17 02:20:14 soak-17 kernel: Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Oct 17 02:20:14 soak-17 kernel: 3062619 total pagecache pages
Oct 17 02:20:14 soak-17 kernel: 6 pages in swap cache
Oct 17 02:20:14 soak-17 kernel: Swap cache stats: add 13, delete 7, find 0/0
Oct 17 02:20:14 soak-17 kernel: Free swap  = 16319432kB
Oct 17 02:20:14 soak-17 kernel: Total swap = 16319484kB
Oct 17 02:20:14 soak-17 kernel: 8369066 pages RAM
Oct 17 02:20:14 soak-17 kernel: 0 pages HighMem/MovableOnly
Oct 17 02:20:14 soak-17 kernel: 241261 pages reserved
Oct 17 02:20:15 soak-17 kernel: kworker/u480:1: page allocation failure: order:8, mode:0x80d0
Oct 17 02:20:15 soak-17 kernel: CPU: 9 PID: 58714 Comm: kworker/u480:1 Tainted: G           OE  ------------   3.10.0-693.2.2.el7.x86_64 #1
Oct 17 02:20:15 soak-17 kernel: Hardware name: Intel Corporation S2600GZ ........../S2600GZ, BIOS SE5C600.86B.01.08.0003.022620131521 02/26/2013
Oct 17 02:20:15 soak-17 kernel: Workqueue: rdma_cm cma_work_handler [rdma_cm]

The systems appear to recover and continue. Lustre-log dump from soak-17 after the most recent failure attached.

Issue Links

• is duplicated by: LU-10322 OSS - memory issues, page allocation failures, crash
• is related to: LU-10736 page allocation failure: order:8, mode:0x80d0

Comments

[Andreas Dilger]

Chris, I believe the problem has been fixed in the upstream kernel, the problem is that users are hitting this regularly on RHEL6/RHEL7 kernels (client and server) with the in-kernel OFED, so it would be good to get a fix for those systems as well.

[Andreas Dilger]

Alexey, did you run any tests with "map_on_demand=32"? I think the default value is 256, but reducing this is important for reducing memory usage.

[Chris Hunter (Inactive)]

We were informed these patches are in mellanox ofed 4.2 GA.

There are similar patches applied to kvzalloc for the mlx5 ethernet driver.

1) mm: introduce kv[mz]alloc helpers
https://lwn.net/Articles/708739/
https://patchwork.kernel.org/patch/9493657/

upstream mlx5 patches were commited May 2017:
2) {net, IB}/mlx5: Replace mlx5_vzalloc with kvzalloc
https://github.com/torvalds/linux/commit/1b9a07ee25049724ab7f7c32282fbf5452530cea#diff-3c967034ac4fb744a569c1a4d3a115d3

and Aug 2017:
3) IB/mlx5: use kvmalloc_array for mlx5_ib_wq
https://github.com/torvalds/linux/commit/b588300801f3502a7de5ca897af68019fbb3bc79#diff-06ae82013eb36f3b0e0eeb9c37040f37
https://www.spinics.net/lists/linux-rdma/msg53756.html

also upstream patch for mlx4:
4) IB/mlx4: use kvmalloc_array to allocate wrid
https://github.com/torvalds/linux/commit/e9105cdefbf64cd7aea300f934c92051e7cb7cff#diff-66b8f4939fabacf90437a794c44b9081
https://www.spinics.net/lists/linux-rdma/msg53441.html

 

[Alexey Lyashkov]

My tests with map_on_demand=256 say 1%-2% perf drop for this case. It's not a big changes i think.

[Amir Shehata (Inactive)]

One thing we should do before making this the default is some performance testing to see how setting map-on-demand to 32 will impact mlx4 and mlx5. It will reduce memory usage per qp, but we need to double check any performance impact.

[Andreas Dilger]

Cliff, the ko2iblnd-opa options are applied for OPA cards only, but the problem affects mlx4 and mlx5 cards, so a separate options ko2iblnd map_on_demand=32 line needs to be added for Mellanox cards. Otherwise, the default is 256.

[Cliff White (Inactive)]

Unfortunately we have been running map_on_demand=32 for quite a while now. At least a year.
So, we can't try that, or maybe better to say we've already tried it and it's not any help.
Current options in ko2iblnd.cof:

options ko2iblnd-opa peer_credits=128 peer_credits_hiw=64 credits=1024 concurrent_sends=256 ntx=2048 map_on_demand=32 fmr_pool_size=2048 fmr_flush_trigger=512 fmr_cache=1

[Andreas Dilger]

Unfortunately, my patch https://review.whamcloud.com/30164 doesn't fix all of the allocation problems here. It also seems that fixes that were added to mlx4_buf_alloc() have not all been added to mlx5_buf_alloc(), which means we may need several other commits to reduce allocation size for mlx5, and at least one small improvement for mlx4.

mlx4:

• add "gfp | __GFP_NOWARN" to the first mlx4_buf_alloc() call in mlx4/qp.c::create_qp_common() so that it doesn't dump a stack on the large-order allocation failure, since there is the fallback to PAGE_SIZE * 2 allocations that should always succeed

mlx5:

• add "max_direct" argument to mlx4_buf_alloc() to allow specifying a chunk size of PAGE_SIZE * 2 and allocate an array of chunks
• 40f2287bd "IB/mlx4: Implement IB_QP_CREATE_USE_GFP_NOIO" equivalent to add gfp argument to mlx5_buf_alloc()
• 73898db04 "net/mlx4: Avoid wrong virtual mappings" equivalent to move mlx5_buf_alloc_node() to mlx5_buf_direct_alloc_node(), and then add the fall back to allocating an array of PAGE_SIZE * 2 pages in mlx5/qp.c::create_qp_common() like mlx4 does
• add "gfp | __GFP_NOWARN" to the first mlx5_buf_alloc() call so that it doesn't dump a stack on the large-order allocation failure

As a workaround, Amir suggests that adding options ko2iblnd map_on_demand=32 in /etc/modprobe.d/ko2iblnd.conf will reduce the size of the QP allocations and will reduce the frequency/severity of this problem.

[Andreas Dilger]

Rick, the https://review.whamcloud.com/30164 patch is definitely for you then. That fixes mlx5 in the same way as mlx4 was fixed for RHEL 7.0-7.4 and RHEL6.x. My original version of the patch also fixed mlx4 for RHEL6.8- but that is already fixed in RHEL 6.9.

[Rick Mohr]

Nov 13 04:23:19 haven-oss1 kernel: warn_alloc_failed: 240 callbacks suppressed
 Nov 13 04:23:19 haven-oss1 kernel: kworker/u32:1: page allocation failure: order:9, mode:0x80d0
 Nov 13 04:23:19 haven-oss1 kernel: CPU: 13 PID: 9120 Comm: kworker/u32:1 Tainted: G OE ------------ 3.10.0-514.el7_lustre.x86_64 #1
 Nov 13 04:23:19 haven-oss1 kernel: Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
 Nov 13 04:23:19 haven-oss1 kernel: Workqueue: rdma_cm cma_work_handler [rdma_cm]
 Nov 13 04:23:19 haven-oss1 kernel: 00000000000080d0 0000000074e4e302 ffff881183c6b810 ffffffff816860f8
 Nov 13 04:23:19 haven-oss1 kernel: ffff881183c6b8a0 ffffffff811869a0 0000000000000000 ffff8816bebd9000
 Nov 13 04:23:19 haven-oss1 kernel: 0000000000000009 00000000000080d0 ffff881183c6b8a0 0000000074e4e302
 Nov 13 04:23:19 haven-oss1 kernel: Call Trace:
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff816860f8>] dump_stack+0x19/0x1b
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff811869a0>] warn_alloc_failed+0x110/0x180
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff81681cb0>] __alloc_pages_slowpath+0x6b7/0x725
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff8118af55>] __alloc_pages_nodemask+0x405/0x420
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff81030fcf>] dma_generic_alloc_coherent+0x8f/0x140
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff81061ed1>] x86_swiotlb_alloc_coherent+0x21/0x50
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffffa0214bfd>] mlx5_dma_zalloc_coherent_node+0xad/0x110 [mlx5_core]
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffffa0214f7d>] mlx5_buf_alloc_node+0x4d/0xc0 [mlx5_core]
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffffa0215004>] mlx5_buf_alloc+0x14/0x20 [mlx5_core]
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffffa044d062>] create_kernel_qp.isra.42+0x292/0x7d0 [mlx5_ib]
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffffa044e1ee>] create_qp_common+0xc4e/0xe00 [mlx5_ib]
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff8119f25a>] ? kvfree+0x2a/0x40
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff8119f25a>] ? kvfree+0x2a/0x40
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff811de2f6>] ? kmem_cache_alloc_trace+0x1d6/0x200
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffffa044e68b>] mlx5_ib_create_qp+0x10b/0x4c0 [mlx5_ib]
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffffa0410a1f>] ib_create_qp+0x3f/0x250 [ib_core]
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffffa03aa584>] rdma_create_qp+0x34/0xb0 [rdma_cm]
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffffa05a3437>] kiblnd_create_conn+0xad7/0x1870 [ko2iblnd]
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffffa05b35f9>] kiblnd_cm_callback+0x1429/0x2290 [ko2iblnd]
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffffa03ae3ac>] cma_work_handler+0x6c/0xa0 [rdma_cm]
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff810a7f3b>] process_one_work+0x17b/0x470
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff810a8d76>] worker_thread+0x126/0x410
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff810a8c50>] ? rescuer_thread+0x460/0x460
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff810b052f>] kthread+0xcf/0xe0
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff810bf8d6>] ? finish_task_switch+0x56/0x180
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff810b0460>] ? kthread_create_on_node+0x140/0x140
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff81696658>] ret_from_fork+0x58/0x90
 Nov 13 04:23:19 haven-oss1 kernel: [<ffffffff810b0460>] ? kthread_create_on_node+0x140/0x140

[Rick Mohr]

Not sure if this is relevant, but I am seeing something very similar on my Lustre servers (Lustre 2.9, CentOS Linux release 7.3.1611, in-kernel IB support, mlx5 driver).