-
Bug
-
Resolution: Fixed
-
Medium
-
None
-
None
-
3
-
9223372036854775807
On one of our agent nodes, robinhood operations have stopped unexpectedly.
Live debug has indicated robinhood threads were stuck along with some Lustre threads and users threads doing Lustre I/Os.
We are running with Ubuntu 24.04 6.8.0-137-generic kernel and Lustre client version 2.14.0-ddn257.
Forced crash-dump later analysis has permitted to find that a bunch of threads were either stuck or running on a CPU since hours with very similar stack threads on their top frames like following :
PID: 844852 TASK: ff3b52795e4fafc0 CPU: 9 COMMAND: "robinhood"
#0 [ff4f91054522af68] __schedule at ffffffff8a26151c
#1 [ff4f91054522b010] schedule at ffffffff8a261993
#2 [ff4f91054522b030] schedule_timeout at ffffffff8a268a25
#3 [ff4f91054522b088] schedule_timeout_interruptible at ffffffff8a268b2e
#4 [ff4f91054522b098] kiblnd_pool_alloc_node at ffffffffc1101a1a [ko2iblnd]
#5 [ff4f91054522b0e8] kiblnd_get_idle_tx at ffffffffc110893b [ko2iblnd]
#6 [ff4f91054522b100] kiblnd_send at ffffffffc110fad6 [ko2iblnd]
#7 [ff4f91054522b198] lnet_ni_send at ffffffffc1700e74 [lnet]
#8 [ff4f91054522b1c0] lnet_send at ffffffffc17043b9 [lnet]
#9 [ff4f91054522b1f0] LNetPut at ffffffffc170484d [lnet]
#10 [ff4f91054522b258] ptl_send_buf at ffffffffc1c30fe5 [ptlrpc]
#11 [ff4f91054522b320] ptl_send_rpc at ffffffffc1c33068 [ptlrpc]
#12 [ff4f91054522b438] ptlrpc_send_new_req at ffffffffc1c27fd9 [ptlrpc]
#13 [ff4f91054522b498] ptlrpc_set_wait at ffffffffc1c2d321 [ptlrpc]
#14 [ff4f91054522b520] ptlrpc_queue_wait at ffffffffc1c2d816 [ptlrpc]
#15 [ff4f91054522b540] ldlm_cli_enqueue at ffffffffc1c13f2c [ptlrpc]
#16 [ff4f91054522b5d0] mdc_enqueue_base at ffffffffc22f28a5 [mdc]
#17 [ff4f91054522b6e8] mdc_intent_lock at ffffffffc22f5452 [mdc]
#18 [ff4f91054522b7b8] lmv_intent_lock at ffffffffc21c1796 [lmv]
#19 [ff4f91054522b850] ll_intent_lock at ffffffffc2406ba0 [lustre]
#20 [ff4f91054522b8a0] ll_inode_revalidate.constprop.0 at ffffffffc23c36f0 [lustre]
#21 [ff4f91054522b940] ll_inode_permission at ffffffffc23c3f7e [lustre]
#22 [ff4f91054522b998] inode_permission at ffffffff895090dc
#23 [ff4f91054522b9d0] link_path_walk at ffffffff8950ecf0
#24 [ff4f91054522ba40] path_lookupat at ffffffff8950f99e
#25 [ff4f91054522ba78] filename_lookup at ffffffff89510814
#26 [ff4f91054522bba0] user_path_at_empty at ffffffff89510a8e
#27 [ff4f91054522bbd0] path_getxattr at ffffffff89536efa
#28 [ff4f91054522bc28] __x64_sys_lgetxattr at ffffffff89537051
#29 [ff4f91054522bc38] x64_sys_call at ffffffff8900735e
#30 [ff4f91054522bc48] do_syscall_64 at ffffffff8a252e37
#31 [ff4f91054522bd90] do_syscall_64 at ffffffff8a252e44
#32 [ff4f91054522be88] do_syscall_64 at ffffffff8a252e44
RIP: 00007abe99124f6e RSP: 00007abe96576368 RFLAGS: 00000246
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007abe99124f6e
RDX: 00007abe93c29000 RSI: 00007abe99a1d568 RDI: 00007abe96576370
RBP: 00007abe965773a0 R8: 0000000000000078 R9: 0000000000000000
R10: 0000000000000801 R11: 0000000000000246 R12: 00007abe76406da0
R13: 00007abe93c29000 R14: 00007abe96576370 R15: 0000000000000000
ORIG_RAX: 00000000000000c0 CS: 0033 SS: 002b
PID: 8793 TASK: ff3b52a6ad8e2fc0 CPU: 72 COMMAND: "lhsmd"
#0 [fffffe57ffbbae88] crash_nmi_callback at ffffffff890a79b1
#1 [fffffe57ffbbae98] default_do_nmi at ffffffff8a2557c4
#2 [fffffe57ffbbaec0] exc_nmi at ffffffff8a255a95
#3 [fffffe57ffbbaef0] end_repeat_nmi at ffffffff8a401891
[exception RIP: native_queued_spin_lock_slowpath+698]
RIP: ffffffff8a26ae5a RSP: ff4f9105337def98 RFLAGS: 00000246
RAX: 0000000000000000 RBX: ff3b5277591cb800 RCX: 0000000000000000
RDX: 0000000000000075 RSI: 0000000001d40001 RDI: ff3b5277591cb800
RBP: ff4f9105337defc0 R8: 0000000000000000 R9: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ff3b52a5c0435800
R13: 0000000001240000 R14: ff3b52a5c0f35800 R15: 0000000000000074
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
--- <NMI exception stack> ---
#4 [ff4f9105337def98] native_queued_spin_lock_slowpath at ffffffff8a26ae5a
#5 [ff4f9105337defc8] _raw_spin_lock at ffffffff8a26a96f
#6 [ff4f9105337defd8] kiblnd_pool_alloc_node at ffffffffc1101705 [ko2iblnd]
#7 [ff4f9105337df028] kiblnd_get_idle_tx at ffffffffc110893b [ko2iblnd]
#8 [ff4f9105337df040] kiblnd_send at ffffffffc110fad6 [ko2iblnd]
#9 [ff4f9105337df0d8] lnet_ni_send at ffffffffc1700e74 [lnet]
#10 [ff4f9105337df100] lnet_send at ffffffffc17043b9 [lnet]
#11 [ff4f9105337df130] LNetPut at ffffffffc170484d [lnet]
#12 [ff4f9105337df198] ptl_send_buf at ffffffffc1c30fe5 [ptlrpc]
#13 [ff4f9105337df260] ptl_send_rpc at ffffffffc1c33068 [ptlrpc]
#14 [ff4f9105337df378] ptlrpc_send_new_req at ffffffffc1c27fd9 [ptlrpc]
#15 [ff4f9105337df3d8] ptlrpc_set_wait at ffffffffc1c2d321 [ptlrpc]
#16 [ff4f9105337df460] ptlrpc_queue_wait at ffffffffc1c2d816 [ptlrpc]
#17 [ff4f9105337df480] ldlm_cli_enqueue at ffffffffc1c13f2c [ptlrpc]
#18 [ff4f9105337df510] mdc_enqueue_base at ffffffffc22f28a5 [mdc]
#19 [ff4f9105337df628] mdc_intent_lock at ffffffffc22f5452 [mdc]
#20 [ff4f9105337df6f8] lmv_intent_lock at ffffffffc21c1796 [lmv]
#21 [ff4f9105337df790] ll_intent_lock at ffffffffc2406ba0 [lustre]
#22 [ff4f9105337df7e0] ll_lookup_it at ffffffffc2407558 [lustre]
#23 [ff4f9105337df950] ll_lookup_nd at ffffffffc2409e36 [lustre]
#24 [ff4f9105337dfa00] __lookup_slow at ffffffff89509d42
#25 [ff4f9105337dfa60] walk_component at ffffffff8950eb37
#26 [ff4f9105337dfaa0] link_path_walk at ffffffff8950ee69
#27 [ff4f9105337dfb10] path_lookupat at ffffffff8950f99e
#28 [ff4f9105337dfb48] filename_lookup at ffffffff89510814
#29 [ff4f9105337dfc70] user_path_at_empty at ffffffff89510a8e
#30 [ff4f9105337dfca0] path_setxattr at ffffffff895367db
#31 [ff4f9105337dfe08] __x64_sys_lsetxattr at ffffffff89536978
#32 [ff4f9105337dfe18] x64_sys_call at ffffffff8900744e
#33 [ff4f9105337dfe28] do_syscall_64 at ffffffff8a252e37
RIP: 00000000004086ce RSP: 000000c00042f788 RFLAGS: 00000206
RAX: ffffffffffffffda RBX: 000000c000786d80 RCX: 00000000004086ce
RDX: 000000c0001aef00 RSI: 000000c000858270 RDI: 000000c000786d80
RBP: 000000c00042f7c8 R8: 0000000000000000 R9: 0000000000000000
R10: 0000000000000055 R11: 0000000000000206 R12: 000000c000858270
R13: 0000000000000000 R14: 000000c0004ba000 R15: 0000001fffffffdf
ORIG_RAX: 00000000000000bd CS: 0033 SS: 002b
these threads are simply competing and suffering a side effect of kiblnd_pool_alloc_node() code when a per-cpt kib_poolset's ps_increasing field has been set by an other thread presently allocating a new pool :
struct list_head *
kiblnd_pool_alloc_node(struct kib_poolset *ps)
{
struct list_head *node;
struct kib_pool *pool;
int rc;
unsigned int interval = 1;
ktime_t time_before;
unsigned int trips = 0;
again:
spin_lock(&ps->ps_lock);
list_for_each_entry(pool, &ps->ps_pool_list, po_list) {
if (list_empty(&pool->po_free_list))
continue;
pool->po_allocated++;
pool->po_deadline = ktime_get_seconds() +
IBLND_POOL_DEADLINE;
node = pool->po_free_list.next;
list_del(node);
if (ps->ps_node_init != NULL) {
/* still hold the lock */
ps->ps_node_init(pool, node);
}
spin_unlock(&ps->ps_lock);
return node;
}
/* no available tx pool and ... */
if (ps->ps_increasing) {
/* another thread is allocating a new pool */
spin_unlock(&ps->ps_lock);
trips++;
CDEBUG(D_NET,
"Another thread is allocating new %s pool, waiting %d jiffies for her to complete. trips = %d\n",
ps->ps_name, interval, trips);
schedule_timeout_interruptible(interval);
if (interval < cfs_time_seconds(1))
interval *= 2;
goto again;
}
if (ktime_get_seconds() < ps->ps_next_retry) {
/* someone failed recently */
spin_unlock(&ps->ps_lock);
return NULL;
}
ps->ps_increasing = 1;
spin_unlock(&ps->ps_lock);
CDEBUG(D_NET, "%s pool exhausted, allocate new pool\n", ps->ps_name);
time_before = ktime_get();
rc = ps->ps_pool_create(ps, ps->ps_pool_size, &pool);
CDEBUG(D_NET, "ps_pool_create took %lld ms to complete",
ktime_ms_delta(ktime_get(), time_before));
spin_lock(&ps->ps_lock);
ps->ps_increasing = 0;
if (rc == 0) {
list_add_tail(&pool->po_list, &ps->ps_pool_list);
} else {
ps->ps_next_retry = ktime_get_seconds() + IBLND_POOL_RETRY;
CERROR("Can't allocate new %s pool because out of memory\n",
ps->ps_name);
}
spin_unlock(&ps->ps_lock);
goto again;
}
and by the way each of these threads trips counter is huge !!!
Finally the guilty thread has been found stuck since hours with the following stack :
PID: 5992 TASK: ff3b52a7cca0afc0 CPU: 4 COMMAND: "ptlrpcd_00_51"
#0 [ff4f910525fdae60] __schedule at ffffffff8a26151c
#1 [ff4f910525fdaf08] schedule at ffffffff8a261993
#2 [ff4f910525fdaf28] lov_delete_composite at ffffffffc228cac9 [lov]
#3 [ff4f910525fdafb0] lov_object_delete at ffffffffc228b692 [lov]
#4 [ff4f910525fdafe0] lu_object_free at ffffffffc17e0608 [obdclass]
#5 [ff4f910525fdb038] lu_object_put at ffffffffc17e2301 [obdclass]
#6 [ff4f910525fdb088] cl_object_put at ffffffffc17eadae [obdclass]
#7 [ff4f910525fdb098] cl_inode_fini at ffffffffc2424b48 [lustre]
#8 [ff4f910525fdb110] ll_clear_inode at ffffffffc23e7bf7 [lustre]
#9 [ff4f910525fdb138] ll_delete_inode at ffffffffc23eb334 [lustre]
#10 [ff4f910525fdb150] evict at ffffffff89521cd1
#11 [ff4f910525fdb1d0] prune_icache_sb at ffffffff895238bc
#12 [ff4f910525fdb208] super_cache_scan at ffffffff894fb81e
#13 [ff4f910525fdb260] do_shrink_slab at ffffffff893f4307
#14 [ff4f910525fdb2c8] shrink_slab at ffffffff893f50f5
#15 [ff4f910525fdb330] shrink_one at ffffffff893ee25c
#16 [ff4f910525fdb378] shrink_many at ffffffff893f11ec
#17 [ff4f910525fdb3f0] shrink_node at ffffffff893f1487
#18 [ff4f910525fdb478] shrink_zones.constprop.0 at ffffffff893f26e0
#19 [ff4f910525fdb4d0] do_try_to_free_pages at ffffffff893f2999
#20 [ff4f910525fdb520] try_to_free_pages at ffffffff893f3266
#21 [ff4f910525fdb5c8] __alloc_pages_slowpath.constprop.0 at ffffffff89460320
#22 [ff4f910525fdb660] __alloc_pages at ffffffff89460d0f
#23 [ff4f910525fdb6c8] __alloc_pages_bulk at ffffffff894610f2
#24 [ff4f910525fdb768] __vmalloc_area_node at ffffffff894562b6
#25 [ff4f910525fdb808] __vmalloc_node_range at ffffffff8945669a
#26 [ff4f910525fdb870] __vmalloc_node at ffffffff89455f2e
#27 [ff4f910525fdb898] vzalloc_node at ffffffff89456ade
#28 [ff4f910525fdb8a8] kiblnd_create_tx_pool at ffffffffc11004f4 [ko2iblnd]
#29 [ff4f910525fdb910] kiblnd_pool_alloc_node at ffffffffc1101870 [ko2iblnd]
#30 [ff4f910525fdb960] kiblnd_get_idle_tx at ffffffffc110893b [ko2iblnd]
#31 [ff4f910525fdb978] kiblnd_send at ffffffffc110fad6 [ko2iblnd]
#32 [ff4f910525fdba10] lnet_ni_send at ffffffffc1700e74 [lnet]
#33 [ff4f910525fdba38] lnet_send at ffffffffc17043b9 [lnet]
#34 [ff4f910525fdba68] LNetPut at ffffffffc170484d [lnet]
#35 [ff4f910525fdbad0] ptl_send_buf at ffffffffc1c30fe5 [ptlrpc]
#36 [ff4f910525fdbb98] ptl_send_rpc at ffffffffc1c33068 [ptlrpc]
#37 [ff4f910525fdbcb0] ptlrpc_send_new_req at ffffffffc1c27fd9 [ptlrpc]
#38 [ff4f910525fdbd10] ptlrpc_check_set at ffffffffc1c2a417 [ptlrpc]
#39 [ff4f910525fdbdb0] ptlrpcd_check at ffffffffc1c5de41 [ptlrpc]
#40 [ff4f910525fdbe00] ptlrpcd at ffffffffc1c5e371 [ptlrpc]
#41 [ff4f910525fdbee8] kthread at ffffffff8913f70f
#42 [ff4f910525fdbf28] ret_from_fork at ffffffff8906a754
#43 [ff4f910525fdbf50] ret_from_fork_asm at ffffffff890058eb
where the waited r0->lo_sub[idx] != los condition in inlined lov_delete_raid0()/lov_subobject_kill() has been found still false.
Since kiblnd_create_tx_pool() allocates all what is needed using LIBCFS_CPT_ALLOC() macro, that some of the requested sizes exceed LIBCFS_VMALLOC_SIZE meaning that finally GFP_NOFS will not be used :
/** * allocate \a nr_bytes of virtually contiguous memory that is bound to the * partition id \a cpt. */ static inline void * cfs_cpt_vzalloc(struct cfs_cpt_table *cptab, int cpt, size_t nr_bytes) { /* vzalloc_node() sets __GFP_FS by default but no current Kernel * exported entry-point allows for both a NUMA node specification * and a custom allocation flags mask. This may be an issue since * __GFP_FS usage can cause some deadlock situations in our code, * like when memory reclaim started, within the same context of a * thread doing FS operations, that can also attempt conflicting FS * operations, ... */ return vzalloc_node(nr_bytes, cfs_cpt_spread_node(cptab, cpt)); } /** * allocate memory for specified CPU partition * \a cptab != NULL, \a cpt is CPU partition id of \a cptab * \a cptab == NULL, \a cpt is HW NUMA node id * The allocated memory is zeroed-out. */ #define LIBCFS_CPT_ALLOC_GFP(ptr, cptab, cpt, size, mask) \ do { \ LIBCFS_ALLOC_PRE((size), (mask)); \ (ptr) = (size) <= LIBCFS_VMALLOC_SIZE ? \ cfs_cpt_malloc((cptab), (cpt), (size), (mask) | __GFP_ZERO) : \ cfs_cpt_vzalloc((cptab), (cpt), (size)); \ LIBCFS_ALLOC_POST((ptr), (size)); \ } while (0) /** default numa allocator */ #define LIBCFS_CPT_ALLOC(ptr, cptab, cpt, size) \ LIBCFS_CPT_ALLOC_GFP(ptr, cptab, cpt, size, GFP_NOFS)
so is seems very likely that we have encountered the same dead-lock scenario that is described/expected by the comment in cfs_cpt_vzalloc() above !!!
To fix this, awaiting that a Kernel API will allow us to specify both GFP_NOFS flag along with a NUMA node specification, would it be reasonable (vs performance regression) to use some other non-NUMA aware Kernel entry point like __ll_vmalloc()/vmalloc() ??