From nobody Sun Dec 14 08:06:54 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 2608922ACDB for ; Thu, 16 Jan 2025 14:53:28 +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=1737039209; cv=none; b=HMDwWdMGLuxnJ9lOWfE019ispndqWjtrXPucidoS1OR5fgG0Vt7w/fLhc+FBRMbgBTn6h0Z62e8mOocuH/oaxKLVPkG2/cSmmAA3SN2Pa22fT9rUidWtmmaNNyEhtFe41E+sZGMPnMC9q675tlZtlyQPwfz6AGi8PZ7A2ics/m8= ARC-Message-Signature: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1737039209; c=relaxed/simple; bh=92+AdIkRIskKFU/XwxzX80Zr6jgBJFgIMilxYKbx71M=; h=Date:From:To:Cc:Subject:Message-ID:MIME-Version:Content-Type; b=u93De0oPrTn+9+SoDbciwW0xNa7dK+3EkGimiIOZikdIZhk15rYKuEsZ2NNeAKrtz04cqzCU+iKi50Wu4r5eLJgFEGFeFmIH4D3WxyaK/ECbM3P9ElwqRybboKMrAueiO3FfiTgYkRTva9G2ZQKpfH/6S8rxF63+xMZb8zy6SxM= 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 06B84C4CEE1; Thu, 16 Jan 2025 14:53:27 +0000 (UTC) Date: Thu, 16 Jan 2025 09:53:33 -0500 From: Steven Rostedt To: Linus Torvalds Cc: LKML , Masami Hiramatsu , Mark Rutland , Mathieu Desnoyers , Shrikanth Hegde Subject: [GIT PULL] tracing: Fixes for v6.13-rc7 Message-ID: <20250116095333.5988c930@gandalf.local.home> X-Mailer: Claws Mail 3.20.0git84 (GTK+ 2.24.33; x86_64-pc-linux-gnu) 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" Linus, Tracing fixes for 6.13: - Fix a regression in the irqsoff and wakeup latency tracing The function graph tracer infrastructure has become generic so that fprobes and BPF can be based on it. As it use to only handle function graph tracing, it would always calculate the time the function entered so that it could then calculate the time it exits and give the length of time the function executed for. But this is not needed for the other users (fprobes and BPF) and reading the clock adds a non-negligible overhead, so the calculation was moved into the function graph tracer logic. But the irqsoff and wakeup latency tracers, when the "display-graph" option was set, would use the function graph tracer to calculate the times of functions during the latency. The movement of the calltime calculation made the value zero for these tracers, and the output no longer showed the length of time of each tracer, but instead the absolute timestamp of when the function returned (rettime - calltime where calltime is now zero). Have the irqsoff and wakeup latency tracers also do the calltime calculation as the function graph tracer does and report the proper length of the function timings. - Update the tracing display to reflect the new preempt lazy model When the system is configured with preempt lazy, the output of the trace data would state "unknown" for the current preemption model. Because the lazy preemption model was just added, make it known to the tracing subsystem too. This is just a one line change. - Document multiple function graph having slightly different timings Now that function graph tracer infrastructure is separate, this also allows the function graph tracer to run in multiple instances (it wasn't able to do so before). If two instances ran the function graph tracer and traced the same functions, the timings for them will be slightly different because each does their own timings and collects the timestamps differently. Document this to not have people be confused by it. Please pull the latest trace-v6.13-rc7 tree, which can be found at: git://git.kernel.org/pub/scm/linux/kernel/git/trace/linux-trace.git trace-v6.13-rc7 Tag SHA1: 343380d69115b113094248a3f6bd5f3e8b14ee59 Head SHA1: 94d529a3255ce65496e932173d7f13e801170597 Shrikanth Hegde (1): tracing: Print lazy preemption model Steven Rostedt (2): tracing: Fix irqsoff and wakeup latency tracers when using function g= raph ftrace: Document that multiple function_graph tracing may have differ= ent times ---- Documentation/trace/ftrace.rst | 6 ++++++ kernel/trace/trace.c | 1 + kernel/trace/trace_irqsoff.c | 14 ++++++++++++++ kernel/trace/trace_sched_wakeup.c | 14 ++++++++++++++ 4 files changed, 35 insertions(+) --------------------------- diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst index 272464bb7c60..2b74f96d09d5 100644 --- a/Documentation/trace/ftrace.rst +++ b/Documentation/trace/ftrace.rst @@ -810,6 +810,12 @@ Here is the list of current tracers that may be config= ured. to draw a graph of function calls similar to C code source. =20 + Note that the function graph calculates the timings of when the + function starts and returns internally and for each instance. If + there are two instances that run function graph tracer and traces + the same functions, the length of the timings may be slightly off as + each read the timestamp separately and not at the same time. + "blk" =20 The block tracer. The tracer used by the blktrace user diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index f8aebcb01e62..b6e40e8791fa 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -4122,6 +4122,7 @@ print_trace_header(struct seq_file *m, struct trace_i= terator *iter) preempt_model_none() ? "server" : preempt_model_voluntary() ? "desktop" : preempt_model_full() ? "preempt" : + preempt_model_lazy() ? "lazy" : preempt_model_rt() ? "preempt_rt" : "unknown", /* These are reserved for later use */ 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);