tracing: tprobe-events: Fixes for tprobe events

Hi,

Beau reported tprobe example in the document does not work on 6.17 kernel.

---
echo "t sched_switch preempt prev_pid=prev->pid next_pid=next->pid" > /sys/kernel/tracing/dynamic_events echo 1 > /sys/kernel/tracing/events/tracepoints/sched_switch/enable
cat /sys/kernel/tracing/trace_pipe
---

It seems that the tracepoint callback is not correctly set. So I tried to trace the actual function calls and the local variables. (I need to enable CONFIG_KPROBE_EVENTS_ON_NOTRACE for tracing ftrace code itself.)

With the below commands, I got some probe definitions for debug:

 $ perf probe -k vmlinux -D "tracepoint_user_find_get name:string"
 $ perf probe -k vmlinux -D '__regsiter_tracepoint_fprobe:13 tuser tuser->tpoint'
 $ perf probe -k vmlinux -D 'register_fprobe_ips addrs[1]'
 $ perf probe -k vmlinux -D 'register_fprobe_ips%return ret=$retval'
 $ perf probe -k vmlinux -D '__regsiter_tracepoint_fprobe tf->tprobe'
 $ perf probe -k vmlinux -D 'tracepoint_probe_register_prio_may_exist tp'
 $ perf probe -k vmlinux -D 'tracepoint_probe_register_prio_may_exist%return ret=$retval'
 $ perf probe -k vmlinux -D '__tracepoint_user_init name:string'

And run below commands on the machine:

-----

 $ cat > /sys/kernel/tracing/dynamic_events << EOF
p:probe/tracepoint_user_find_get enable_trace_fprobe+271 name_string=+0(%bp):string
p:probe/regsiter_tracepoint_fprobe_L13 enable_trace_fprobe+692 tuser=%r13 tpoint=+24(%r13)
p:probe/regsiter_tracepoint_fprobe_L13_1 enable_trace_fprobe+685 tuser=%r13 tpoint=+24(%r13)
p:probe/register_fprobe_ips register_fprobe_ips+0 addrs=+8(%si):u64
r:probe/register_fprobe_ips__return register_fprobe_ips+0 ret=\$retval
p:probe/regsiter_tracepoint_fprobe enable_trace_fprobe+247 tprobe=+80(-96(%r14)):u8
p:probe/tracepoint_probe_register_prio_may_exist tracepoint_probe_register_prio_may_exist+0 tp=%di
r:probe/tracepoint_probe_register_prio_may_exist__return tracepoint_probe_register_prio_may_exist+0 ret=\$retval
p:probe/tracepoint_user_init enable_trace_fprobe+440 name_string=+0(%bp):string
EOF
 $ echo 1 > /sys/kernel/tracing/events/probe/enable

 $ echo "t sched_switch preempt prev_pid=prev->pid next_pid=next->pid" >> /sys/kernel/tracing/dynamic_events
 $ echo 1 > /sys/kernel/tracing/events/tracepoints/sched_switch/enable
 $ cat /sys/kernel/tracing/trace
-----

And I got below trace data:

-----

#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
              sh-107     [005] ..Zff     7.290496: regsiter_tracepoint_fprobe: (enable_trace_fprobe+0xf7/0x3a0) tprobe=0
              sh-107     [005] ..Zff     7.290547: tracepoint_user_find_get: (enable_trace_fprobe+0x10f/0x3a0) name_string="sched_switch"
              sh-107     [005] ..Zff     7.290680: tracepoint_user_init: (enable_trace_fprobe+0x1b8/0x3a0) name_string="sched_switch"
              sh-107     [005] ..Zff     7.290727: regsiter_tracepoint_fprobe_L13_1: (enable_trace_fprobe+0x2ad/0x3a0) tuser=0xffff88800538b280 tpoint=0xffffffff82a4ac10
              sh-107     [005] ..Zff     7.290730: regsiter_tracepoint_fprobe_L13: (enable_trace_fprobe+0x2b4/0x3a0) tuser=0xffff88800538b280 tpoint=0xffffffff82a4ac10
              sh-107     [005] ..Zff     7.290735: register_fprobe_ips: (register_fprobe_ips+0x4/0x310) addrs=18446612682157410880
              sh-107     [005] .....     7.311345: register_fprobe_ips__return: (enable_trace_fprobe+0x2f6/0x3a0 <- register_fprobe_ips) ret=0

-----

