Re: [PATCH] ftrace: Correct preemption accounting for function tracing.

[Steven Rostedt <rostedt@goodmis.org>]

On Thu, 20 Feb 2025 12:10:30 -0300
Wander Lairson Costa <wander@redhat.com> wrote:

> On Thu, Feb 20, 2025 at 03:07:49PM +0100, Sebastian Andrzej Siewior wrote:
> > The function tracer should record the preemption level at the point when
> > the function is invoked. If the tracing subsystem decrement the
> > preemption counter it needs to correct this before feeding the data into
> > the trace buffer. This was broken in the commit cited below while
> > shifting the preempt-disabled section.
> > 
> > Use tracing_gen_ctx_dec() which properly subtracts one from the
> > preemption counter on a preemptible kernel.
> > 
> > Cc: Wander Lairson Costa <wander@redhat.com>
> > Fixes: ce5e48036c9e7 ("ftrace: disable preemption when recursion locked")
> > Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
> > ---
> > I haven't been ftrace for quite some time if I got the fixes tag right.
> > 
> >  kernel/trace/trace_functions.c | 6 ++----
> >  1 file changed, 2 insertions(+), 4 deletions(-)
> > 
> > diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c
> > index d358c9935164d..df56f9b760109 100644
> > --- a/kernel/trace/trace_functions.c
> > +++ b/kernel/trace/trace_functions.c
> > @@ -216,7 +216,7 @@ function_trace_call(unsigned long ip, unsigned long parent_ip,
> >  
> >  	parent_ip = function_get_true_parent_ip(parent_ip, fregs);
> >  
> > -	trace_ctx = tracing_gen_ctx();
> > +	trace_ctx = tracing_gen_ctx_dec();
> >  
> >  	data = this_cpu_ptr(tr->array_buffer.data);
> >  	if (!atomic_read(&data->disabled))
> > @@ -321,7 +321,6 @@ function_no_repeats_trace_call(unsigned long ip, unsigned long parent_ip,
> >  	struct trace_array *tr = op->private;
> >  	struct trace_array_cpu *data;
> >  	unsigned int trace_ctx;
> > -	unsigned long flags;
> >  	int bit;
> >  
> >  	if (unlikely(!tr->function_enabled))
> > @@ -347,8 +346,7 @@ function_no_repeats_trace_call(unsigned long ip, unsigned long parent_ip,
> >  	if (is_repeat_check(tr, last_info, ip, parent_ip))
> >  		goto out;
> >  
> > -	local_save_flags(flags);
> > -	trace_ctx = tracing_gen_ctx_flags(flags);
> > +	trace_ctx = tracing_gen_ctx_dec();
> >  	process_repeats(tr, ip, parent_ip, last_info, trace_ctx);
> >  
> >  	trace_function(tr, ip, parent_ip, trace_ctx);
> > -- 
> > 2.47.2
> >   
> 
> It now reports the preemption count correctly:
> 
>     kworker/0:5-88      [000] b...3   211.972885: e1000_check_for_ack_vf <-e1000_write_posted_mbx
>      kworker/0:5-88      [000] b...3   211.983386: e1000_read_posted_mbx <-e1000_reset_hw_vf
>      kworker/0:5-88      [000] b...3   211.983389: e1000_init_hw_vf <-igbvf_reset
>      kworker/0:5-88      [000] b...3   211.983390: e1000_rar_set_vf <-e1000_init_hw_vf
>      kworker/0:5-88      [000] b...3   211.983390: e1000_write_posted_mbx <-e1000_rar_set_vf
>      kworker/0:5-88      [000] D.Zf2   211.983391: igbvf_reset_L14: (igbvf_reset+0x62/0x120 [igbvf])
>      kworker/0:5-88      [000] .N...   211.983396: igbvf_reset_L16: (igbvf_reset+0x7b/0x120 [igbvf])
>   irq/63-ens14f0-1122    [000] b...2   211.983399: igb_msix_other <-irq_thread_fn
>   irq/63-ens14f0-1122    [000] b...2   211.983399: igb_rd32 <-igb_msix_other
>   irq/63-ens14f0-1122    [000] b...3   211.983400: igb_check_for_rst <-igb_msix_other
>   irq/63-ens14f0-1122    [000] b...3   211.983400: igb_check_for_rst_pf <-igb_msix_other
>   irq/63-ens14f0-1122    [000] b...3   211.983400: igb_rd32 <-igb_check_for_rst_pf
>   irq/63-ens14f0-1122    [000] b...3   211.983401: igb_check_for_msg <-igb_msix_other
>   irq/63-ens14f0-1122    [000] b...3   211.983401: igb_check_for_msg_pf <-igb_msix_other
>   irq/63-ens14f0-1122    [000] b...3   211.983401: igb_rd32 <-igb_check_for_msg_pf
>   irq/63-ens14f0-1122    [000] b...3   211.983402: igb_check_for_ack <-igb_msix_other
>   irq/63-ens14f0-1122    [000] b...3   211.983402: igb_check_for_ack_pf <-igb_msix_other
> 
> (Except in line 6 where it show 'f', which seems to be an unrelated issue)

But it appears to be consistent.

Let me go and add some probes and see what they show. The output you gave
me that I requested didn't show anything unusual.

-- Steve