Re: [PATCH v5 6/8] selftests: tracing: Add a basic testcase for wprobe

[Masami Hiramatsu (Google) <mhiramat@kernel.org>]

On Wed, 29 Oct 2025 00:42:19 +0900
Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:

> On Tue, 28 Oct 2025 10:55:49 +0900
> Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:
> 
> > On Tue, 28 Oct 2025 08:42:22 +0900
> > Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:
> > 
> > > ~ # cd /sys/kernel/tracing/
> > > /sys/kernel/tracing # echo 'w:my_wprobe w@jiffies' >> dynamic_events 
> > > /sys/kernel/tracing # echo 1 > events/wprobes/my_wprobe/enable 
> > > [   54.942288] trace_wprobe: enable_trace_wprobe called
> > > [   54.945306] trace_wprobe: trying to register wprobes
> > > [   54.947367] trace_wprobe: __register_trace_wprobe called
> > > [   54.949586] trace_wprobe: registering wprobe at addr: 0xffffb6ce429fb200, len: 4, type: 2
> > > [   54.951639] Creating wide hw breakpoint on CPU 0
> > > [   54.966390] Creating kernel counter on CPU 0 for event type 5
> > > [   54.967758] perf_install_in_context: event 00000000736da1d9 ctx 000000005d4db900 cpu 0
> > > [   54.972015] perf_install_in_context2: event 00000000736da1d9 ctx set to 000000005d4db900
> > > [   54.976697] cpu_function_call: calling function on CPU 0, func: __perf_install_in_context+0x0/0x2c8
> > > 
> > > What happen if the cpu calls function on itself by
> > > smp_call_function_single() on arm64?
> > > 
> > >   smp_call_function_single(this_cpu, remote_function, &data, 1);
> > 
> > Sorry, that was printk buffering issue. I used trace_printk() instead
> > and persistent ring buffer[1] to trace it.
> > 
> > [1] https://docs.kernel.org/trace/debugging.html#persistent-buffers-across-boots
> > 
> > ~ # echo 1 > /sys/kernel/tracing/instances/boot_map/options/trace_printk_dest
> > ~ # echo 'w:my_wprobe w@jiffies' >> /sys/kernel/tracing/dynamic_events 
> > ~ # echo 1 > /sys/kernel/tracing/events/wprobes/my_wprobe/enable 
> > QEMU 8.2.2 monitor - type 'help' for more information
> > (qemu) system_reset
> > ...
> > 
> > ~ # cat /sys/kernel/tracing/instances/boot_map/trace 
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 16/16   #P:1
> > #
> > #                                _-----=> irqs-off/BH-disabled
> > #                               / _----=> need-resched
> > #                              | / _---=> hardirq/softirq
> > #                              || / _--=> preempt-depth
> > #                              ||| / _-=> migrate-disable
> > #                              |||| /     delay
> > #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
> > #              | |         |   |||||     |         |
> >            <...>-63      [000] .....    21.065038: register_wide_hw_breakpoint: Creating wide hw breakpoint on CPU 0
> >            <...>-63      [000] .....    21.079678: perf_event_create_kernel_counter: Creating kernel counter on CPU 0 for event type 5
> >            <...>-63      [000] .....    21.080051: perf_install_in_context: perf_install_in_context: event 000000000b3ac4d3 ctx 00000000097d6337 cpu 0
> >            <...>-63      [000] .....    21.080140: perf_install_in_context: perf_install_in_context2: event 000000000b3ac4d3 ctx set to 00000000097d6337
> >            <...>-63      [000] .....    21.080939: cpu_function_call: cpu_function_call: calling function on CPU 0, func: __perf_install_in_context+0x0/0x2f0
> >            <...>-63      [000] .....    21.080966: smp_call_function_single: smp_call_function_single: calling function on CPU 0, func: remote_function+0x0/0x78, wait=1
> >            <...>-63      [000] ...1.    21.080973: smp_call_function_single: smp_call_function_single: running on CPU 0, call CPU 0
> >            <...>-63      [000] ...1.    21.081099: smp_call_function_single: smp_call_function_single: checking for potential deadlock conditions
> >            <...>-63      [000] ...1.    21.081259: generic_exec_single: generic_exec_single: preparing to call function on CPU 0, func: remote_function+0x0/0x78
> >            <...>-63      [000] ...1.    21.081269: generic_exec_single: Executing smp_call_function_single on self CPU 0, func: remote_function+0x0/0x78
> >            <...>-63      [000] d..1.    21.081289: csd_do_func: csd_do_func: CPU 0 executing func remote_function+0x0/0x78
> >            <...>-63      [000] d..1.    21.081429: __perf_install_in_context: __perf_install_in_context: event 000000000b3ac4d3 ctx 00000000097d6337
> >            <...>-63      [000] d..2.    21.083211: hw_breakpoint_control: hw_breakpoint_control: ops=0
> >            <...>-63      [000] d..1.    21.084191: __perf_install_in_context: __perf_install_in_context: event 000000000b3ac4d3 done, ret=0
> >            <...>-63      [000] d..1.    21.084237: csd_do_func: csd_do_func: CPU 0 finished func remote_function+0x0/0x78
> >            <...>-63      [000] d..1.    21.084243: generic_exec_single: Finished csd_lock_record(NULL)
> > ~ # 
> > 
> > 
> > So the last message is right before the local_irq_restore() in
> > generic_exec_single().
> > 
> > static int generic_exec_single(int cpu, call_single_data_t *csd)
> > {
> > 	...
> > 		csd_lock_record(csd);
> > 		csd_unlock(csd);
> > 		local_irq_save(flags);
> > 		csd_do_func(func, info, NULL);
> > 		csd_lock_record(NULL);
> > 		trace_printk("Finished csd_lock_record(NULL)\n"); <- 
> > 		local_irq_restore(flags);
> > 		return 0;
> > 
> > Actually, I added another trace_printk() right after generic_exec_single().
> > 
> > 	err = generic_exec_single(cpu, csd);
> > 	trace_printk("generic_exec_single returned %d for CPU %d, func: %pS\n",
> > 		err, cpu, func);
> > 
> > This means after setting the hw_breakpoint, when enabing the IRQ,
> > the machine is frozen - but qemu is running busy.
> > 
> > Can we specify the kernel memory address to HW breakpoint on arm64?
> 
> Hmm, it seems that jiffies related things are updated frequently
> and it may cause interrupt storm or infinit recursive call.

I added another trace_printk() in el1_watchpt(). It seems el1_watchpt()
takes too long and there is no time to do any other things.
(Note the interval shown below is only within the el1_watchpt function,
 and in reality various processes (save/restore registers etc) for
 exception handling will be inserted before and after.)

   kworker/u32:3-75      [001] d.h2.    43.216706: el1_watchpt: FAR=0xjiffies+0x0/0x40, ESR=0xd6000062, WP index=0, n
est=0
   kworker/u32:3-75      [001] d.h2.    43.216750: el1_watchpt: returning to EL1: nest=0
   kworker/u32:3-75      [001] d.h2.    43.216816: el1_watchpt: FAR=0xjiffies+0x0/0x40, ESR=0xd6000062, WP index=0, n
est=0
   kworker/u32:3-75      [001] d.h2.    43.216860: el1_watchpt: returning to EL1: nest=0
   kworker/u32:3-75      [001] d.h2.    43.216927: el1_watchpt: FAR=0xjiffies+0x0/0x40, ESR=0xd6000062, WP index=0, n
est=0
   kworker/u32:3-75      [001] d.h2.    43.216971: el1_watchpt: returning to EL1: nest=0
   kworker/u32:3-75      [001] d.h2.    43.217058: el1_watchpt: FAR=0xjiffies+0x0/0x40, ESR=0xd6000062, WP index=0, n
est=0
   kworker/u32:3-75      [001] d.h2.    43.217106: el1_watchpt: returning to EL1: nest=0
   kworker/u32:3-75      [001] d.h2.    43.217175: el1_watchpt: FAR=0xjiffies+0x0/0x40, ESR=0xd6000062, WP index=0, n
est=0
   kworker/u32:3-75      [001] d.h2.    43.217219: el1_watchpt: returning to EL1: nest=0

So watching any variables which is frequently updated will
almost freeze the system. Hmmm, the handler should check the
interval and if it is too frequently, it should disable the
wprobe.

Thank you,

-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>