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?
~# 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
