Re: BUG: scheduling while atomic with PREEMPT_RT=y and bpf selftests

Bert Karwatzki
2025-06-08T08:45:55Z

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@web.de> 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.