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

[Bert Karwatzki <spasswolf@web.de>]

Am Donnerstag, dem 05.06.2025 um 08:48 -0400 schrieb Steven Rostedt:
> 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?

Thanks for pointing me to this, I only very briefly tried out the function tracer
judging by an old file I found on 22.01.2022:

-rw-r--r-- 1 root root  75529450 22. Jan 2022  trace.log

> 
> ~# trace-cmd start -e preempt_enable -e preempt_disable
> ~# trace-cmd show
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 177552/177552   #P:8
> #
> #                                _-----=> irqs-off/BH-disabled
> #                               / _----=> need-resched
> #                              | / _---=> hardirq/softirq
> #                              || / _--=> preempt-depth
> #                              ||| / _-=> migrate-disable
> #                              |||| /     delay
> #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
> #              | |         |   |||||     |         |
>        trace-cmd-1131    [001] ...1.   965.046684: preempt_disable: caller=vfs_write+0x89c/0xe90 parent=vfs_write+0x89c/0xe90
>        trace-cmd-1131    [001] ...1.   965.046695: preempt_enable: caller=vfs_write+0x923/0xe90 parent=vfs_write+0x923/0xe90
>        trace-cmd-1131    [001] ...1.   965.046729: preempt_disable: caller=_raw_spin_lock+0x17/0x40 parent=0x0
>        trace-cmd-1131    [001] ...1.   965.046746: preempt_enable: caller=_raw_spin_unlock+0x2d/0x50 parent=0x0
>        trace-cmd-1131    [001] ...1.   965.046749: preempt_disable: caller=count_memcg_events+0x74/0x480 parent=count_memcg_events+0x74/0x480
>        trace-cmd-1131    [001] ...1.   965.046751: preempt_enable: caller=count_memcg_events+0x2b4/0x480 parent=count_memcg_events+0x2b4/0x480
>        trace-cmd-1131    [001] ...1.   965.046765: preempt_disable: caller=_raw_spin_lock+0x17/0x40 parent=0x0
>        trace-cmd-1131    [001] ...1.   965.046769: preempt_enable: caller=_raw_spin_unlock+0x2d/0x50 parent=0x0
>        trace-cmd-1131    [001] ...1.   965.046771: preempt_disable: caller=count_memcg_events+0x74/0x480 parent=count_memcg_events+0x74/0x480
>        trace-cmd-1131    [001] ...1.   965.046773: preempt_enable: caller=count_memcg_events+0x2b4/0x480 parent=count_memcg_events+0x2b4/0x480
>        trace-cmd-1131    [001] ...1.   965.046787: preempt_disable: caller=_raw_spin_lock+0x17/0x40 parent=0x0
>        trace-cmd-1131    [001] ...1.   965.046801: preempt_enable: caller=_raw_spin_unlock+0x2d/0x50 parent=0x0
>        trace-cmd-1131    [001] ...1.   965.046803: preempt_disable: caller=count_memcg_events+0x74/0x480 parent=count_memcg_events+0x74/0x480
>        trace-cmd-1131    [001] ...1.   965.046805: preempt_enable: caller=count_memcg_events+0x2b4/0x480 parent=count_memcg_events+0x2b4/0x480
>        trace-cmd-1131    [001] d..1.   965.046812: preempt_disable: caller=_raw_spin_lock_irq+0x2b/0x60 parent=0x0
>        trace-cmd-1131    [001] ...1.   965.046815: preempt_enable: caller=_raw_spin_unlock_irq+0x38/0x60 parent=0x0
> [..]
> 
> It's very light weight. There's also trace_printk() that is also very light
> weight to use.

> It's enabled when you enable CONFIG_PREEMPT_TRACER.
> 
> -- Steve

I tried this and first thought my kernel did not have the right configuration as

# trace-cmd record -e preempt_disable -e preempt_enable

seemed to do nothing in particular, but it turns out it takes a long time to start
(~1min) when the kernel is compiled with CONFIG_LOCKDEP=y. (on the standard debian
kernel starting to record takes less time, but it does not have CONFIG_PREEMPT_TRACER.)

So after the trace-cmd was running I ran the bpf example and got a trace.dat:

# ls -lh trace.dat 
-rw-r--r-- 1 root root 152M  6. Jun 14:41 trace.dat

turning this into a report with

# trace-cmd report > preemp_trace.rep

gives a rather unwieldly large file

# ls -lh preempt_trace.rep 
-rw-rw-r-- 1 root root 7,4G  6. Jun 14:46 preempt_trace.rep

This file has about 61 million lines

# wc -l preempt_trace.rep
61627360 preempt_trace.rep

but only 742104 corresponding to the bpf example program "test_progs"

# grep test_progs preempt_trace.rep | wc -l
742104

Is it possible to filter the preempt_{en,dis}able events by task name (i.e.
get_current()->comm)?

I tried this (from https://code.tools/man/1/trace-cmd-report/) but it
fails with an error message:
# trace-cmd record -e preempt_enable -F '.*:COMM == "test_progs"' -e preempt_disable -F '.*:COMM == "test_progs"'

********************
 Unable to exec .*:COMM == "test_progs"
********************
trace-cmd: No such file or directory
  Failed to exec .*:COMM == "test_progs"
libtracecmd: No such file or directory
  can not stat 'trace.dat.cpu0'


Bert Karwatzki