Date:	Fri, 2 May 2014 19:11:11 +0000
From:	"Elliott, Robert (Server Storage)" <Elliott@...com>
To:	"rostedt@...dmis.org" <rostedt@...dmis.org>,
	"fweisbec@...il.com" <fweisbec@...il.com>,
	"mingo@...hat.com" <mingo@...hat.com>
CC:	"linux-kernel (linux-kernel@...r.kernel.org)" 
	<linux-kernel@...r.kernel.org>
Subject: [RFC PATCH] ftrace function-graph: print the function name on all }
 lines

Using ftrace function-graph to examine the times consumed by
functions, the time shows up on the line where the call is made
if no other traceable functions were called by that function:
 11)   0.672 us    |    cmd_alloc [hpsa]();

but the time shows up down by the } if the were other traceable
functions called by that function:
 11)               |              cmd_alloc [hpsa]() {
 11)   0.129 us    |                cmd_free [hpsa]();
 11)   0.106 us    |                cmd_free [hpsa]();
 11)   2.014 us    |              }

On its own, the } line doesn't indicate which function it is
closing, so grep cannot be used to search for all the times
for this function. You have to write a parser.

The function name does get printed on those lines when the
start of the function is off the trace, so I modified 
trace_functions_graph.c to do that in all cases.

 11)               |    hpsa_scsi_ioaccel_raid_map [hpsa]() {
 11)               |      hpsa_scsi_ioaccel_queue_command [hpsa]() {
 11)               |        hpsa_scsi_ioaccel2_queue_command [hpsa]() {
 11)   0.067 us    |          fixup_ioaccel_cdb [hpsa]();
 11)   0.053 us    |          set_encrypt_ioaccel2 [hpsa]();
 11)   0.199 us    |          enqueue_cmd_and_start_io [hpsa]();
 11)   1.952 us    |        } /* hpsa_scsi_ioaccel2_queue_command [hpsa] */
 11)   2.501 us    |      } /* hpsa_scsi_ioaccel_queue_command [hpsa] */
 11)   3.093 us    |    } /* hpsa_scsi_ioaccel_raid_map [hpsa] */
 11)   4.667 us    |  } /* hpsa_scsi_queue_command [hpsa] */

rather than:
 11)               |    hpsa_scsi_ioaccel_raid_map [hpsa]() {
 11)               |      hpsa_scsi_ioaccel_queue_command [hpsa]() {
 11)               |        hpsa_scsi_ioaccel2_queue_command [hpsa]() {
 11)   0.067 us    |          fixup_ioaccel_cdb [hpsa]();
 11)   0.053 us    |          set_encrypt_ioaccel2 [hpsa]();
 11)   0.199 us    |          enqueue_cmd_and_start_io [hpsa]();
 11)   1.952 us    |        }
 11)   2.501 us    |      }
 11)   3.093 us    |    }
 11)   4.667 us    |  }

Is this a change you would be interested in taking, or
do you think that makes the output too cluttered?

A potential patch (based on kernel-3.14) is:

From: Robert Elliott <elliott@...com>

In the function-graph tracer, print the function name on
all } lines, not just functions whose first line is no
longer in the trace buffer.

If a function calls other traced functions, its total
time appears on its } line.  This change allows grep
to be used to determine the function for which the
line corresponds.

Signed-off-by: Robert Elliott <elliott@...com>
---
 kernel/trace/trace_functions_graph.c |   24 ++++++------------------
 1 files changed, 6 insertions(+), 18 deletions(-)

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 0b99120..d530a61 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -1130,7 +1130,6 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
 	struct fgraph_data *data = iter->private;
 	pid_t pid = ent->pid;
 	int cpu = iter->cpu;
-	int func_match = 1;
 	int ret;
 	int i;
 
@@ -1150,11 +1149,8 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
 		 */
 		cpu_data->depth = trace->depth - 1;
 
-		if (trace->depth < FTRACE_RETFUNC_DEPTH) {
-			if (cpu_data->enter_funcs[trace->depth] != trace->func)
-				func_match = 0;
+		if (trace->depth < FTRACE_RETFUNC_DEPTH)
 			cpu_data->enter_funcs[trace->depth] = 0;
-		}
 	}
 
 	if (print_graph_prologue(iter, s, 0, 0, flags))
@@ -1173,20 +1169,12 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
 	}
 
 	/*
-	 * If the return function does not have a matching entry,
-	 * then the entry was lost. Instead of just printing
-	 * the '}' and letting the user guess what function this
-	 * belongs to, write out the function name.
+	 * Write out the function name if the return
+	 * function has or does not have a matching entry.
 	 */
-	if (func_match) {
-		ret = trace_seq_puts(s, "}\n");
-		if (!ret)
-			return TRACE_TYPE_PARTIAL_LINE;
-	} else {
-		ret = trace_seq_printf(s, "} /* %ps */\n", (void *)trace->func);
-		if (!ret)
-			return TRACE_TYPE_PARTIAL_LINE;
-	}
+	ret = trace_seq_printf(s, "} /* %ps */\n", (void *)trace->func);
+	if (!ret)
+		return TRACE_TYPE_PARTIAL_LINE;
 
 	/* Overrun */
 	if (flags & TRACE_GRAPH_PRINT_OVERRUN) {


---
Rob Elliott    HP Server Storage


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Powered by blists - more mailing lists