Am Montag, dem 09.06.2025 um 13:37 +0200 schrieb Bert Karwatzki:
> Am Sonntag, dem 08.06.2025 um 17:53 +0200 schrieb Bert Karwatzki:
> > Am Sonntag, dem 08.06.2025 um 10:45 +0200 schrieb Bert Karwatzki:
> > > Am Donnerstag, dem 05.06.2025 um 14:51 +0200 schrieb Sebastian Andrzej Siewior:
> > > > On 2025-06-05 08:48:38 [-0400], Steven Rostedt wrote:
> > > > > On Thu, 5 Jun 2025 11:19:03 +0200
> > > > > Bert Karwatzki <spasswolf@xxxxxx> wrote:
> > > > >
> > > > > > This patch seems to create so much output that the orginal error message and
> > > > > > backtrace often get lost, so I needed several runs to get a meaningful message
> > > > > > when running
> > > > >
> > > > > Are you familiar with preempt count tracing?
> > > >
> > > > I have an initial set of patches to tackle this problem, I'm going to
> > > > send them after the merge window.
> > > >
> > > > Sebastian
> > >
> > > I've found the reason for the "mysterious" increase of preempt_count:
> > >
> > > [ 70.821750] [ T2746] bpf_link_settle calling fd_install() preemt_count = 0
> > > [ 70.821751] [ T2746] preempt_count_add 5898: preempt_count = 0x0 counter = 0x1b232c
> > > [ 70.821752] [ T2746] preempt_count_add 5900: preempt_count = 0x1 counter = 0x1b232d
> > > [ 70.821754] [ T2746] preempt_count_sub 5966: preempt_count = 0x1 counter = 0x1b232e
> > > [ 70.821755] [ T2746] preempt_count_sub 5968: preempt_count = 0x0 counter = 0x1b232f
> > > [ 70.821761] [ T2746] __bpf_trace_sys_enter 18: preempt_count = 0x0
> > > [ 70.821762] [ T2746] __bpf_trace_sys_enter 18: preempt_count = 0x1
> > > [ 70.821764] [ T2746] __bpf_trace_run: preempt_count = 1
> > > [ 70.821765] [ T2746] bpf_prog_run: preempt_count = 1
> > > [ 70.821766] [ T2746] __bpf_prog_run: preempt_count = 1
> > >
> > > It's caused by this macro from include/trace/bpf_probe.h (with my pr_err()):
> > >
> > > #define __BPF_DECLARE_TRACE_SYSCALL(call, proto, args) \
> > > static notrace void \
> > > __bpf_trace_##call(void *__data, proto) \
> > > { \
> > > might_fault(); \
> > > if (!strcmp(get_current()->comm, "test_progs")) \
> > > pr_err("%s %d: preempt_count = 0x%x", __func__, __LINE__, preempt_count());\
> > > preempt_disable_notrace(); \
> > > if (!strcmp(get_current()->comm, "test_progs")) \
> > > pr_err("%s %d: preempt_count = 0x%x", __func__, __LINE__, preempt_count());\
> > > CONCATENATE(bpf_trace_run, COUNT_ARGS(args))(__data, CAST_TO_U64(args)); \
> > > preempt_enable_notrace(); \
> > > }
> > >
> > > The preempt_{en,dis}able_notrace were introduced in
> > > commit 4aadde89d81f ("tracing/bpf: disable preemption in syscall probe")
> > > This commit is present in v6.14 and v6.15, but the bug already appears in
> > > v6.12 so in that case preemption is disable somewhere else.
> > >
> > > Bert Karwatzki
> >
> > After reading this
> > https://lore.kernel.org/bpf/CAADnVQJf535hwud5XtQKStOge9=pYVYWSiq_8Q2YAvN5rba==A@xxxxxxxxxxxxxx/
> > I tried using migrate_{en,disable} like this (in v6.15)
> >
> > diff --git a/include/trace/bpf_probe.h b/include/trace/bpf_probe.h
> > index 183fa2aa2935..49257cb90209 100644
> > --- a/include/trace/bpf_probe.h
> > +++ b/include/trace/bpf_probe.h
> > @@ -58,9 +58,9 @@ static notrace void \
> > __bpf_trace_##call(void *__data, proto) \
> > { \
> > might_fault(); \
> > - preempt_disable_notrace(); \
> > + migrate_disable(); \
> > CONCATENATE(bpf_trace_run, COUNT_ARGS(args))(__data, CAST_TO_U64(args)); \
> > - preempt_enable_notrace(); \
> > + migrate_enable(); \
> > }
> >
> > #undef DECLARE_EVENT_SYSCALL_CLASS
> > diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
> > index 187dc37d61d4..ec0326405fc3 100644
> > --- a/kernel/trace/bpf_trace.c
> > +++ b/kernel/trace/bpf_trace.c
> > @@ -2350,7 +2350,7 @@ void __bpf_trace_run(struct bpf_raw_tp_link *link, u64 *args)
> > struct bpf_run_ctx *old_run_ctx;
> > struct bpf_trace_run_ctx run_ctx;
> >
> > - cant_sleep();
> > + cant_migrate();
> > if (unlikely(this_cpu_inc_return(*(prog->active)) != 1)) {
> > bpf_prog_inc_misses_counter(prog);
> > goto out;
> > diff --git a/tools/testing/selftests/bpf/progs/dynptr_success.c b/tools/testing/selftests/bpf/progs/dynptr_success.c
> > index e1fba28e4a86..7cfb9473a526 100644
> > --- a/tools/testing/selftests/bpf/progs/dynptr_success.c
> > +++ b/tools/testing/selftests/bpf/progs/dynptr_success.c
> > @@ -7,6 +7,7 @@
> > #include <bpf/bpf_helpers.h>
> > #include <bpf/bpf_tracing.h>
> > #include "bpf_misc.h"
> > +#include "bpf_kfuncs.h"
> > #include "errno.h"
> >
> > char _license[] SEC("license") = "GPL";
> >
> >
> > This fixes the warnings when running the bpf cgroup examples:
> >
> > ./test_progs -a "cgrp_local_storage/cgrp1*"
> >
> > but I still get a warning from another example (I don't know which, yet):
> >
> > Bert Karwatzki
>
> Another of the bpf selftests that gives a warning with PREEMPT_RT=y (for calling spinlock
> with preemption disabled) is
>
> $ ./test_progs -a wq
>
> giving this warning:
>
> [ T3576] BUG: sleeping function called from invalid context at kernel/locking/spinlock_rt.c:48
> [ T3576] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 3576, name: test_progs
> [ T3576] preempt_count: 1, expected: 0
> [ T3576] RCU nest depth: 3, expected: 3
> [ T3576] 6 locks held by test_progs/3576:
> [ T3576] #0: ffffffffa1131300 (rcu_read_lock){....}-{1:3}, at: bpf_test_timer_enter+0x1e/0xc0
> [ T3576] #1: ffffffffa109acc0 (local_bh){.+.+}-{1:3}, at: __local_bh_disable_ip+0x29/0x1c0
> [ T3576] #2: ffff997b0e7d78b8 ((softirq_ctrl.lock)){+.+.}-{3:3}, at: __local_bh_disable_ip+0xc8/0x1c0
> [ T3576] #3: ffffffffa1131300 (rcu_read_lock){....}-{1:3}, at: rt_spin_lock+0xf0/0x190
> [ T3576] #4: ffffffffa1131300 (rcu_read_lock){....}-{1:3}, at: __local_bh_disable_ip+0x29/0x1c0
> [ T3576] #5: ffff997b0e7f4588 ((&c->lock)){+.+.}-{3:3}, at: ___slab_alloc+0x68/0xde0
> [ T3576] irq event stamp: 247437
> [ T3576] hardirqs last enabled at (247435): [<ffffffffa05b5fa7>] _raw_spin_unlock_irqrestore+0x57/0x80
> [ T3576] hardirqs last disabled at (247437): [<ffffffff9fbbc57b>] __bpf_async_init+0xdb/0x310
> [ T3576] softirqs last enabled at (241464): [<ffffffff9f98a2e1>] __local_bh_enable_ip+0x111/0x180
> [ T3576] softirqs last disabled at (247436): [<ffffffffa036688c>] bpf_test_run+0x10c/0x350
> [ T3576] CPU: 7 UID: 0 PID: 3576 Comm: test_progs Tainted: G O 6.15.0-bpf-00003-g5197b534e6ad #4 PREEMPT_{RT,(full)}
> [ T3576] Tainted: [O]=OOT_MODULE
> [ T3576] Hardware name: Micro-Star International Co., Ltd. Alpha 15 B5EEK/MS-158L, BIOS E158LAMS.10F 11/11/2024
> [ T3576] Call Trace:
> [ T3576] <TASK>
> [ T3576] dump_stack_lvl+0x6d/0xb0
> [ T3576] __might_resched.cold+0xe1/0xf3
> [ T3576] rt_spin_lock+0x5f/0x190
> [ T3576] ? ___slab_alloc+0x68/0xde0
> [ T3576] ? srso_alias_return_thunk+0x5/0xfbef5
> [ T3576] ? __lock_acquire+0x45f/0x2a70
> [ T3576] ___slab_alloc+0x68/0xde0
> [ T3576] ? bpf_map_kmalloc_node+0x72/0x220
> [ T3576] ? srso_alias_return_thunk+0x5/0xfbef5
> [ T3576] ? lock_acquire+0xbe/0x2e0
> [ T3576] ? bpf_map_get_memcg.isra.0+0x182/0x310
> [ T3576] ? srso_alias_return_thunk+0x5/0xfbef5
> [ T3576] ? find_held_lock+0x2b/0x80
> [ T3576] ? bpf_map_get_memcg.isra.0+0x8d/0x310
> [ T3576] ? bpf_map_kmalloc_node+0x72/0x220
> [ T3576] __kmalloc_node_noprof+0xee/0x490
> [ T3576] bpf_map_kmalloc_node+0x72/0x220
> [ T3576] __bpf_async_init+0x107/0x310
> [ T3576] bpf_prog_aa38f9274c0318a2_test_call_array_sleepable+0xb3/0x10e
> [ T3576] bpf_test_run+0x1ef/0x350
> [ T3576] ? bpf_test_run+0x10c/0x350
> [ T3576] ? migrate_enable+0x115/0x160
> [ T3576] ? kmem_cache_alloc_noprof+0x210/0x2b0
> [ T3576] bpf_prog_test_run_skb+0x37b/0x7c0
> [ T3576] ? fput+0x3f/0x90
> [ T3576] __sys_bpf+0xd33/0x26d0
> [ T3576] ? srso_alias_return_thunk+0x5/0xfbef5
> [ T3576] __x64_sys_bpf+0x21/0x30
> [ T3576] do_syscall_64+0x72/0xfa0
> [ T3576] entry_SYSCALL_64_after_hwframe+0x76/0x7e
> [ T3576] RIP: 0033:0x7f1c8e2a6779
> [ T3576] Code: ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff
> 73 01 c3 48 8b 0d 4f 86 0d 00 f7 d8 64 89 01 48
> [ T3576] RSP: 002b:00007fff8ef7b4d8 EFLAGS: 00000202 ORIG_RAX: 0000000000000141
> [ T3576] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f1c8e2a6779
> [ T3576] RDX: 0000000000000050 RSI: 00007fff8ef7b510 RDI: 000000000000000a
> [ T3576] RBP: 00007fff8ef7b4f0 R08: 00000000ffffffff R09: 00007fff8ef7b510
> [ T3576] R10: 0000000000000064 R11: 0000000000000202 R12: 0000000000000000
> [ T3576] R13: 00007fff8ef7c038 R14: 00007f1c8e8db000 R15: 000055d507eb3890
> [ T3576] </TASK>
>
>
> Here the problem is in __bpf_spin_lock() which calls arch_spin_lock()
> with preemption disabled:
>
> static inline void __bpf_spin_lock(struct bpf_spin_lock *lock)
> {
> arch_spinlock_t *l = (void *)lock;
> union {
> __u32 val;
> arch_spinlock_t lock;
> } u = { .lock = __ARCH_SPIN_LOCK_UNLOCKED };
>
> compiletime_assert(u.val == 0, "__ARCH_SPIN_LOCK_UNLOCKED not 0");
> BUILD_BUG_ON(sizeof(*l) != sizeof(__u32));
> BUILD_BUG_ON(sizeof(*lock) != sizeof(__u32));
> if (!strcmp(get_current()->comm, "test_progs"))
> pr_err("%s: calling preempt_disable()\n", __func__);
> preempt_disable();
> arch_spin_lock(l);
> }
>
> The call to preempt_disable here was introduced in commit
> 5861d1e8dbc4 ("bpf: Allow bpf_spin_{lock,unlock} in sleepable progs").
>
>
> Bert Karwatzki
As a quick fix of this problem I moved the __bpf_spin_lock_irqsave() beyond the
allocation in __bpf_async_init() (can this leak memory?):
diff --git a/kernel/bpf/helpers.c b/kernel/bpf/helpers.c
index e3a2662f4e33..94fcd8c8661c 100644
--- a/kernel/bpf/helpers.c
+++ b/kernel/bpf/helpers.c
@@ -1263,19 +1263,16 @@ static int __bpf_async_init(struct bpf_async_kern *async, struct bpf_map *map, u
return -EINVAL;
}
- __bpf_spin_lock_irqsave(&async->lock);
t = async->timer;
- if (t) {
- ret = -EBUSY;
- goto out;
- }
+ if (t)
+ return -EBUSY;
/* allocate hrtimer via map_kmalloc to use memcg accounting */
cb = bpf_map_kmalloc_node(map, size, GFP_ATOMIC, map->numa_node);
- if (!cb) {
- ret = -ENOMEM;
- goto out;
- }
+ if (!cb)
+ return -ENOMEM;
+
+ __bpf_spin_lock_irqsave(&async->lock);
switch (type) {
case BPF_ASYNC_TYPE_TIMER:
@@ -1315,7 +1312,6 @@ static int __bpf_async_init(struct bpf_async_kern *async, struct bpf_map *map, u
kfree(cb);
ret = -EPERM;
}
-out:
__bpf_spin_unlock_irqrestore(&async->lock);
return ret;
}
With this these bpf example programs run without giving a warning in dmesg:
./test_progs -a timer -a timer_mim -a free_timer
But running ./test_progs -a timer_lockup gives this error:
[ 127.373597] [ C1] ============================================
[ 127.373598] [ C1] WARNING: possible recursive locking detected
[ 127.373601] [ C1] 6.15.0-bpf-00006-g31cf22212ed9 #41 Tainted: G O
[ 127.373602] [ C1] --------------------------------------------
[ 127.373603] [ C1] ktimers/1/85 is trying to acquire lock:
[ 127.373605] [ C1] ffff98f62e61c1b8 (&base->softirq_expiry_lock){+...}-{3:3}, at: hrtimer_cancel_wait_running+0x4d/0x80
[ 127.373614] [ C1]
but task is already holding lock:
[ 127.373615] [ C1] ffff98f62e65c1b8 (&base->softirq_expiry_lock){+...}-{3:3}, at: hrtimer_run_softirq+0x37/0x100
[ 127.373621] [ C1]
other info that might help us debug this:
[ 127.373621] [ C1] Possible unsafe locking scenario:
[ 127.373622] [ C1] CPU0
[ 127.373623] [ C1] ----
[ 127.373624] [ C1] lock(&base->softirq_expiry_lock);
[ 127.373626] [ C1] lock(&base->softirq_expiry_lock);
[ 127.373627] [ C1]
*** DEADLOCK ***
[ 127.373628] [ C1] May be due to missing lock nesting notation
[ 127.373629] [ C1] 8 locks held by ktimers/1/85:
[ 127.373630] [ C1] #0: ffffffffa7a9acc0 (local_bh){.+.+}-{1:3}, at: __local_bh_disable_ip+0x29/0x1c0
[ 127.373636] [ C1] #1: ffff98f62e6578b8 ((softirq_ctrl.lock)){+.+.}-{3:3}, at: __local_bh_disable_ip+0xc8/0x1c0
[ 127.373641] [ C1] #2: ffffffffa7b31300 (rcu_read_lock){....}-{1:3}, at: rt_spin_lock+0xf0/0x190
[ 127.373648] [ C1] #3: ffffffffa7b31300 (rcu_read_lock){....}-{1:3}, at: __local_bh_disable_ip+0x29/0x1c0
[ 127.373653] [ C1] #4: ffff98f62e65c1b8 (&base->softirq_expiry_lock){+...}-{3:3}, at: hrtimer_run_softirq+0x37/0x100
[ 127.373658] [ C1] #5: ffffffffa7b31300 (rcu_read_lock){....}-{1:3}, at: rt_spin_lock+0xf0/0x190
[ 127.373663] [ C1] #6: ffffffffa7b31300 (rcu_read_lock){....}-{1:3}, at: bpf_timer_cancel+0x42/0x2e0
[ 127.373668] [ C1] #7: ffffffffa7a9acc0 (local_bh){.+.+}-{1:3}, at: __local_bh_disable_ip+0x29/0x1c0
[ 127.373673] [ C1]
stack backtrace:
[ 127.373675] [ C1] CPU: 1 UID: 0 PID: 85 Comm: ktimers/1 Tainted: G O 6.15.0-bpf-00006-g31cf22212ed9 #41 PREEMPT_{RT,(full)}
[ 127.373679] [ C1] Tainted: [O]=OOT_MODULE
[ 127.373680] [ C1] Hardware name: Micro-Star International Co., Ltd. Alpha 15 B5EEK/MS-158L, BIOS E158LAMS.10F 11/11/2024
[ 127.373681] [ C1] Call Trace:
[ 127.373683] [ C1] <TASK>
[ 127.373684] [ C1] dump_stack_lvl+0x6d/0xb0
[ 127.373689] [ C1] print_deadlock_bug.cold+0xbd/0xca
[ 127.373693] [ C1] __lock_acquire+0x1390/0x2a70
[ 127.373699] [ C1] ? __lock_acquire+0x45f/0x2a70
[ 127.373703] [ C1] lock_acquire+0xbe/0x2e0
[ 127.373706] [ C1] ? hrtimer_cancel_wait_running+0x4d/0x80
[ 127.373711] [ C1] ? hrtimer_cancel_wait_running+0x39/0x80
[ 127.373714] [ C1] rt_spin_lock+0x3d/0x190
[ 127.373716] [ C1] ? hrtimer_cancel_wait_running+0x4d/0x80
[ 127.373718] [ C1] ? __local_bh_disable_ip+0x48/0x1c0
[ 127.373720] [ C1] ? __local_bh_disable_ip+0x29/0x1c0
[ 127.373722] [ C1] ? hrtimer_cancel_wait_running+0x39/0x80
[ 127.373724] [ C1] hrtimer_cancel_wait_running+0x4d/0x80
[ 127.373727] [ C1] hrtimer_cancel+0x34/0x50
[ 127.373730] [ C1] bpf_timer_cancel+0x1fd/0x2e0
[ 127.373734] [ C1] bpf_prog_c55f7d3cdccd3222_timer_cb2+0x59/0x6e
[ 127.373737] [ C1] ? 0xffffffffc014d2a4
[ 127.373754] [ C1] bpf_timer_cb+0x74/0x140
[ 127.373757] [ C1] ? __pfx_bpf_timer_cb+0x10/0x10
[ 127.373760] [ C1] __hrtimer_run_queues+0x1b3/0x430
[ 127.373763] [ C1] ? srso_alias_return_thunk+0x5/0xfbef5
[ 127.373768] [ C1] hrtimer_run_softirq+0x9d/0x100
[ 127.373771] [ C1] handle_softirqs.isra.0+0xb0/0x3e0
[ 127.373775] [ C1] ? smpboot_thread_fn+0x25/0x2c0
[ 127.373779] [ C1] ? __pfx_smpboot_thread_fn+0x10/0x10
[ 127.373782] [ C1] run_ktimerd+0x40/0xa0
[ 127.373784] [ C1] smpboot_thread_fn+0x143/0x2c0
[ 127.373788] [ C1] kthread+0x11c/0x210
[ 127.373791] [ C1] ? __pfx_kthread+0x10/0x10
[ 127.373793] [ C1] ret_from_fork+0x34/0x50
[ 127.373796] [ C1] ? __pfx_kthread+0x10/0x10
[ 127.373799] [ C1] ret_from_fork_asm+0x1a/0x30
[ 127.373806] [ C1] </TASK>
Bert Karwatzki
