[LU-14815] memory issues leading to blocked new connections until drop_cache set Created: 05/Jul/21  Updated: 22/Jul/21

Status: Open
Project: Lustre
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Critical
Reporter: Makia Minich (Inactive) Assignee: Peter Jones
Resolution: Unresolved Votes: 0
Labels: None
Environment:

CentOS 7.8.2003
Kernel – kernel-3.10.0-1062.9.1.el7_lustre.x86_64
Lustre – lustre-2.12.4-1.el7.x86_64
e2fsprogs – e2fsprogs-1.45.6.wc5-0.el7.x86_64
IML – yes

Severity: 3
Rank (Obsolete): 9223372036854775807

 Description   

We have a system with 2 OSS and 2 MDS running community lustre editions with patched kernels. The specs of both OSS nodes are:

  • 2 socket 20 core Xeon Gold 6230 @ 2.1GHz
  • 384GB of RAM
  • single port EDR IB

Under load on the system, we average the following load usage:

[root@oss2 ~]# uptime
{{ 15:54:37 up 7:33, 2 users, load average: 185.68, 161.83, 164.17}}
[root@oss2 ~]# free
{{ total used free shared buff/cache available}}
Mem: 394501208 11600480 21953712 968424 360947016 380784736
Swap: 4194300 8968 4185332
[root@oss2 ~]#

When the system is being utilized we see quite often the following (once the messages start, they continue until either a reboot or an "echo 3 > /proc/sys/vm_drop_caches"):

