ftrace: Fix DIRECT_CALLS to use SAVE_REGS by default

PATCH In review Masami Hiramatsu (Google) 3 participants 4 messages Jan 10, 2024

Subsystems (2)

Tracing ftrace

lore

Share & tools

lore

Masami Hiramatsu (Google)

author maintainer

2024-01-10 00:13 UTC #0 lore raw

PATCH 1/1 ftrace: Fix DIRECT_CALLS to use SAVE_REGS by default

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

The commit 60c8971899f3 ("ftrace: Make DIRECT_CALLS work WITH_ARGS and !WITH_REGS") changed DIRECT_CALLS to use SAVE_ARGS when there are multiple ftrace_ops at the same function, but since the x86 only support to jump to direct_call from ftrace_regs_caller, when we set the function tracer on the same target function on x86, ftrace-direct does not work as below (this actually works on arm64.)

At first, insmod ftrace-direct.ko to put a direct_call on 'wake_up_process()'.

 # insmod kernel/samples/ftrace/ftrace-direct.ko
 # less trace
...
          <idle>-0       [006] ..s1.   564.686958: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [007] ..s1.   564.687836: my_direct_func: waking up kcompactd0-63
          <idle>-0       [006] ..s1.   564.690926: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [006] ..s1.   564.696872: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [007] ..s1.   565.191982: my_direct_func: waking up kcompactd0-63

Setup a function filter to the 'wake_up_process' too, and enable it.

 # cd /sys/kernel/tracing/
 # echo wake_up_process > set_ftrace_filter
 # echo function > current_tracer
 # less trace
...
          <idle>-0       [006] ..s3.   686.180972: wake_up_process <-call_timer_fn
          <idle>-0       [006] ..s3.   686.186919: wake_up_process <-call_timer_fn
          <idle>-0       [002] ..s3.   686.264049: wake_up_process <-call_timer_fn
          <idle>-0       [002] d.h6.   686.515216: wake_up_process <-kick_pool
          <idle>-0       [002] d.h6.   686.691386: wake_up_process <-kick_pool

Then, only function tracer is shown on x86.
But if you enable 'kprobe on ftrace' event (which uses SAVE_REGS flag) on the same function, it is shown again.

 # echo 'p wake_up_process' >> dynamic_events
 # echo 1 > events/kprobes/p_wake_up_process_0/enable
 # echo > trace
 # less trace
...
          <idle>-0       [006] ..s2.  2710.345919: p_wake_up_process_0: (wake_up_process+0x4/0x20)
          <idle>-0       [006] ..s3.  2710.345923: wake_up_process <-call_timer_fn
          <idle>-0       [006] ..s1.  2710.345928: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [006] ..s2.  2710.349931: p_wake_up_process_0: (wake_up_process+0x4/0x20)
          <idle>-0       [006] ..s3.  2710.349934: wake_up_process <-call_timer_fn
          <idle>-0       [006] ..s1.  2710.349937: my_direct_func: waking up rcu_preempt-17

To fix this issue, use SAVE_REGS flag for multiple ftrace_ops flag of direct_call by default.

Fixes 60c8971899f3 ("ftrace: Make DIRECT_CALLS work WITH_ARGS and !WITH_REGS")

Cc [email protected]

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

---
 kernel/trace/ftrace.c |   10 ++++++++++
 1 file changed, 10 insertions(+)

kernel/trace/ftrace.c +10 -0

index b01ae7d36021..c060d5b47910 100644
@@ -5325,7 +5325,17 @@ static LIST_HEAD(ftrace_direct_funcs);
 
 static int register_ftrace_function_nolock(struct ftrace_ops *ops);
 
+/*
+ * If there are multiple ftrace_ops, use SAVE_REGS by default, so that direct
+ * call will be jumped from ftrace_regs_caller. Only if the architecture does
+ * not support ftrace_regs_caller but direct_call, use SAVE_ARGS so that it
+ * jumps from ftrace_caller for multiple ftrace_ops.
+ */
+#ifndef HAVE_DYNAMIC_FTRACE_WITH_REGS
 #define MULTI_FLAGS (FTRACE_OPS_FL_DIRECT | FTRACE_OPS_FL_SAVE_ARGS)
