[PATCH 0/2] ftrace: Add funcgraph_tail option

[PATCH 0/2] ftrace: Add funcgraph_tail option

[Robert Elliott]

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.

This patch series adds a funcgraph-tail option to do that
in all cases.

echo 1 > /sys/kernel/debug/tracing/options/funcgraph-tail
or
echo funcgraph-tail > /sys/kernel/debug/tracing/trace_options
yields:
 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] */

echo 0 > /sys/kernel/debug/tracing/options/funcgraph-tail
or
echo nofuncgraph-tail > /sys/kernel/debug/tracing/trace_options
(which is the default setting) still yields:
 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    |  }


---

Robert Elliott (2):
      Eliminate duplicate TRACE_GRAPH_PRINT_xx defines
      In the function-graph tracer, add a funcgraph_tail option


 Documentation/trace/ftrace.txt       |   26 ++++++++++++++++++++++++++
 kernel/trace/trace.h                 |    2 ++
 kernel/trace/trace_functions_graph.c |   18 ++++++------------
 3 files changed, 34 insertions(+), 12 deletions(-)

--
Rob Elliott   HP Server Storage

[PATCH 1/2] Eliminate duplicate TRACE_GRAPH_PRINT_xx defines

[Robert Elliott]

in trace_functions_graph.c that are already in
trace.h.

Add TRACE_GRAPH_PRINT_IRQS to trace.h, which is
the only one that is missing.

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

diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 2e29d7b..861668a 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -724,6 +724,7 @@ extern unsigned long trace_flags;
 #define TRACE_GRAPH_PRINT_PROC          0x8
 #define TRACE_GRAPH_PRINT_DURATION      0x10
 #define TRACE_GRAPH_PRINT_ABS_TIME      0x20
+#define TRACE_GRAPH_PRINT_IRQS          0x40
 #define TRACE_GRAPH_PRINT_FILL_SHIFT	28
 #define TRACE_GRAPH_PRINT_FILL_MASK	(0x3 << TRACE_GRAPH_PRINT_FILL_SHIFT)
 
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index deff112..ab78221 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -38,15 +38,6 @@ struct fgraph_data {
 
 #define TRACE_GRAPH_INDENT	2
 
-/* Flag options */
-#define TRACE_GRAPH_PRINT_OVERRUN	0x1
-#define TRACE_GRAPH_PRINT_CPU		0x2
-#define TRACE_GRAPH_PRINT_OVERHEAD	0x4
-#define TRACE_GRAPH_PRINT_PROC		0x8
-#define TRACE_GRAPH_PRINT_DURATION	0x10
-#define TRACE_GRAPH_PRINT_ABS_TIME	0x20
-#define TRACE_GRAPH_PRINT_IRQS		0x40
-
 static unsigned int max_depth;
 
 static struct tracer_opt trace_opts[] = {

[PATCH 2/2] In the function-graph tracer, add a funcgraph_tail option

[Robert Elliott]

to 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.

Update Documentation/trace/ftrace.txt to describe
this new option.

Signed-off-by: Robert Elliott <elliott@hp.com>
---
 Documentation/trace/ftrace.txt       |   26 ++++++++++++++++++++++++++
 kernel/trace/trace.h                 |    1 +
 kernel/trace/trace_functions_graph.c |    9 ++++++---
 3 files changed, 33 insertions(+), 3 deletions(-)

diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt
index bd36598..2479b2a 100644
--- a/Documentation/trace/ftrace.txt
+++ b/Documentation/trace/ftrace.txt
@@ -2003,6 +2003,32 @@ want, depending on your needs.
   360.774530 |   1)   0.594 us    |                                          __phys_addr();
 
 
+The function name is always displayed after the closing bracket
+for a function if the start of that function is not in the
+trace buffer.
+
+Display of the function name after the closing bracket may be
+enabled for functions whose start is in the trace buffer,
+allowing easier searching with grep for function durations.
+It is default disabled.
+
+	hide: echo nofuncgraph-tail > trace_options
+	show: echo funcgraph-tail > trace_options
+
+  Example with nofuncgraph-tail (default):
+  0)               |      putname() {
+  0)               |        kmem_cache_free() {
+  0)   0.518 us    |          __phys_addr();
+  0)   1.757 us    |        }
+  0)   2.861 us    |      }
+
+  Example with funcgraph-tail:
+  0)               |      putname() {
+  0)               |        kmem_cache_free() {
+  0)   0.518 us    |          __phys_addr();
+  0)   1.757 us    |        } /* kmem_cache_free() */
+  0)   2.861 us    |      } /* putname() */
+
 You can put some comments on specific functions by using
 trace_printk() For example, if you want to put a comment inside
 the __might_sleep() function, you just have to include
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 861668a..5ca365f 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -725,6 +725,7 @@ extern unsigned long trace_flags;
 #define TRACE_GRAPH_PRINT_DURATION      0x10
 #define TRACE_GRAPH_PRINT_ABS_TIME      0x20
 #define TRACE_GRAPH_PRINT_IRQS          0x40
+#define TRACE_GRAPH_PRINT_TAIL          0x80
 #define TRACE_GRAPH_PRINT_FILL_SHIFT	28
 #define TRACE_GRAPH_PRINT_FILL_MASK	(0x3 << TRACE_GRAPH_PRINT_FILL_SHIFT)
 
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index ab78221..ba10bb0 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -55,11 +55,13 @@ static struct tracer_opt trace_opts[] = {
 	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
 	/* Display interrupts */
 	{ TRACER_OPT(funcgraph-irqs, TRACE_GRAPH_PRINT_IRQS) },
+	/* Display function name after trailing } */
+	{ TRACER_OPT(funcgraph-tail, TRACE_GRAPH_PRINT_TAIL) },
 	{ } /* Empty entry */
 };
 
 static struct tracer_flags tracer_flags = {
-	/* Don't display overruns and proc by default */
+	/* Don't display overruns, proc, or tail by default */
 	.val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD |
 	       TRACE_GRAPH_PRINT_DURATION | TRACE_GRAPH_PRINT_IRQS,
 	.opts = trace_opts
@@ -1167,9 +1169,10 @@ 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.
+	 * belongs to, write out the function name. Always do
+	 * that if the funcgraph-tail option is enabled.
 	 */
-	if (func_match) {
+	if (func_match && !(flags & TRACE_GRAPH_PRINT_TAIL)) {
 		ret = trace_seq_puts(s, "}\n");
 		if (!ret)
 			return TRACE_TYPE_PARTIAL_LINE;