diff options
author | Steven Rostedt (Google) <rostedt@goodmis.org> | 2024-01-11 17:13:05 -0500 |
---|---|---|
committer | Steven Rostedt (Google) <rostedt@goodmis.org> | 2024-01-11 17:50:25 -0500 |
commit | 7f078cfd20721234c7f2543ef235b79bf7e2e894 (patch) | |
tree | b0d69ff3378045f92860bc28c38df7878bdc8341 | |
parent | 1571b67c3ca2e1b6ad5f38559a4c224f710ca4fe (diff) | |
download | trace-cmd-7f078cfd20721234c7f2543ef235b79bf7e2e894.tar.gz |
libtracecmd: Break function graph line if exit is on another CPU
The function graph tracer has two events. One for the entry of a function,
and one for the exit. The ftrace tracing plugin will check the next event,
and if the exit event of a function follows directly after the entry of the
same function, it will combine them to look like:
123.456 us | func();
If some other event were to be between the events, then it will break it up:
| func() {
54.321 us | other_func();
123.456 us | }
But this could hide that a function migrated across CPUs.
For example:
migrate-14353 [001] dN.1. 66420.851920: funcgraph_entry: + 43.090 us | exit_to_user_mode_prepare();
Hides that the migrate program migrated between the entry of
exit_to_user_mode_prepare() and the exit, where looking at each event there is:
migrate-14353 [001] dN.1. 66420.851920: funcgraph_entry: | exit_to_user_mode_prepare() {
migrate-14353 [003] d.... 66420.851963: funcgraph_exit: + 43.090 us | }
Where it migrated from CPU 1 to 3.
Worse, it confuses the idle for which CPUs they were run on and for how long:
<idle>-0 [007] ...2. 66420.073288: funcgraph_entry: ! 268.817 us | do_idle();
<idle>-0 [004] ...2. 66420.073315: funcgraph_entry: ! 258.832 us | do_idle();
<idle>-0 [005] ...2. 66420.073323: funcgraph_entry: ! 157.311 us | do_idle();
Instead of:
<idle>-0 [007] ...2. 66420.073288: funcgraph_entry: | do_idle() {
<idle>-0 [004] ...1. 66420.073315: funcgraph_exit: ! 268.817 us | }
<idle>-0 [004] ...2. 66420.073315: funcgraph_entry: | do_idle() {
<idle>-0 [005] ...1. 66420.073322: funcgraph_exit: ! 258.832 us | }
<idle>-0 [005] ...2. 66420.073323: funcgraph_entry: | do_idle() {
<idle>-0 [000] ...1. 66420.073330: funcgraph_exit: ! 157.311 us | }
Where the first one shows 268.817us for CPU 7 when it was really for CPU 4.
Link: https://lore.kernel.org/linux-trace-devel/20240111171305.0bb529f0@gandalf.local.home
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
-rw-r--r-- | lib/trace-cmd/trace-ftrace.c | 8 |
1 files changed, 8 insertions, 0 deletions
diff --git a/lib/trace-cmd/trace-ftrace.c b/lib/trace-cmd/trace-ftrace.c index f74f7c2e..89e46c3d 100644 --- a/lib/trace-cmd/trace-ftrace.c +++ b/lib/trace-cmd/trace-ftrace.c @@ -283,6 +283,14 @@ fgraph_ent_handler(struct trace_seq *s, struct tep_record *record, return trace_seq_putc(s, '!'); rec = tracecmd_peek_next_data(tracecmd_curr_thread_handle, &cpu); + + /* + * If the next event is on another CPU, show it. + * Even if the next event is the return of this function. + */ + if (cpu != record->cpu) + rec = NULL; + if (rec) rec = get_return_for_leaf(s, cpu, pid, val, rec, finfo); |