[Mon Jul 5 15:40:39 2021] kworker/13:0: page allocation failure: order:8, mode:0x80d0
[Mon Jul 5 15:40:39 2021] CPU: 13 PID: 115770 Comm: kworker/13:0 Kdump: loaded Tainted: P OE ------------ 3.10.0-1062.9.1.el7_lustre.x86_64 #1
[Mon Jul 5 15:40:39 2021] Hardware name: Dell Inc. PowerEdge R740/06WXJT, BIOS 2.10.0 11/12/2020
[Mon Jul 5 15:40:39 2021] Workqueue: ib_cm cm_work_handler [ib_cm]
[Mon Jul 5 15:40:39 2021] Call Trace:
[Mon Jul 5 15:40:39 2021] [<ffffffffabf7ac23>] dump_stack+0x19/0x1b
[Mon Jul 5 15:40:39 2021] [<ffffffffab9c3d70>] warn_alloc_failed+0x110/0x180
[Mon Jul 5 15:40:39 2021] [<ffffffffab9c6af0>] ? drain_pages+0xb0/0xb0
[Mon Jul 5 15:40:39 2021] [<ffffffffab9c897f>] __alloc_pages_nodemask+0x9df/0xbe0
[Mon Jul 5 15:40:39 2021] [<ffffffffaba16b28>] alloc_pages_current+0x98/0x110
[Mon Jul 5 15:40:39 2021] [<ffffffffab9c2b1e>] __get_free_pages+0xe/0x40
[Mon Jul 5 15:40:39 2021] [<ffffffffabbadafc>] swiotlb_alloc_coherent+0x5c/0x160
[Mon Jul 5 15:40:39 2021] [<ffffffffab86ead1>] x86_swiotlb_alloc_coherent+0x41/0x50
[Mon Jul 5 15:40:39 2021] [<ffffffffc06d8394>] mlx5_dma_zalloc_coherent_node+0xb4/0x110 [mlx5_core]
[Mon Jul 5 15:40:39 2021] [<ffffffffc06d8c89>] mlx5_buf_alloc_node+0x89/0x120 [mlx5_core]
[Mon Jul 5 15:40:39 2021] [<ffffffffaba674e1>] ? alloc_inode+0x51/0xa0
[Mon Jul 5 15:40:39 2021] [<ffffffffc06d8d34>] mlx5_buf_alloc+0x14/0x20 [mlx5_core]
[Mon Jul 5 15:40:39 2021] [<ffffffffc0d5e63f>] create_kernel_qp.isra.65+0x43a/0x741 [mlx5_ib]
[Mon Jul 5 15:40:39 2021] [<ffffffffc0d48d1c>] create_qp_common+0x8ec/0x17a0 [mlx5_ib]
[Mon Jul 5 15:40:39 2021] [<ffffffffaba25286>] ? kmem_cache_alloc_trace+0x1d6/0x200
[Mon Jul 5 15:40:39 2021] [<ffffffffc0d49d1a>] mlx5_ib_create_qp+0x14a/0x820 [mlx5_ib]
[Mon Jul 5 15:40:39 2021] [<ffffffffab9ddc2d>] ? kvmalloc_node+0x8d/0xe0
[Mon Jul 5 15:40:39 2021] [<ffffffffab9ddc2d>] ? kvmalloc_node+0x8d/0xe0
[Mon Jul 5 15:40:39 2021] [<ffffffffab9ddcb5>] ? kvfree+0x35/0x40
[Mon Jul 5 15:40:39 2021] [<ffffffffc0d411e6>] ? mlx5_ib_create_cq+0x346/0x6f0 [mlx5_ib]
[Mon Jul 5 15:40:39 2021] [<ffffffffc0cbccab>] ib_create_qp+0x8b/0x320 [ib_core]
[Mon Jul 5 15:40:39 2021] [<ffffffffc0d98974>] rdma_create_qp+0x34/0xb0 [rdma_cm]
[Mon Jul 5 15:40:39 2021] [<ffffffffc0a0b85c>] kiblnd_create_conn+0xe5c/0x19b0 [ko2iblnd]
[Mon Jul 5 15:40:39 2021] [<ffffffffaba2630d>] ? kmem_cache_alloc_node_trace+0x11d/0x210
[Mon Jul 5 15:40:39 2021] [<ffffffffc0a1a24c>] kiblnd_passive_connect+0xa2c/0x1760 [ko2iblnd]
[Mon Jul 5 15:40:39 2021] [<ffffffffc0a1b6d5>] kiblnd_cm_callback+0x755/0x23a0 [ko2iblnd]
[Mon Jul 5 15:40:39 2021] [<ffffffffc0d978af>] ? _cma_attach_to_dev+0x5f/0x70 [rdma_cm]
[Mon Jul 5 15:40:39 2021] [<ffffffffc0d9cca0>] cma_ib_req_handler+0xce0/0x12a0 [rdma_cm]
[Mon Jul 5 15:40:39 2021] [<ffffffffc0d87beb>] cm_process_work+0x2b/0x130 [ib_cm]
[Mon Jul 5 15:40:39 2021] [<ffffffffc0d89468>] cm_req_handler+0xaa8/0xf80 [ib_cm]
[Mon Jul 5 15:40:39 2021] [<ffffffffab82b59e>] ? __switch_to+0xce/0x580
[Mon Jul 5 15:40:39 2021] [<ffffffffc0d89d1d>] cm_work_handler+0x15d/0xfcf [ib_cm]
[Mon Jul 5 15:40:39 2021] [<ffffffffabf805a2>] ? __schedule+0x402/0x840
[Mon Jul 5 15:40:39 2021] [<ffffffffab8be21f>] process_one_work+0x17f/0x440
[Mon Jul 5 15:40:39 2021] [<ffffffffab8bf336>] worker_thread+0x126/0x3c0
[Mon Jul 5 15:40:39 2021] [<ffffffffab8bf210>] ? manage_workers.isra.26+0x2a0/0x2a0
[Mon Jul 5 15:40:39 2021] [<ffffffffab8c61f1>] kthread+0xd1/0xe0
[Mon Jul 5 15:40:39 2021] [<ffffffffab8c6120>] ? insert_kthread_work+0x40/0x40
[Mon Jul 5 15:40:39 2021] [<ffffffffabf8dd37>] ret_from_fork_nospec_begin+0x21/0x21
[Mon Jul 5 15:40:39 2021] [<ffffffffab8c6120>] ? insert_kthread_work+0x40/0x40
[Mon Jul 5 15:40:39 2021] Mem-Info:
[Mon Jul 5 15:40:39 2021] active_anon:133507 inactive_anon:148978 isolated_anon:0
{{ active_file:10646819 inactive_file:81974614 isolated_file:0}}
{{ unevictable:19088 dirty:1079 writeback:0 unstable:0}}
{{ slab_reclaimable:1867029 slab_unreclaimable:195034}}
{{ mapped:30616 shmem:229818 pagetables:2598 bounce:0}}
{{ free:1061087 free_pcp:148 free_cma:0}}
[Mon Jul 5 15:40:39 2021] Node 0 DMA free:15896kB min:0kB low:0kB high:0kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15980kB managed:15896kB 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
[Mon Jul 5 15:40:39 2021] lowmem_reserve[]: 0 1281 191724 191724
[Mon Jul 5 15:40:39 2021] Node 0 DMA32 free:762136kB min:296kB low:368kB high:444kB active_anon:16kB inactive_anon:152kB active_file:4548kB inactive_file:4916kB unevictable:216kB isolated(anon):0kB isolated(file):0kB present:1566348kB managed:1312364kB mlocked:216kB dirty:4kB writeback:0kB mapped:216kB shmem:80kB slab_reclaimable:213740kB slab_unreclaimable:38944kB kernel_stack:144kB pagetables:236kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[Mon Jul 5 15:40:39 2021] lowmem_reserve[]: 0 0 190442 190442
[Mon Jul 5 15:40:39 2021] Node 0 Normal free:2062308kB min:44544kB low:55680kB high:66816kB active_anon:111288kB inactive_anon:128592kB active_file:15617196kB inactive_file:169639488kB unevictable:8768kB isolated(anon):0kB isolated(file):0kB present:198180864kB managed:195015992kB mlocked:8768kB dirty:1668kB writeback:0kB mapped:39240kB shmem:126220kB slab_reclaimable:3365336kB slab_unreclaimable:340572kB kernel_stack:14336kB pagetables:4008kB unstable:0kB bounce:0kB free_pcp:420kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[Mon Jul 5 15:40:39 2021] lowmem_reserve[]: 0 0 0 0
[Mon Jul 5 15:40:39 2021] Node 1 Normal free:1404008kB min:45260kB low:56572kB high:67888kB active_anon:422868kB inactive_anon:467168kB active_file:26965532kB inactive_file:158254052kB unevictable:67368kB isolated(anon):0kB isolated(file):0kB present:201326592kB managed:198156940kB mlocked:67368kB dirty:2644kB writeback:0kB mapped:83008kB shmem:792972kB slab_reclaimable:3889040kB slab_unreclaimable:400620kB kernel_stack:20768kB pagetables:6148kB unstable:0kB bounce:0kB free_pcp:216kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[Mon Jul 5 15:40:39 2021] lowmem_reserve[]: 0 0 0 0
[Mon Jul 5 15:40:39 2021] Node 0 DMA: 0*4kB 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) = 15896kB
[Mon Jul 5 15:40:39 2021] Node 0 DMA32: 1512*4kB (UEM) 1277*8kB (UEM) 881*16kB (UEM) 767*32kB (UEM) 720*64kB (UEM) 457*128kB (UEM) 252*256kB (UEM) 155*512kB (UM) 22*1024kB (UEM) 51*2048kB (UE) 81*4096kB (M) = 762104kB
[Mon Jul 5 15:40:39 2021] Node 0 Normal: 5268*4kB (UE) 4145*8kB (UE) 125630*16kB (UEM) 1*32kB (U) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2064344kB
[Mon Jul 5 15:40:39 2021] Node 1 Normal: 57139*4kB (UEM) 5107*8kB (UE) 70991*16kB (UM) 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1405268kB
[Mon Jul 5 15:40:39 2021] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[Mon Jul 5 15:40:39 2021] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[Mon Jul 5 15:40:39 2021] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[Mon Jul 5 15:40:39 2021] Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[Mon Jul 5 15:40:39 2021] 92854017 total pagecache pages
[Mon Jul 5 15:40:39 2021] 86 pages in swap cache
[Mon Jul 5 15:40:39 2021] Swap cache stats: add 520, delete 434, find 402/518
[Mon Jul 5 15:40:39 2021] Free swap = 4185332kB
[Mon Jul 5 15:40:39 2021] Total swap = 4194300kB
[Mon Jul 5 15:40:39 2021] 100272446 pages RAM
[Mon Jul 5 15:40:39 2021] 0 pages HighMem/MovableOnly
[Mon Jul 5 15:40:39 2021] 1647148 pages reserved

