[PATCH 1/2] ftrace: Fix preemption acounting for stacktrace trigger command

[PATCH 1/2] ftrace: Fix preemption acounting for stacktrace trigger command

[pengdonglin]

From: pengdonglin <pengdonglin@xiaomi.com>

While using the stacktrace trigger command to trace syscalls/sys_enter_read,
I noticed that the preemption count was consistently reported as 1, which seemed
incorrect:

root@ubuntu22-vm:/sys/kernel/tracing/events/syscalls/sys_enter_read
$ echo stacktrace > trigger
$ echo 1 > enable

    sshd-416     [002] .....   232.864910: sys_read(fd: a, buf: 556b1f3221d0, count: 8000)
    sshd-416     [002] ...1.   232.864913: <stack trace>
 => ftrace_syscall_enter
 => syscall_trace_enter
 => do_syscall_64
 => entry_SYSCALL_64_after_hwframe

The root cause is that the trace framework disables preemption in __DO_TRACE before
invoking the trigger callback.

This patch uses tracing_gen_ctx_dec() to obtain the correct preemption
count within the callback, resulting in accurate reporting:

    sshd-410     [004] .....   210.117660: sys_read(fd: 4, buf: 559b725ba130, count: 40000)
    sshd-410     [004] .....   210.117662: <stack trace>
 => ftrace_syscall_enter
 => syscall_trace_enter
 => do_syscall_64
 => entry_SYSCALL_64_after_hwframe

Signed-off-by: pengdonglin <dolinux.peng@gmail.com>
---
 kernel/trace/trace_events_trigger.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
index b66b6d235d91..6e87ae2a1a66 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -1560,7 +1560,7 @@ stacktrace_trigger(struct event_trigger_data *data,
 	struct trace_event_file *file = data->private_data;
 
 	if (file)
-		__trace_stack(file->tr, tracing_gen_ctx(), STACK_SKIP);
+		__trace_stack(file->tr, tracing_gen_ctx_dec(), STACK_SKIP);
 	else
 		trace_dump_stack(STACK_SKIP);
 }
-- 
2.25.1

[PATCH 2/2] ftrace: Fix preemption acounting for stacktrace filter command

[pengdonglin]

From: pengdonglin <pengdonglin@xiaomi.com>

While using the stacktrace filter command to trace ksys_read, I noticed
that the preemption count was consistently reported as 1, which seemed
incorrect:

$ echo ksys_read:stacktrace > set_ftrace_filter

   <...>-453     [004] ...1.    38.308956: <stack trace>
=> ksys_read
=> do_syscall_64
=> entry_SYSCALL_64_after_hwframe

The root cause is that the trace framework disables preemption when
invoking the filter command callback in function_trace_probe_call:

   preempt_disable_notrace();
   probe_ops->func(ip, parent_ip, probe_opsbe->tr, probe_ops, probe->data);
   preempt_enable_notrace();

This patch uses tracing_gen_ctx_dec() to obtain the correct preemption
count within the callback, resulting in accurate reporting:

$ echo ksys_read:stacktrace > set_ftrace_filter

   <...>-410     [006] .....    31.420396: <stack trace>
=> ksys_read
=> do_syscall_64
=> entry_SYSCALL_64_after_hwframe

Signed-off-by: pengdonglin <dolinux.peng@gmail.com>
---
 kernel/trace/trace_functions.c | 6 +-----
 1 file changed, 1 insertion(+), 5 deletions(-)

diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c
index 98ccf3f00c51..4e37a0f6aaa3 100644
--- a/kernel/trace/trace_functions.c
+++ b/kernel/trace/trace_functions.c
@@ -633,11 +633,7 @@ ftrace_traceoff(unsigned long ip, unsigned long parent_ip,
 
 static __always_inline void trace_stack(struct trace_array *tr)
 {
-	unsigned int trace_ctx;
-
-	trace_ctx = tracing_gen_ctx();
-
-	__trace_stack(tr, trace_ctx, FTRACE_STACK_SKIP);
+	__trace_stack(tr, tracing_gen_ctx_dec(), FTRACE_STACK_SKIP);
 }
 
 static void
-- 
2.25.1

Re: [PATCH 1/2] ftrace: Fix preemption acounting for stacktrace trigger command

[Steven Rostedt]

On Mon, 12 May 2025 17:42:45 +0800
pengdonglin <dolinux.peng@gmail.com> wrote:

> From: pengdonglin <pengdonglin@xiaomi.com>
> 
> While using the stacktrace trigger command to trace syscalls/sys_enter_read,
> I noticed that the preemption count was consistently reported as 1, which seemed
> incorrect:

FYI, the change log should always be in "imperative mood". The above is
fine for cover letters, but for the change log that will live forever in
the git history, it should not reference "I" nor "This patch". That is, it
should state:

   When using the stacktrace trigger command to trace syscalls, the
   preemption count was consistently reported as 1 when the system call
   event itself had 0 (".").

   For example:

> 
> root@ubuntu22-vm:/sys/kernel/tracing/events/syscalls/sys_enter_read
> $ echo stacktrace > trigger
> $ echo 1 > enable
> 
>     sshd-416     [002] .....   232.864910: sys_read(fd: a, buf: 556b1f3221d0, count: 8000)
>     sshd-416     [002] ...1.   232.864913: <stack trace>
>  => ftrace_syscall_enter
>  => syscall_trace_enter
>  => do_syscall_64
>  => entry_SYSCALL_64_after_hwframe  
> 
> The root cause is that the trace framework disables preemption in __DO_TRACE before
> invoking the trigger callback.
> 
> This patch uses tracing_gen_ctx_dec() to obtain the correct preemption
> count within the callback, resulting in accurate reporting:

Instead of "This patch ..."

   Use the tracing_gen_ctx_dec() that will accommodate for the increase of
   the preemption count in __DO_TRACE when calling the callback. The result
   is the accurate reporting of:

This is FYI for when you send new patches. You don't need to resend. I'll
update the change logs and take these patches (unless of course I find
something else wrong with them).

-- Steve

> 
>     sshd-410     [004] .....   210.117660: sys_read(fd: 4, buf: 559b725ba130, count: 40000)
>     sshd-410     [004] .....   210.117662: <stack trace>
>  => ftrace_syscall_enter
>  => syscall_trace_enter
>  => do_syscall_64
>  => entry_SYSCALL_64_after_hwframe  
> 
> Signed-off-by: pengdonglin <dolinux.peng@gmail.com>
> ---
>  kernel/trace/trace_events_trigger.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
> index b66b6d235d91..6e87ae2a1a66 100644
> --- a/kernel/trace/trace_events_trigger.c
> +++ b/kernel/trace/trace_events_trigger.c
> @@ -1560,7 +1560,7 @@ stacktrace_trigger(struct event_trigger_data *data,
>  	struct trace_event_file *file = data->private_data;
>  
>  	if (file)
> -		__trace_stack(file->tr, tracing_gen_ctx(), STACK_SKIP);
> +		__trace_stack(file->tr, tracing_gen_ctx_dec(), STACK_SKIP);
>  	else
>  		trace_dump_stack(STACK_SKIP);
>  }

Re: [PATCH 1/2] ftrace: Fix preemption acounting for stacktrace trigger command

[Donglin Peng]

On Mon, May 12, 2025 at 10:15 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Mon, 12 May 2025 17:42:45 +0800
> pengdonglin <dolinux.peng@gmail.com> wrote:
>
> > From: pengdonglin <pengdonglin@xiaomi.com>
> >
> > While using the stacktrace trigger command to trace syscalls/sys_enter_read,
> > I noticed that the preemption count was consistently reported as 1, which seemed
> > incorrect:
>
> FYI, the change log should always be in "imperative mood". The above is
> fine for cover letters, but for the change log that will live forever in
> the git history, it should not reference "I" nor "This patch". That is, it
> should state:
>
>    When using the stacktrace trigger command to trace syscalls, the
>    preemption count was consistently reported as 1 when the system call
>    event itself had 0 (".").
>
>    For example:
>
Thanks.

> >
> > root@ubuntu22-vm:/sys/kernel/tracing/events/syscalls/sys_enter_read
> > $ echo stacktrace > trigger
> > $ echo 1 > enable
> >
> >     sshd-416     [002] .....   232.864910: sys_read(fd: a, buf: 556b1f3221d0, count: 8000)
> >     sshd-416     [002] ...1.   232.864913: <stack trace>
> >  => ftrace_syscall_enter
> >  => syscall_trace_enter
> >  => do_syscall_64
> >  => entry_SYSCALL_64_after_hwframe
> >
> > The root cause is that the trace framework disables preemption in __DO_TRACE before
> > invoking the trigger callback.
> >
> > This patch uses tracing_gen_ctx_dec() to obtain the correct preemption
> > count within the callback, resulting in accurate reporting:
>
> Instead of "This patch ..."
>
>    Use the tracing_gen_ctx_dec() that will accommodate for the increase of
>    the preemption count in __DO_TRACE when calling the callback. The result
>    is the accurate reporting of:
>
> This is FYI for when you send new patches. You don't need to resend. I'll
> update the change logs and take these patches (unless of course I find
> something else wrong with them).
>
> -- Steve
>
Okay, thanks.

> >
> >     sshd-410     [004] .....   210.117660: sys_read(fd: 4, buf: 559b725ba130, count: 40000)
> >     sshd-410     [004] .....   210.117662: <stack trace>
> >  => ftrace_syscall_enter
> >  => syscall_trace_enter
> >  => do_syscall_64
> >  => entry_SYSCALL_64_after_hwframe
> >
> > Signed-off-by: pengdonglin <dolinux.peng@gmail.com>
> > ---
> >  kernel/trace/trace_events_trigger.c | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> >
> > diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
> > index b66b6d235d91..6e87ae2a1a66 100644
> > --- a/kernel/trace/trace_events_trigger.c
> > +++ b/kernel/trace/trace_events_trigger.c
> > @@ -1560,7 +1560,7 @@ stacktrace_trigger(struct event_trigger_data *data,
> >       struct trace_event_file *file = data->private_data;
> >
> >       if (file)
> > -             __trace_stack(file->tr, tracing_gen_ctx(), STACK_SKIP);
> > +             __trace_stack(file->tr, tracing_gen_ctx_dec(), STACK_SKIP);
> >       else
> >               trace_dump_stack(STACK_SKIP);
> >  }
>
>