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(+)
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index b01ae7d36021..c060d5b47910 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -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)
{
On Wed, Jan 10, 2024 at 09:13:06AM +0900, Masami Hiramatsu (Google) wrote:
> 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]>
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.
> ---
> kernel/trace/ftrace.c | 10 ++++++++++
> 1 file changed, 10 insertions(+)
>
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index b01ae7d36021..c060d5b47910 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -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)
> {
>
On Wed, 10 Jan 2024 12:20:21 +0000
Mark Rutland <[email protected]> wrote:
> On Wed, Jan 10, 2024 at 09:13:06AM +0900, Masami Hiramatsu (Google) wrote:
> > 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]>
>
> 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 :)
>
> 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]
Thank you!
>
> Thanks,
> Mark.
>
> > ---
> > kernel/trace/ftrace.c | 10 ++++++++++
> > 1 file changed, 10 insertions(+)
> >
> > diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> > index b01ae7d36021..c060d5b47910 100644
> > --- a/kernel/trace/ftrace.c
> > +++ b/kernel/trace/ftrace.c
> > @@ -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) <[email protected]>
On Wed, Jan 10, 2024 at 09:13:06AM +0900, Masami Hiramatsu (Google) wrote:
> 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.
nice catch
Acked-by: Jiri Olsa <[email protected]>
jirka
>
> 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(+)
>
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index b01ae7d36021..c060d5b47910 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -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)
> {
>