| Message ID | 174124210422.3014222.12363751066695445786.stgit@mhiramat.tok.corp.google.com (mailing list archive) |
|---|---|
| State | Superseded |
| Headers | show |
| Series | tracing: tprobe-events: Fix to clean up tprobe correctly when module unload | expand |
On Thu, 6 Mar 2025 15:21:44 +0900 "Masami Hiramatsu (Google)" <mhiramat@kernel.org> wrote: > When unloading module, the tprobe events are not correctly cleaned > up. Thus it becomes `fprobe-event` and never be enabled again even > if loading the same module again. > > For example; > > # cd /sys/kernel/tracing > # modprobe trace_events_sample > # echo 't:my_tprobe foo_bar' >> dynamic_events > # cat dynamic_events > t:tracepoints/my_tprobe foo_bar > # rmmod trace_events_sample > # cat dynamic_events > f:tracepoints/my_tprobe foo_bar > > As you can see, the second time my_tprobe starts with 'f' instead > of 't'. > > This cleans up (unregister) the tprobe events when module is > unloaded. After applying this, I tried it out: # cd /sys/kernel/tracing # modprobe trace_events_sample # echo 't:my_tprobe foo_bar a=$arg1' > dynamic_events # echo 1 > events/tracepoints/enable [wait] # echo 0 > events/tracepoints/enable # cat trace # tracer: nop # # entries-in-buffer/entries-written: 13/13 #P:8 # # _-----=> irqs-off/BH-disabled # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / _-=> migrate-disable # |||| / delay # TASK-PID CPU# ||||| TIMESTAMP FUNCTION # | | | ||||| | | event-sample-1041 [005] ...1. 1957.632897: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1958.656935: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1959.680883: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1960.704855: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1961.728977: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1962.751822: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1963.776834: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1964.800748: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1965.824788: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1966.848789: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1967.872902: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1968.896754: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1969.920737: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 # rmmod trace_events_sample # cat trace # tracer: nop # # entries-in-buffer/entries-written: 13/13 #P:8 # # _-----=> irqs-off/BH-disabled # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / _-=> migrate-disable # |||| / delay # TASK-PID CPU# ||||| TIMESTAMP FUNCTION # | | | ||||| | | event-sample-1041 [005] ...1. 1957.632897: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1958.656935: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1959.680883: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1960.704855: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1961.728977: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1962.751822: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1963.776834: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1964.800748: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1965.824788: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1966.848789: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1967.872902: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1968.896754: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1969.920737: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 # modprobe trace_events_sample # echo 1 > events/tracepoints/enable # cat trace # tracer: nop # # entries-in-buffer/entries-written: 13/13 #P:8 # # _-----=> irqs-off/BH-disabled # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / _-=> migrate-disable # |||| / delay # TASK-PID CPU# ||||| TIMESTAMP FUNCTION # | | | ||||| | | event-sample-1041 [005] ...1. 1957.632897: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1958.656935: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1959.680883: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1960.704855: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1961.728977: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1962.751822: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1963.776834: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1964.800748: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1965.824788: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1966.848789: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1967.872902: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1968.896754: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 event-sample-1041 [005] ...1. 1969.920737: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 Tracing doesn't restart. -- Steve
On Fri, 7 Mar 2025 12:20:00 -0500 Steven Rostedt <rostedt@goodmis.org> wrote: > On Thu, 6 Mar 2025 15:21:44 +0900 > "Masami Hiramatsu (Google)" <mhiramat@kernel.org> wrote: > > > When unloading module, the tprobe events are not correctly cleaned > > up. Thus it becomes `fprobe-event` and never be enabled again even > > if loading the same module again. > > > > For example; > > > > # cd /sys/kernel/tracing > > # modprobe trace_events_sample > > # echo 't:my_tprobe foo_bar' >> dynamic_events > > # cat dynamic_events > > t:tracepoints/my_tprobe foo_bar > > # rmmod trace_events_sample > > # cat dynamic_events > > f:tracepoints/my_tprobe foo_bar > > > > As you can see, the second time my_tprobe starts with 'f' instead > > of 't'. > > > > This cleans up (unregister) the tprobe events when module is > > unloaded. > > After applying this, I tried it out: > > # cd /sys/kernel/tracing > # modprobe trace_events_sample > # echo 't:my_tprobe foo_bar a=$arg1' > dynamic_events > # echo 1 > events/tracepoints/enable > [wait] > # echo 0 > events/tracepoints/enable > # cat trace > # tracer: nop > # > # entries-in-buffer/entries-written: 13/13 #P:8 > # > # _-----=> irqs-off/BH-disabled > # / _----=> need-resched > # | / _---=> hardirq/softirq > # || / _--=> preempt-depth > # ||| / _-=> migrate-disable > # |||| / delay > # TASK-PID CPU# ||||| TIMESTAMP FUNCTION > # | | | ||||| | | > event-sample-1041 [005] ...1. 1957.632897: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1958.656935: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1959.680883: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1960.704855: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1961.728977: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1962.751822: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1963.776834: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1964.800748: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1965.824788: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1966.848789: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1967.872902: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1968.896754: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1969.920737: my_tprobe: (__probestub_foo_bar+0x4/0x20 [trace_events_sample]) a=0xffffffffc006c186 > # rmmod trace_events_sample > # cat trace > # tracer: nop > # > # entries-in-buffer/entries-written: 13/13 #P:8 > # > # _-----=> irqs-off/BH-disabled > # / _----=> need-resched > # | / _---=> hardirq/softirq > # || / _--=> preempt-depth > # ||| / _-=> migrate-disable > # |||| / delay > # TASK-PID CPU# ||||| TIMESTAMP FUNCTION > # | | | ||||| | | > event-sample-1041 [005] ...1. 1957.632897: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1958.656935: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1959.680883: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1960.704855: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1961.728977: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1962.751822: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1963.776834: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1964.800748: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1965.824788: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1966.848789: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1967.872902: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1968.896754: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1969.920737: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > > # modprobe trace_events_sample > # echo 1 > events/tracepoints/enable > # cat trace > # tracer: nop > # > # entries-in-buffer/entries-written: 13/13 #P:8 > # > # _-----=> irqs-off/BH-disabled > # / _----=> need-resched > # | / _---=> hardirq/softirq > # || / _--=> preempt-depth > # ||| / _-=> migrate-disable > # |||| / delay > # TASK-PID CPU# ||||| TIMESTAMP FUNCTION > # | | | ||||| | | > event-sample-1041 [005] ...1. 1957.632897: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1958.656935: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1959.680883: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1960.704855: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1961.728977: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1962.751822: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1963.776834: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1964.800748: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1965.824788: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1966.848789: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1967.872902: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1968.896754: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > event-sample-1041 [005] ...1. 1969.920737: my_tprobe: (0xffffffffc00620b4) a=0xffffffffc006c186 > > Tracing doesn't restart. Ah, I see. __unregister_trace_fprobe() clean up fp. static void __unregister_trace_fprobe(struct trace_fprobe *tf) { if (trace_fprobe_is_registered(tf)) { unregister_fprobe(&tf->fp); memset(&tf->fp, 0, sizeof(tf->fp)); <---- this This will cleanup the callbacks. Let me update it. Thanks! > > -- Steve >
diff --git a/kernel/trace/trace_fprobe.c b/kernel/trace/trace_fprobe.c index e27305d31fc5..d5fc0c5bf879 100644 --- a/kernel/trace/trace_fprobe.c +++ b/kernel/trace/trace_fprobe.c @@ -775,7 +775,7 @@ static void __unregister_trace_fprobe(struct trace_fprobe *tf) if (trace_fprobe_is_tracepoint(tf)) { tracepoint_probe_unregister(tf->tpoint, tf->tpoint->probestub, NULL); - tf->tpoint = NULL; + tf->tpoint = TRACEPOINT_STUB; tf->mod = NULL; } } @@ -1007,12 +1007,8 @@ static int __tracepoint_probe_module_cb(struct notifier_block *self, trace_probe_is_enabled(&tf->tp)) reenable_trace_fprobe(tf); } - } else if (val == MODULE_STATE_GOING && tp_mod->mod == tf->mod) { - tracepoint_probe_unregister(tf->tpoint, - tf->tpoint->probestub, NULL); - tf->tpoint = NULL; - tf->mod = NULL; - } + } else if (val == MODULE_STATE_GOING && tp_mod->mod == tf->mod) + __unregister_trace_fprobe(tf); } mutex_unlock(&event_mutex);