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 <wan...@redhat.com>
> Fixes: ce5e48036c9e7 ("ftrace: disable preemption when recursion locked")
> Signed-off-by: Sebastian Andrzej Siewior <bige...@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)
Tested-by: Wander Lairson Costa <wan...@redhat.com>
