[PATCH 19/19] perf ftrace: Tidy up the function graph output of 'show' subcommand

[Namhyung Kim <namhyung@kernel.org>]

From: Namhyung Kim <namhyung.kim@lge.com>

Now it doesn't call pevent_print_event() but prints context info in
itself using print_graph_duration().  Make it compact by only print
cpu number and duration:

  # perf ftrace show
  ...
   10)   0.065 us |  __fsnotify_parent();
   10)            |  fsnotify() {
   10)   0.060 us |    __srcu_read_lock();
   10)   0.040 us |    __srcu_read_unlock();
   10)   0.652 us |  }
   10)   0.040 us |  fput();
   10)            |  __audit_syscall_exit() {
   10)            |    path_put() {
   10)   0.037 us |      dput();
   10)   0.032 us |      mntput();
   10)   0.563 us |    }
   10)   0.035 us |    unroll_tree_refs();
   10)   0.035 us |    kfree();
   10)   1.284 us |  }
   10)            |  __audit_syscall_entry() {
   10)   0.029 us |    current_kernel_time();
   10)   0.239 us |  }


Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/builtin-ftrace.c | 35 +++++++++++++++++++++++++++++++++--
 1 file changed, 33 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-ftrace.c b/tools/perf/builtin-ftrace.c
index f17269db3121..7905b7b777d0 100644
--- a/tools/perf/builtin-ftrace.c
+++ b/tools/perf/builtin-ftrace.c
@@ -865,6 +865,27 @@ static struct pevent_record *get_ordered_record(struct perf_ftrace *ftrace);
 
 static struct event_format *fgraph_exit_event;
 
+static void
+print_graph_duration(struct trace_seq *s, struct event_format *event,
+		     struct pevent_record *record)
+{
+	unsigned long long duration;
+	unsigned long long rettime, calltime;
+	unsigned long usec, nsec;
+
+	if (pevent_get_field_val(s, event, "rettime", record, &rettime, 1))
+		return;
+
+	if (pevent_get_field_val(s, event, "calltime", record, &calltime, 1))
+		return;
+
+	duration = rettime - calltime;
+	usec = duration / 1000;
+	nsec = duration % 1000;
+
+	trace_seq_printf(s, "%3d) %3lu.%03lu us |  ", record->cpu, usec, nsec);
+}
+
 static int
 fgraph_ent_handler(struct trace_seq *s, struct pevent_record *record,
 		   struct event_format *event, void *context)
@@ -897,9 +918,14 @@ fgraph_ent_handler(struct trace_seq *s, struct pevent_record *record,
 	if (next && next->cpu == record->cpu &&
 	    pevent_data_type(event->pevent, next) == fgraph_exit_event->id) {
 		is_leaf = true;
+
+		print_graph_duration(s, fgraph_exit_event, next);
+
 		/* consume record */
 		get_ordered_record(ftrace);
 		free(next);
+	} else {
+		trace_seq_printf(s, "%3d) %*s |  ", record->cpu, 10, "");
 	}
 
 nested:
@@ -940,6 +966,8 @@ fgraph_ret_handler(struct trace_seq *s, struct pevent_record *record,
 	unsigned long long depth;
 	int i;
 
+	print_graph_duration(s, event, record);
+
 	if (pevent_get_field_val(s, event, "depth", record, &depth, 1))
 		return trace_seq_putc(s, '!');
 
@@ -1243,9 +1271,12 @@ static int do_ftrace_show(struct perf_ftrace *ftrace)
 			continue;
 		}
 
-		pevent_print_event(ftrace->pevent, &seq, record);
-		trace_seq_do_printf(&seq);
+		if (!strcmp(ftrace->tracer, "function_graph"))
+			pevent_event_info(&seq, event, record);
+		else
+			pevent_print_event(ftrace->pevent, &seq, record);
 
+		trace_seq_do_printf(&seq);
 		trace_seq_reset(&seq);
 
 		free(record);
-- 
1.7.11.7