No tracepoint_probe_register_prio_may_exist event is recorded, but tracepoint_user_init and regsiter_tracepoint_fprobe_L13_1 (call-site of tracepoint_user_init()) are recorded and tuser and tpoint are not NULL or error.

This means when the tprobe is enabled, the register_tracepoint_fprobe() eventually calls tracepoint_user_init() correctly. However, it does not call tracepoint_probe_register_prio_may_exist() to register tracepoint callback. So the bug is inside tracepoint_user_init(), not NULL return path.

-----
static struct tracepoint_user *__tracepoint_user_init(const char *name, struct tracepoint *tpoint)

{
	struct tracepoint_user *tuser __free(tuser_free) = NULL;
	int ret;

	tuser = kzalloc(sizeof(*tuser), GFP_KERNEL);
	if (!tuser)
		return NULL;
	tuser->name = kstrdup(name, GFP_KERNEL);
	if (!tuser->name)
		return NULL;

	if (tpoint) {
		ret = tracepoint_user_register(tuser); /* forgot to set tuser->tpoint */
		if (ret)
			return ERR_PTR(ret);
	}

-----

And found it forgot to set tuser->tpoint before calling tracepoint_user_register() which calls tracepoint_probe_register_prio_may_exist(tuser->tpoint). To fix that, I just moved the tuser->tpoint setting line right before tracepoint_user_register() call [1/2].

I also found another issue when I switched enable and disable[2/2].

I hope this report will help someone to do similar debug by tracing.

Thank you,

---

Masami Hiramatsu (Google) (2):
tracing: tprobe-events: Fix to register tracepoint correctly
tracing: tprobe-events: Fix to put tracepoint_user when disable the tprobe

 kernel/trace/trace_fprobe.c |    7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

--
Masami Hiramatsu (Google) <[email protected]>

From: Masami Hiramatsu (Google) <[email protected]>

Since __tracepoint_user_init() calls tracepoint_user_register() without initializing tuser->tpoint with given tracpoint, it does not register tracepoint stub function as callback correctly, and tprobe does not work.

Initializing tuser->tpoint correctly before tracepoint_user_register() so that it sets up tracepoint callback.

I confirmed below example works fine again.

echo "t sched_switch preempt prev_pid=prev->pid next_pid=next->pid" > /sys/kernel/tracing/dynamic_events echo 1 > /sys/kernel/tracing/events/tracepoints/sched_switch/enable
cat /sys/kernel/tracing/trace_pipe

---
 kernel/trace/trace_fprobe.c |    3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

index b36ade43d4b3..d4e78d1ace12 100644
@@ -106,13 +106,14 @@ static struct tracepoint_user *__tracepoint_user_init(const char *name, struct t
 	if (!tuser->name)
 		return NULL;
 
+	/* Register tracepoint if it is loaded. */
 	if (tpoint) {
+		tuser->tpoint = tpoint;
 		ret = tracepoint_user_register(tuser);
 		if (ret)
 			return ERR_PTR(ret);
 	}
 
-	tuser->tpoint = tpoint;
 	tuser->refcount = 1;
 	INIT_LIST_HEAD(&tuser->list);
 	list_add(&tuser->list, &tracepoint_user_list);

From: Masami Hiramatsu (Google) <[email protected]>

__unregister_trace_fprobe() checks tf->tuser to put it when removing tprobe. However, disable_trace_fprobe() does not use it and only calls unregister_fprobe(). Thus it forgets to disable tracepoint_user.

If the trace_fprobe has tuser, put it for unregistering the tracepoint callbacks when disabling tprobe correctly.

---
 kernel/trace/trace_fprobe.c |    4 ++++
 1 file changed, 4 insertions(+)

index d4e78d1ace12..62420eec677f 100644
@@ -1512,6 +1512,10 @@ static int disable_trace_fprobe(struct trace_event_call *call,
 	if (!trace_probe_is_enabled(tp)) {
 		list_for_each_entry(tf, trace_probe_probe_list(tp), tp.list) {
 			unregister_fprobe(&tf->fp);
+			if (tf->tuser) {
+				tracepoint_user_put(tf->tuser);
+				tf->tuser = NULL;
+			}
 		}
 	}
 

Thanks! I've applied this series locally and tested this. Everything works well in our environment.

Thanks! I've validated no bad dmesg, etc. and can delete the tprobe without issues after we disable it.

I will reference this, it's very useful.

For the series:

Thanks,
-Beau

Great!

Thanks!

Masami Hiramatsu (Google) <[email protected]>