I have seen mention in other Jira entries (e.g. LU-10133) versions of the MLNX code perhaps being an issue, this is using the versions of OFED included prebuilt with the Lustre packages.

When the above messages begin to repeat we see an issue where new mounts cannot succeed (they hang at mount). A rebooted compute node (where the filesystem was mounted, then rebooted) will not be able to mount after the reboot until either the OSS nodes are rebooted (going clearing memory and going through recovery) or "echo 3 > /proc/sys/vm/drop_cache" is run.

Currently, all lustre module tunables are default, we had tried with a few different options in hoping to provide better performance but the same issues above occurred.

 Comments   
Comment by Makia Minich (Inactive) [ 05/Jul/21 ]

During this, on the client side we would see the following:

[Mon Jul 5 15:56:39 2021] LNet: 3570:0:(o2iblnd_cb.c:3397:kiblnd_check_conns()) Timed out tx for 172.19.15.7@o2ib: 0 seconds
[Mon Jul 5 15:56:39 2021] LNet: 3570:0:(o2iblnd_cb.c:3397:kiblnd_check_conns()) Skipped 2 previous similar messages
[Mon Jul 5 15:59:54 2021] LNetError: 23802:0:(o2iblnd_cb.c:2957:kiblnd_rejected()) 172.19.15.7@o2ib rejected: o2iblnd no resources