+#else
+#define MULTI_FLAGS (FTRACE_OPS_FL_DIRECT | FTRACE_OPS_FL_SAVE_REGS)
+#endif
 
 static int check_direct_multi(struct ftrace_ops *ops)
 {

Mark Rutland

reviewer Reviewed-by Tested-by on v1 1/1

2024-01-10 12:20 UTC #1 lore raw

Quoted 50 lines · Masami Hiramatsu (Google)

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

At first, insmod ftrace-direct.ko to put a direct_call on 'wake_up_process()'.

 # insmod kernel/samples/ftrace/ftrace-direct.ko
 # less trace
...
          <idle>-0       [006] ..s1.   564.686958: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [007] ..s1.   564.687836: my_direct_func: waking up kcompactd0-63
          <idle>-0       [006] ..s1.   564.690926: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [006] ..s1.   564.696872: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [007] ..s1.   565.191982: my_direct_func: waking up kcompactd0-63

Setup a function filter to the 'wake_up_process' too, and enable it.

 # cd /sys/kernel/tracing/
 # echo wake_up_process > set_ftrace_filter
 # echo function > current_tracer
 # less trace
...
          <idle>-0       [006] ..s3.   686.180972: wake_up_process <-call_timer_fn
          <idle>-0       [006] ..s3.   686.186919: wake_up_process <-call_timer_fn
          <idle>-0       [002] ..s3.   686.264049: wake_up_process <-call_timer_fn
          <idle>-0       [002] d.h6.   686.515216: wake_up_process <-kick_pool
          <idle>-0       [002] d.h6.   686.691386: wake_up_process <-kick_pool

Then, only function tracer is shown on x86.
But if you enable 'kprobe on ftrace' event (which uses SAVE_REGS flag) on the same function, it is shown again.

 # echo 'p wake_up_process' >> dynamic_events
 # echo 1 > events/kprobes/p_wake_up_process_0/enable
 # echo > trace
 # less trace
...
          <idle>-0       [006] ..s2.  2710.345919: p_wake_up_process_0: (wake_up_process+0x4/0x20)
          <idle>-0       [006] ..s3.  2710.345923: wake_up_process <-call_timer_fn
          <idle>-0       [006] ..s1.  2710.345928: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [006] ..s2.  2710.349931: p_wake_up_process_0: (wake_up_process+0x4/0x20)
          <idle>-0       [006] ..s3.  2710.349934: wake_up_process <-call_timer_fn
          <idle>-0       [006] ..s1.  2710.349937: my_direct_func: waking up rcu_preempt-17

Quoted 6 lines

To fix this issue, use SAVE_REGS flag for multiple ftrace_ops flag of direct_call by default.
Fixes 60c8971899f3 ("ftrace: Make DIRECT_CALLS work WITH_ARGS and !WITH_REGS")
Cc [email protected]
Signed-off-by Masami Hiramatsu (Google) <[email protected]>

Sorry about this; I hadn't realised that x86 only supported direct calls when SAVE_REGS was requested.

The patch looks good to me. I applied it atop v6.7 and double-checked that this still works on arm64 as per your examples above, and everything looks good:

# mount -t tracefs none /sys/kernel/tracing/
# insmod ftrace-direct.ko 
# echo wake_up_process > /sys/kernel/tracing/set_ftrace_filter 
# echo function > /sys/kernel/tracing/current_tracer 
# less /sys/kernel/tracing/trace
...	
          <idle>-0       [007] ..s3.   172.932840: wake_up_process <-process_timeout
          <idle>-0       [007] ..s1.   172.932842: my_direct_func: waking up kcompactd0-62
          <idle>-0       [007] ..s3.   173.444836: wake_up_process <-process_timeout
          <idle>-0       [007] ..s1.   173.444838: my_direct_func: waking up kcompactd0-62
          <idle>-0       [001] d.h5.   173.471116: wake_up_process <-kick_pool
          <idle>-0       [001] d.h3.   173.471118: my_direct_func: waking up kworker/1:1-58

Reviewed-by Mark Rutland <[email protected]>

Tested-by Mark Rutland <[email protected]> [arm64]

Thanks,
Mark.

Quoted 27 lines

---
 kernel/trace/ftrace.c |   10 ++++++++++
 1 file changed, 10 insertions(+)

kernel/trace/ftrace.c +10 -0

index b01ae7d36021..c060d5b47910 100644
@@ -5325,7 +5325,17 @@ static LIST_HEAD(ftrace_direct_funcs);
 
 static int register_ftrace_function_nolock(struct ftrace_ops *ops);
 
+/*
+ * If there are multiple ftrace_ops, use SAVE_REGS by default, so that direct
+ * call will be jumped from ftrace_regs_caller. Only if the architecture does
+ * not support ftrace_regs_caller but direct_call, use SAVE_ARGS so that it
+ * jumps from ftrace_caller for multiple ftrace_ops.
+ */
+#ifndef HAVE_DYNAMIC_FTRACE_WITH_REGS
 #define MULTI_FLAGS (FTRACE_OPS_FL_DIRECT | FTRACE_OPS_FL_SAVE_ARGS)
+#else
+#define MULTI_FLAGS (FTRACE_OPS_FL_DIRECT | FTRACE_OPS_FL_SAVE_REGS)
+#endif
 
 static int check_direct_multi(struct ftrace_ops *ops)
 {

Masami Hiramatsu (Google)

author maintainer

2024-01-10 12:33 UTC #2 lore raw

Quoted 54 lines · On Wed, 10 Jan 2024 12:20:21 +0000 Mark Rutland <[email protected]> wrote:

Quoted 53 lines · Masami Hiramatsu (Google)
From: Masami Hiramatsu (Google) <[email protected]>
The commit 60c8971899f3 ("ftrace: Make DIRECT_CALLS work WITH_ARGS and !WITH_REGS") changed DIRECT_CALLS to use SAVE_ARGS when there are multiple ftrace_ops at the same function, but since the x86 only support to jump to direct_call from ftrace_regs_caller, when we set the function tracer on the same target function on x86, ftrace-direct does not work as below (this actually works on arm64.)
At first, insmod ftrace-direct.ko to put a direct_call on 'wake_up_process()'.
 # insmod kernel/samples/ftrace/ftrace-direct.ko
 # less trace
...
          <idle>-0       [006] ..s1.   564.686958: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [007] ..s1.   564.687836: my_direct_func: waking up kcompactd0-63
          <idle>-0       [006] ..s1.   564.690926: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [006] ..s1.   564.696872: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [007] ..s1.   565.191982: my_direct_func: waking up kcompactd0-63
Setup a function filter to the 'wake_up_process' too, and enable it.
 # cd /sys/kernel/tracing/
 # echo wake_up_process > set_ftrace_filter
 # echo function > current_tracer
 # less trace
...
          <idle>-0       [006] ..s3.   686.180972: wake_up_process <-call_timer_fn
          <idle>-0       [006] ..s3.   686.186919: wake_up_process <-call_timer_fn
          <idle>-0       [002] ..s3.   686.264049: wake_up_process <-call_timer_fn
          <idle>-0       [002] d.h6.   686.515216: wake_up_process <-kick_pool
          <idle>-0       [002] d.h6.   686.691386: wake_up_process <-kick_pool
Then, only function tracer is shown on x86.
But if you enable 'kprobe on ftrace' event (which uses SAVE_REGS flag) on the same function, it is shown again.
 # echo 'p wake_up_process' >> dynamic_events
 # echo 1 > events/kprobes/p_wake_up_process_0/enable
 # echo > trace
 # less trace
...
          <idle>-0       [006] ..s2.  2710.345919: p_wake_up_process_0: (wake_up_process+0x4/0x20)
          <idle>-0       [006] ..s3.  2710.345923: wake_up_process <-call_timer_fn
          <idle>-0       [006] ..s1.  2710.345928: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [006] ..s2.  2710.349931: p_wake_up_process_0: (wake_up_process+0x4/0x20)
          <idle>-0       [006] ..s3.  2710.349934: wake_up_process <-call_timer_fn
          <idle>-0       [006] ..s1.  2710.349937: my_direct_func: waking up rcu_preempt-17
To fix this issue, use SAVE_REGS flag for multiple ftrace_ops flag of direct_call by default.

Quoted 6 lines

Quoted 3 lines
Fixes 60c8971899f3 ("ftrace: Make DIRECT_CALLS work WITH_ARGS and !WITH_REGS")
Cc [email protected]
Signed-off-by Masami Hiramatsu (Google) <[email protected]>
Sorry about this; I hadn't realised that x86 only supported direct calls when SAVE_REGS was requested.

Yeah, it is hard to find without my fprobe on fgraph series because all probes (kprobe/fprobe) and function-graph tracer uses SAVE_REGS. Only function tracer hits this issue, but usually ftrace-direct user will not use it with function tracer. So we were lucky to find it :)

Quoted 17 lines

The patch looks good to me. I applied it atop v6.7 and double-checked that this still works on arm64 as per your examples above, and everything looks good:

# mount -t tracefs none /sys/kernel/tracing/
# insmod ftrace-direct.ko 
# echo wake_up_process > /sys/kernel/tracing/set_ftrace_filter 
# echo function > /sys/kernel/tracing/current_tracer 
# less /sys/kernel/tracing/trace
..	
          <idle>-0       [007] ..s3.   172.932840: wake_up_process <-process_timeout
          <idle>-0       [007] ..s1.   172.932842: my_direct_func: waking up kcompactd0-62
          <idle>-0       [007] ..s3.   173.444836: wake_up_process <-process_timeout
          <idle>-0       [007] ..s1.   173.444838: my_direct_func: waking up kcompactd0-62
          <idle>-0       [001] d.h5.   173.471116: wake_up_process <-kick_pool
          <idle>-0       [001] d.h3.   173.471118: my_direct_func: waking up kworker/1:1-58

Quoted 2 lines

Reviewed-by Mark Rutland <[email protected]>
Tested-by Mark Rutland <[email protected]> [arm64]

Thank you!

Quoted 32 lines

Thanks,
Mark.

Quoted 27 lines

---
 kernel/trace/ftrace.c |   10 ++++++++++
 1 file changed, 10 insertions(+)

kernel/trace/ftrace.c +10 -0

index b01ae7d36021..c060d5b47910 100644
@@ -5325,7 +5325,17 @@ static LIST_HEAD(ftrace_direct_funcs);
 
 static int register_ftrace_function_nolock(struct ftrace_ops *ops);
 
+/*
+ * If there are multiple ftrace_ops, use SAVE_REGS by default, so that direct
+ * call will be jumped from ftrace_regs_caller. Only if the architecture does
+ * not support ftrace_regs_caller but direct_call, use SAVE_ARGS so that it
+ * jumps from ftrace_caller for multiple ftrace_ops.
+ */
+#ifndef HAVE_DYNAMIC_FTRACE_WITH_REGS
 #define MULTI_FLAGS (FTRACE_OPS_FL_DIRECT | FTRACE_OPS_FL_SAVE_ARGS)
+#else
+#define MULTI_FLAGS (FTRACE_OPS_FL_DIRECT | FTRACE_OPS_FL_SAVE_REGS)
+#endif
 
 static int check_direct_multi(struct ftrace_ops *ops)
 {

Signature · 1 line

Masami Hiramatsu (Google) <[email protected]>

Jiri Olsa

Acked-by on v1 1/1

2024-01-10 13:10 UTC #3 lore raw

In reply to Masami Hiramatsu (Google)

Quoted 50 lines · Masami Hiramatsu (Google)

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

At first, insmod ftrace-direct.ko to put a direct_call on 'wake_up_process()'.

 # insmod kernel/samples/ftrace/ftrace-direct.ko
 # less trace
...
          <idle>-0       [006] ..s1.   564.686958: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [007] ..s1.   564.687836: my_direct_func: waking up kcompactd0-63
          <idle>-0       [006] ..s1.   564.690926: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [006] ..s1.   564.696872: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [007] ..s1.   565.191982: my_direct_func: waking up kcompactd0-63

Setup a function filter to the 'wake_up_process' too, and enable it.

 # cd /sys/kernel/tracing/
 # echo wake_up_process > set_ftrace_filter
 # echo function > current_tracer
 # less trace
...
          <idle>-0       [006] ..s3.   686.180972: wake_up_process <-call_timer_fn
          <idle>-0       [006] ..s3.   686.186919: wake_up_process <-call_timer_fn
          <idle>-0       [002] ..s3.   686.264049: wake_up_process <-call_timer_fn
          <idle>-0       [002] d.h6.   686.515216: wake_up_process <-kick_pool
          <idle>-0       [002] d.h6.   686.691386: wake_up_process <-kick_pool

Then, only function tracer is shown on x86.
But if you enable 'kprobe on ftrace' event (which uses SAVE_REGS flag) on the same function, it is shown again.

 # echo 'p wake_up_process' >> dynamic_events
 # echo 1 > events/kprobes/p_wake_up_process_0/enable
 # echo > trace
 # less trace
...
          <idle>-0       [006] ..s2.  2710.345919: p_wake_up_process_0: (wake_up_process+0x4/0x20)
          <idle>-0       [006] ..s3.  2710.345923: wake_up_process <-call_timer_fn
          <idle>-0       [006] ..s1.  2710.345928: my_direct_func: waking up rcu_preempt-17
          <idle>-0       [006] ..s2.  2710.349931: p_wake_up_process_0: (wake_up_process+0x4/0x20)
          <idle>-0       [006] ..s3.  2710.349934: wake_up_process <-call_timer_fn
          <idle>-0       [006] ..s1.  2710.349937: my_direct_func: waking up rcu_preempt-17

Quoted 2 lines

To fix this issue, use SAVE_REGS flag for multiple ftrace_ops flag of direct_call by default.

nice catch

Acked-by Jiri Olsa <[email protected]>

jirka

Quoted 31 lines

Fixes 60c8971899f3 ("ftrace: Make DIRECT_CALLS work WITH_ARGS and !WITH_REGS")

Cc [email protected]

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

---
 kernel/trace/ftrace.c |   10 ++++++++++
 1 file changed, 10 insertions(+)

kernel/trace/ftrace.c +10 -0

index b01ae7d36021..c060d5b47910 100644
@@ -5325,7 +5325,17 @@ static LIST_HEAD(ftrace_direct_funcs);
 
 static int register_ftrace_function_nolock(struct ftrace_ops *ops);
 
+/*
+ * If there are multiple ftrace_ops, use SAVE_REGS by default, so that direct
+ * call will be jumped from ftrace_regs_caller. Only if the architecture does
+ * not support ftrace_regs_caller but direct_call, use SAVE_ARGS so that it
+ * jumps from ftrace_caller for multiple ftrace_ops.
+ */
+#ifndef HAVE_DYNAMIC_FTRACE_WITH_REGS
 #define MULTI_FLAGS (FTRACE_OPS_FL_DIRECT | FTRACE_OPS_FL_SAVE_ARGS)
+#else
+#define MULTI_FLAGS (FTRACE_OPS_FL_DIRECT | FTRACE_OPS_FL_SAVE_REGS)
+#endif
 
 static int check_direct_multi(struct ftrace_ops *ops)
 {