diff mbox series

ftrace: Document that multiple function_graph tracing may have different times

Message ID 20250114101202.02e7bc68@gandalf.local.home (mailing list archive)
State Accepted
Commit 94d529a3255ce65496e932173d7f13e801170597
Headers show
Series ftrace: Document that multiple function_graph tracing may have different times | expand

Commit Message

Steven Rostedt Jan. 14, 2025, 3:12 p.m. UTC
From: Steven Rostedt <rostedt@goodmis.org>

The function graph tracer now calculates the calltime internally and for
each instance. If there are two instances that are running function graph
tracer and are tracing the same functions, the timings of the length of
those functions may be slightly different:

 # trace-cmd record -B foo -p function_graph -B bar -p function_graph sleep 5
 # trace-cmd report
[..]
bar:            sleep-981   [000] ...1.  1101.109027: funcgraph_entry:        0.764 us   |          mutex_unlock(); (ret=0xffff8abcc256c300)
foo:            sleep-981   [000] ...1.  1101.109028: funcgraph_entry:        0.748 us   |          mutex_unlock(); (ret=0xffff8abcc256c300)
bar:            sleep-981   [000] .....  1101.109029: funcgraph_exit:         2.456 us   |        } (ret=0xffff8abcc256c300)
foo:            sleep-981   [000] .....  1101.109029: funcgraph_exit:         2.403 us   |        } (ret=0xffff8abcc256c300)
bar:            sleep-981   [000] d..1.  1101.109031: funcgraph_entry:        0.844 us   |  fpregs_assert_state_consistent(); (ret=0x0)
foo:            sleep-981   [000] d..1.  1101.109032: funcgraph_entry:        0.803 us   |  fpregs_assert_state_consistent(); (ret=0x0)

Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
 Documentation/trace/ftrace.rst | 6 ++++++
 1 file changed, 6 insertions(+)

Comments

Steven Rostedt Jan. 14, 2025, 3:47 p.m. UTC | #1
On Tue, 14 Jan 2025 10:12:02 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> From: Steven Rostedt <rostedt@goodmis.org>
> 
> The function graph tracer now calculates the calltime internally and for
> each instance. If there are two instances that are running function graph
> tracer and are tracing the same functions, the timings of the length of
> those functions may be slightly different:
> 
>  # trace-cmd record -B foo -p function_graph -B bar -p function_graph sleep 5
>  # trace-cmd report
> [..]
> bar:            sleep-981   [000] ...1.  1101.109027: funcgraph_entry:        0.764 us   |          mutex_unlock(); (ret=0xffff8abcc256c300)
> foo:            sleep-981   [000] ...1.  1101.109028: funcgraph_entry:        0.748 us   |          mutex_unlock(); (ret=0xffff8abcc256c300)
> bar:            sleep-981   [000] .....  1101.109029: funcgraph_exit:         2.456 us   |        } (ret=0xffff8abcc256c300)
> foo:            sleep-981   [000] .....  1101.109029: funcgraph_exit:         2.403 us   |        } (ret=0xffff8abcc256c300)
> bar:            sleep-981   [000] d..1.  1101.109031: funcgraph_entry:        0.844 us   |  fpregs_assert_state_consistent(); (ret=0x0)
> foo:            sleep-981   [000] d..1.  1101.109032: funcgraph_entry:        0.803 us   |  fpregs_assert_state_consistent(); (ret=0x0)
> 

I added:

  Link: https://lore.kernel.org/all/20250114101806.b2778cb01f34f5be9d23ad98@kernel.org/
 
  Suggested-by: Masami Hiramatsu <mhiramat@kernel.org>

To this as well.

-- Steve

> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
> ---
>  Documentation/trace/ftrace.rst | 6 ++++++
>  1 file changed, 6 insertions(+)
diff mbox series

Patch

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 configured.
 	to draw a graph of function calls similar to C code
 	source.
 
+	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"
 
 	The block tracer. The tracer used by the blktrace user