At this point, from the clients view, file operations appear to be working (I was able to df, touch/dd new files, etc) but then attempting to umount or mount caused an "in use" error (with lsof and ps showing now jobs utilizing the filesystem).

Comment by Makia Minich (Inactive) [ 05/Jul/21 ]

I attempted to run a drop_cache on the OSS while system was locked, and immediately while running it, the OSS's dmesg looked to start processing bottlenecked requests:

[Mon Jul 5 16:05:06 2021] Lustre: lustre3p-OST000f: Export ffff90889aaf2c00 already connecting from 172.19.5.98@o2ib
[Mon Jul 5 16:05:06 2021] Lustre: Skipped 1 previous similar message
[Mon Jul 5 16:06:22 2021] Lustre: lustre3p-OST000f: Client ad43237e-1cd2-3183-5c17-fd718830486d (at 172.19.4.231@o2ib) reconnecting
[Mon Jul 5 16:06:22 2021] Lustre: Skipped 104 previous similar messages
[Mon Jul 5 16:06:55 2021] LustreError: 137-5: lustre3p-OST000a_UUID: not available for connect from 172.19.2.49@o2ib (no target). If you are running an HA pair check that the target is mounted on the other server.
[Mon Jul 5 16:06:55 2021] LustreError: Skipped 853 previous similar messages
[Mon Jul 5 16:07:22 2021] Lustre: lustre3p-OST0006: Connection restored to 7f8fbac2-b395-511a-0c54-0db2e0bb9f4b (at 172.19.4.178@o2ib)
[Mon Jul 5 16:07:22 2021] Lustre: Skipped 2624 previous similar messages
[Mon Jul 5 16:07:41 2021] Lustre: 9662:0:(service.c:2165:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (100:5s); client may timeout. req@ffff90463dd80850 x1703551324093056/t0(0) o8->c52b4ac8-56a4-5335-0855-f4c02ca42bf4@172.19.1.70@o2ib:0/0 lens 520/384 e 0 to 0 dl 1625494121 ref 1 fl Complete:/0/0 rc 0/0
[Mon Jul 5 16:07:42 2021] Lustre: 8283:0:(service.c:2165:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (100:21s); client may timeout. req@ffff907f651c7050 x1703549555959744/t0(0) o8->192b6053-7423-c4b1-ecb3-5c1d5b6ce24e@172.19.4.137@o2ib:0/0 lens 520/384 e 0 to 0 dl 1625494107 ref 1 fl Complete:/0/0 rc 0/0
[Mon Jul 5 16:07:42 2021] Lustre: 8283:0:(service.c:2165:ptlrpc_server_handle_request()) Skipped 3 previous similar messages
[Mon Jul 5 16:09:41 2021] Lustre: lustre3p-OST0006: denying duplicate export for 42b2a082-b982-1dae-1423-ee8ad63fe6bc, -114

 

Comment by Peter Jones [ 05/Jul/21 ]

Does the same behaviour exhibit on 2.12.7 RC1?

Comment by Makia Minich (Inactive) [ 05/Jul/21 ]

At the moment I'm unsure as this system is attempting to run in production so changing versions is somewhat limited. Would there be something in 2.12.7 RC1 I should be looking towards moreso than perhaps the latest 2.12.6 version?

Comment by Makia Minich (Inactive) [ 13/Jul/21 ]

We have upgraded the lustre servers to 2.12.6 and continue to see the original reported error. In addition, we're seeing the following intermingled:

[Tue Jul 13 15:05:31 2021] Lustre: lustre3p-OST0008: Connection restored to 2ec09a79-f161-5925-2c1a-06ba4e2425a8 (at 172.19.2.66@o2ib)
[Tue Jul 13 15:05:31 2021] Lustre: Skipped 643 previous similar messages
[Tue Jul 13 15:05:42 2021] Lustre: 12315:0:(service.c:1372:ptlrpc_at_send_early_reply()) @@@ Couldn't add any time (5/5), not sending early reply
{{ req@ffff8dae96cb6050 x1703545892360832/t0(0) o2->d30c2397-6a5e-d86a-b8eb-3c398c7190ad@172.19.1.160@o2ib:74/0 lens 440/432 e 8 to 0 dl 1626181739 ref 2 fl Interpret:/0/0 rc 0/0}}
[Tue Jul 13 15:05:42 2021] Lustre: 12315:0:(service.c:1372:ptlrpc_at_send_early_reply()) Skipped 1 previous similar message
[Tue Jul 13 15:06:20 2021] LustreError: 12383:0:(ldlm_lib.c:3287:target_bulk_io()) @@@ bulk WRITE failed: rc 107 req@ffff8d99924f0850 x1703545892358336/t0(0) o4>d30c2397-6a5e-d86a-b8eb-3c398c7190ad@172.19.1.160@o2ib:229/0 lens 488/448 e 0 to 0 dl 1626181894 ref 1 fl Interpret:/0/0 rc 0/0
[Tue Jul 13 15:06:20 2021] Lustre: lustre3p-OST000e: Bulk IO write error with d30c2397-6a5e-d86a-b8eb-3c398c7190ad (at 172.19.1.160@o2ib), client will retry: rc = -107
[Tue Jul 13 15:06:20 2021] LustreError: 12383:0:(ldlm_lib.c:3287:target_bulk_io()) Skipped 6 previous similar messages
[Tue Jul 13 15:06:20 2021] LNet: Service thread pid 19455 completed after 941.21s. This indicates the system was overloaded (too many service threads, or there were not enough hardware resources).
[Tue Jul 13 15:06:20 2021] LNet: Skipped 1 previous similar message

 

Interesting is the service threads as we've been running with limited threads after seeing this earlier. At the moment we have:

[root@oss1 ~]# lctl get_param ost.OSS.*.threads_started
ost.OSS.ost.threads_started=112
ost.OSS.ost_create.threads_started=24
ost.OSS.ost_io.threads_started=248
ost.OSS.ost_out.threads_started=4
ost.OSS.ost_seq.threads_started=4
[root@oss1 ~]#

 

Comment by Makia Minich (Inactive) [ 13/Jul/21 ]

Unsure if related, a cause, a result, or a different issue but we have also captured the following errors in the logs as well:

[Tue Jul 13 15:15:46 2021] LNet: Service thread pid 12287 was inactive for 1014.41s. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debuggi
ng purposes:
[Tue Jul 13 15:15:46 2021] Pid: 12287, comm: ll_ost01_034 3.10.0-1160.2.1.el7_lustre.x86_64 #1 SMP Wed Dec 9 20:53:35 UTC 2020
[Tue Jul 13 15:15:46 2021] Call Trace:
[Tue Jul 13 15:15:46 2021] [<ffffffffc0682085>] wait_transaction_locked+0x85/0xd0 [jbd2]
[Tue Jul 13 15:15:46 2021] [<ffffffffc0682378>] add_transaction_credits+0x278/0x310 [jbd2]
[Tue Jul 13 15:15:46 2021] [<ffffffffc0682601>] start_this_handle+0x1a1/0x430 [jbd2]
[Tue Jul 13 15:15:46 2021] [<ffffffffc0682cce>] jbd2__journal_restart+0xfe/0x160 [jbd2]
[Tue Jul 13 15:15:46 2021] [<ffffffffc0682d43>] jbd2_journal_restart+0x13/0x20 [jbd2]
[Tue Jul 13 15:15:46 2021] [<ffffffffc1cb23fe>] ldiskfs_truncate_restart_trans+0x4e/0x80 [ldiskfs]
[Tue Jul 13 15:15:46 2021] [<ffffffffc1c683a2>] ldiskfs_ext_truncate_extend_restart+0x42/0x60 [ldiskfs]
[Tue Jul 13 15:15:46 2021] [<ffffffffc1c6bd5a>] ldiskfs_ext_remove_space+0x56a/0x1150 [ldiskfs]
[Tue Jul 13 15:15:46 2021] [<ffffffffc1c6e880>] ldiskfs_ext_truncate+0xb0/0xe0 [ldiskfs]
[Tue Jul 13 15:15:46 2021] [<ffffffffc1cb7967>] ldiskfs_truncate+0x3b7/0x3f0 [ldiskfs]
[Tue Jul 13 15:15:46 2021] [<ffffffffc1cb86ca>] ldiskfs_evict_inode+0x58a/0x630 [ldiskfs]
[Tue Jul 13 15:15:46 2021] [<ffffffffa386c154>] evict+0xb4/0x180
[Tue Jul 13 15:15:46 2021] [<ffffffffa386c58c>] iput+0xfc/0x190
[Tue Jul 13 15:15:46 2021] [<ffffffffc0c280c8>] osd_object_delete+0x1f8/0x370 [osd_ldiskfs]
[Tue Jul 13 15:15:46 2021] [<ffffffffc17f4698>] lu_object_free.isra.32+0x68/0x170 [obdclass]
[Tue Jul 13 15:15:46 2021] [<ffffffffc17f81d5>] lu_object_put+0xc5/0x3e0 [obdclass]
[Tue Jul 13 15:15:46 2021] [<ffffffffc0b26b5e>] ofd_destroy_by_fid+0x20e/0x510 [ofd]
[Tue Jul 13 15:15:46 2021] [<ffffffffc0b1d797>] ofd_destroy_hdl+0x257/0x9d0 [ofd]
[Tue Jul 13 15:15:46 2021] [<ffffffffc1aeaf1a>] tgt_request_handle+0xada/0x1570 [ptlrpc]
[Tue Jul 13 15:15:46 2021] [<ffffffffc1a8f88b>] ptlrpc_server_handle_request+0x24b/0xab0 [ptlrpc]
[Tue Jul 13 15:15:46 2021] [<ffffffffc1a931f4>] ptlrpc_main+0xb34/0x1470 [ptlrpc]
[Tue Jul 13 15:15:46 2021] [<ffffffffa36c5c21>] kthread+0xd1/0xe0
[Tue Jul 13 15:15:46 2021] [<ffffffffa3d93df7>] ret_from_fork_nospec_end+0x0/0x39
[Tue Jul 13 15:15:46 2021] [<ffffffffffffffff>] 0xffffffffffffffff
[Tue Jul 13 15:15:46 2021] LustreError: dumping log to /tmp/lustre-log.1626182339.12287
[Tue Jul 13 15:15:46 2021] LustreError: 12397:0:(tgt_grant.c:758:tgt_grant_check()) lustre3p-OST000e: cli eaa76b78-0728-7cc7-0fc0-9aa3218a1a41 claims 9076736 GRANT, real grant 0
[Tue Jul 13 15:16:01 2021] Lustre: 12301:0:(service.c:2165:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (100:30s); client may timeout. req@ffff8dcef0976050 x1704649368
564480/t0(0) o8->aecbb3c1-bc2b-9f53-4e37-e2efc6ef0638@172.19.4.220@o2ib:0/0 lens 520/384 e 0 to 0 dl 1626182324 ref 1 fl Complete:/0/0 rc 0/0
[Tue Jul 13 15:16:01 2021] Lustre: 12301:0:(service.c:2165:ptlrpc_server_handle_request()) Skipped 5 previous similar messages
[Tue Jul 13 15:17:24 2021] LustreError: 12712:0:(tgt_grant.c:758:tgt_grant_check()) lustre3p-OST000e: cli eaa76b78-0728-7cc7-0fc0-9aa3218a1a41 claims 9076736 GRANT, real grant 7868416
[Tue Jul 13 15:17:24 2021] LustreError: 12712:0:(tgt_grant.c:758:tgt_grant_check()) Skipped 1 previous similar message

Comment by Etienne Aujames [ 22/Jul/21 ]

Hello,

Sorry to interfere here.

You seem to be missing the following commit on your MOFED:
34f4c9554d8b2a7d2deb9503e9373b598ee3279f: IB/mlx5: Use fragmented QP's buffer for in-kernel users

mlx5_frag_buf_alloc_node should be used instead of mlx5_buf_alloc_node.

MOFED 4.7 should have this symbol (in kmod-mlnx-ofa_kernel.x86_64 rpm).

Comment by Makia Minich (Inactive) [ 22/Jul/21 ]

It does look like that patch is missing from all kernel options from the community release. I'm looking at the patch and options to try it on this system. Thank you for that link.

Generated at Sat Feb 10 09:29:48 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.