From nobody Wed Dec 17 06:12:18 2025 Received: from smtp.kernel.org (aws-us-west-2-korg-mail-1.web.codeaurora.org [10.30.226.201]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 55E1B1553B7 for ; Tue, 14 Jan 2025 14:53:26 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=10.30.226.201 ARC-Seal: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1736866408; cv=none; b=NDiRmOp5gaqOf7FuNofO1H9SXsM4p+MSHNeYESnmtr4uv/JzmHufNh9ETba4rdFCwdvB21g7D/sP+Cz60paW5gisxXU3YPXDwqQgTxU6DgH3yQzizDD+ZBX9ZzPINeOWNtYrXF6xA/38jyrNVDVGhtY17QznyPOWQk54EBiG6Ng= ARC-Message-Signature: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1736866408; c=relaxed/simple; bh=NCS3Gt/qTaHTxEeWrzKI+Efi0ZK+giE3T5aAqWJ1JWs=; h=Message-ID:Date:From:To:Cc:Subject:References:MIME-Version: Content-Type; b=imVrjuXA+6fiXFC3Qp+pMCZGBynx9zjfERuE18C0ldREtIr8m91GjMg9g1vkfp/v+b0pap+B6pGef2MO6enNOgNs5nFkUQ03xBahUe0q3nrHrblyhqWoCvuut3J3EUhrHhz/zQ6xirg3S4DMO+jqS8DgfmvOyAG8VErNyESn3EE= ARC-Authentication-Results: i=1; smtp.subspace.kernel.org; arc=none smtp.client-ip=10.30.226.201 Received: by smtp.kernel.org (Postfix) with ESMTPSA id A90E0C4CEE5; Tue, 14 Jan 2025 14:53:26 +0000 (UTC) Received: from rostedt by gandalf with local (Exim 4.98) (envelope-from ) id 1tXiIK-00000000FpJ-0F9U; Tue, 14 Jan 2025 09:53:28 -0500 Message-ID: <20250114145327.836654920@goodmis.org> User-Agent: quilt/0.68 Date: Tue, 14 Jan 2025 09:53:14 -0500 From: Steven Rostedt To: linux-kernel@vger.kernel.org Cc: Masami Hiramatsu , Mark Rutland , Mathieu Desnoyers , Andrew Morton Subject: [for-linus][PATCH 1/2] tracing: Fix irqsoff and wakeup latency tracers when using function graph References: <20250114145313.452899098@goodmis.org> Precedence: bulk X-Mailing-List: linux-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset="utf-8" From: Steven Rostedt The function graph tracer has become generic so that kretprobes and BPF can use it along with function graph tracing itself. Some of the infrastructure was specific for function graph tracing such as recording the calltime and return time of the functions. Calling the clock code on a high volume function does add overhead. The calculation of the calltime was removed from the generic code and placed into the function graph tracer itself so that the other users did not incur this overhead as they did not need that timestamp. The calltime field was still kept in the generic return entry structure and the function graph return entry callback filled it as that structure was passed to other code. But this broke both irqsoff and wakeup latency tracer as they still depended on the trace structure containing the calltime when the option display-graph is set as it used some of those same functions that the function graph tracer used. But now the calltime was not set and was just zero. This caused the calculation of the function time to be the absolute value of the return timestamp and not the length of the function. # cd /sys/kernel/tracing # echo 1 > options/display-graph # echo irqsoff > current_tracer The tracers went from: # REL TIME CPU TASK/PID |||| DURATION F= UNCTION CALLS # | | | | |||| | | = | | | | 0 us | 4) -0 | d..1. | 0.000 us | irqentry_ent= er(); 3 us | 4) -0 | d..2. | | irq_enter_rc= u() { 4 us | 4) -0 | d..2. | 0.431 us | preempt_co= unt_add(); 5 us | 4) -0 | d.h2. | | tick_irq_e= nter() { 5 us | 4) -0 | d.h2. | 0.433 us | tick_che= ck_oneshot_broadcast_this_cpu(); 6 us | 4) -0 | d.h2. | 2.426 us | ktime_ge= t(); 9 us | 4) -0 | d.h2. | | tick_noh= z_stop_idle() { 10 us | 4) -0 | d.h2. | 0.398 us | nr_iow= ait_cpu(); 11 us | 4) -0 | d.h1. | 1.903 us | } 11 us | 4) -0 | d.h2. | | tick_do_= update_jiffies64() { 12 us | 4) -0 | d.h2. | | _raw_s= pin_lock() { 12 us | 4) -0 | d.h2. | 0.360 us | pree= mpt_count_add(); 13 us | 4) -0 | d.h3. | 0.354 us | do_r= aw_spin_lock(); 14 us | 4) -0 | d.h2. | 2.207 us | } 15 us | 4) -0 | d.h3. | 0.428 us | calc_g= lobal_load(); 16 us | 4) -0 | d.h3. | | _raw_s= pin_unlock() { 16 us | 4) -0 | d.h3. | 0.380 us | do_r= aw_spin_unlock(); 17 us | 4) -0 | d.h3. | 0.334 us | pree= mpt_count_sub(); 18 us | 4) -0 | d.h1. | 1.768 us | } 18 us | 4) -0 | d.h2. | | update= _wall_time() { [..] To: # REL TIME CPU TASK/PID |||| DURATION F= UNCTION CALLS # | | | | |||| | | = | | | | 0 us | 5) -0 | d.s2. | 0.000 us | _raw_spin_lo= ck_irqsave(); 0 us | 5) -0 | d.s3. | 312159583 us | preempt= _count_add(); 2 us | 5) -0 | d.s4. | 312159585 us | do_raw_= spin_lock(); 3 us | 5) -0 | d.s4. | | _raw_spi= n_unlock() { 3 us | 5) -0 | d.s4. | 312159586 us | do_ra= w_spin_unlock(); 4 us | 5) -0 | d.s4. | 312159587 us | preem= pt_count_sub(); 4 us | 5) -0 | d.s2. | 312159587 us | } 5 us | 5) -0 | d.s3. | | _raw_spi= n_lock() { 5 us | 5) -0 | d.s3. | 312159588 us | preem= pt_count_add(); 6 us | 5) -0 | d.s4. | 312159589 us | do_ra= w_spin_lock(); 7 us | 5) -0 | d.s3. | 312159590 us | } 8 us | 5) -0 | d.s4. | 312159591 us | calc_wh= eel_index(); 9 us | 5) -0 | d.s4. | | enqueue_= timer() { 9 us | 5) -0 | d.s4. | | wake_u= p_nohz_cpu() { 11 us | 5) -0 | d.s4. | | nati= ve_smp_send_reschedule() { 11 us | 5) -0 | d.s4. | 312171987 us | d= efault_send_IPI_single_phys(); 12408 us | 5) -0 | d.s3. | 312171990 us | } 12408 us | 5) -0 | d.s3. | 312171991 us | } 12409 us | 5) -0 | d.s3. | 312171991 us | } Where the calculation of the time for each function was the return time minus zero and not the time of when the function returned. Have these tracers also save the calltime in the fgraph data section and retrieve it again on the return to get the correct timings again. Cc: Masami Hiramatsu Cc: Mathieu Desnoyers Cc: Mark Rutland Link: https://lore.kernel.org/20250113183124.61767419@gandalf.local.home Fixes: f1f36e22bee9 ("ftrace: Have calltime be saved in the fgraph storage") Signed-off-by: Steven Rostedt (Google) --- kernel/trace/trace_irqsoff.c | 14 ++++++++++++++ kernel/trace/trace_sched_wakeup.c | 14 ++++++++++++++ 2 files changed, 28 insertions(+) diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index fce064e20570..a4e799c1e767 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -182,6 +182,7 @@ static int irqsoff_graph_entry(struct ftrace_graph_ent = *trace, struct trace_array_cpu *data; unsigned long flags; unsigned int trace_ctx; + u64 *calltime; int ret; =20 if (ftrace_graph_ignore_func(gops, trace)) @@ -199,6 +200,12 @@ static int irqsoff_graph_entry(struct ftrace_graph_ent= *trace, if (!func_prolog_dec(tr, &data, &flags)) return 0; =20 + calltime =3D fgraph_reserve_data(gops->idx, sizeof(*calltime)); + if (!calltime) + return 0; + + *calltime =3D trace_clock_local(); + trace_ctx =3D tracing_gen_ctx_flags(flags); ret =3D __trace_graph_entry(tr, trace, trace_ctx); atomic_dec(&data->disabled); @@ -213,12 +220,19 @@ static void irqsoff_graph_return(struct ftrace_graph_= ret *trace, struct trace_array_cpu *data; unsigned long flags; unsigned int trace_ctx; + u64 *calltime; + int size; =20 ftrace_graph_addr_finish(gops, trace); =20 if (!func_prolog_dec(tr, &data, &flags)) return; =20 + calltime =3D fgraph_retrieve_data(gops->idx, &size); + if (!calltime) + return; + trace->calltime =3D *calltime; + trace_ctx =3D tracing_gen_ctx_flags(flags); __trace_graph_return(tr, trace, trace_ctx); atomic_dec(&data->disabled); diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_w= akeup.c index d6c7f18daa15..c58292e424d5 100644 --- a/kernel/trace/trace_sched_wakeup.c +++ b/kernel/trace/trace_sched_wakeup.c @@ -118,6 +118,7 @@ static int wakeup_graph_entry(struct ftrace_graph_ent *= trace, struct trace_array *tr =3D wakeup_trace; struct trace_array_cpu *data; unsigned int trace_ctx; + u64 *calltime; int ret =3D 0; =20 if (ftrace_graph_ignore_func(gops, trace)) @@ -135,6 +136,12 @@ static int wakeup_graph_entry(struct ftrace_graph_ent = *trace, if (!func_prolog_preempt_disable(tr, &data, &trace_ctx)) return 0; =20 + calltime =3D fgraph_reserve_data(gops->idx, sizeof(*calltime)); + if (!calltime) + return 0; + + *calltime =3D trace_clock_local(); + ret =3D __trace_graph_entry(tr, trace, trace_ctx); atomic_dec(&data->disabled); preempt_enable_notrace(); @@ -148,12 +155,19 @@ static void wakeup_graph_return(struct ftrace_graph_r= et *trace, struct trace_array *tr =3D wakeup_trace; struct trace_array_cpu *data; unsigned int trace_ctx; + u64 *calltime; + int size; =20 ftrace_graph_addr_finish(gops, trace); =20 if (!func_prolog_preempt_disable(tr, &data, &trace_ctx)) return; =20 + calltime =3D fgraph_retrieve_data(gops->idx, &size); + if (!calltime) + return; + trace->calltime =3D *calltime; + __trace_graph_return(tr, trace, trace_ctx); atomic_dec(&data->disabled); =20 --=20 2.45.2