tracing: add latency format to function_graph tracer

While debugging something with the function_graph tracer, I found the
need to see the preempt count of the traces. Unfortunately, since
the function graph tracer has its own output formatting, it does not
honor the latency-format option.

This patch makes the function_graph tracer honor the latency-format
option, but still keeps control of the output. But now we have the
same details that the latency-format supplies.

 # tracer: function_graph
 #
 #      _-----=> irqs-off
 #     / _----=> need-resched
 #    | / _---=> hardirq/softirq
 #    || / _--=> preempt-depth
 #    ||| /
 #    ||||
 # CPU||||  DURATION                  FUNCTION CALLS
 # |  ||||   |   |                     |   |   |   |
  3)  d..1  1.333 us    |        idle_cpu();
  3)  d.h1              |        tick_check_idle() {
  3)  d.h1  0.550 us    |          tick_check_oneshot_broadcast();
  3)  d.h1              |          tick_nohz_stop_idle() {
  3)  d.h1              |            ktime_get() {
  3)  d.h1              |              ktime_get_ts() {

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

1 files changed, 68 insertions, 6 deletions

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index b3749a2c3132..ee791a9650c5 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -364,6 +364,29 @@ print_graph_proc(struct trace_seq *s, pid_t pid)
 }
 
 
+static enum print_line_t
+print_graph_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
+{
+        int hardirq, softirq;
+
+        hardirq = entry->flags & TRACE_FLAG_HARDIRQ;
+        softirq = entry->flags & TRACE_FLAG_SOFTIRQ;
+
+        if (!trace_seq_printf(s, " %c%c%c",
+                              (entry->flags & TRACE_FLAG_IRQS_OFF) ? 'd' :
+                                (entry->flags & TRACE_FLAG_IRQS_NOSUPPORT) ?
+                                  'X' : '.',
+                              (entry->flags & TRACE_FLAG_NEED_RESCHED) ?
+                                'N' : '.',
+                              (hardirq && softirq) ? 'H' :
+                                hardirq ? 'h' : softirq ? 's' : '.'))
+                return 0;
+
+        if (entry->preempt_count)
+                return trace_seq_printf(s, "%x", entry->preempt_count);
+        return trace_seq_puts(s, ".");
+}
+
 /* If the pid changed since the last trace, output this event */
 static enum print_line_t
 verif_pid(struct trace_seq *s, pid_t pid, int cpu, struct fgraph_data *data)
@@ -521,6 +544,7 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
                 if (ret == TRACE_TYPE_PARTIAL_LINE)
                         return TRACE_TYPE_PARTIAL_LINE;
         }
+
         /* Proc */
         if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
                 ret = print_graph_proc(s, pid);
@@ -758,6 +782,13 @@ print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
                         return TRACE_TYPE_PARTIAL_LINE;
         }
 
+        /* Latency format */
+        if (trace_flags & TRACE_ITER_LATENCY_FMT) {
+                ret = print_graph_lat_fmt(s, ent);
+                if (ret == TRACE_TYPE_PARTIAL_LINE)
+                        return TRACE_TYPE_PARTIAL_LINE;
+        }
+
         return 0;
 }
 
@@ -952,28 +983,59 @@ print_graph_function(struct trace_iterator *iter)
         return TRACE_TYPE_HANDLED;
 }
 
+static void print_lat_header(struct seq_file *s)
+{
+        static const char spaces[] = "                " /* 16 spaces */
+                "    "                                  /* 4 spaces */
+                "                 ";                    /* 17 spaces */
+        int size = 0;
+
+        if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
+                size += 16;
+        if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
+                size += 4;
+        if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
+                size += 17;
+
+        seq_printf(s, "#%.*s  _-----=> irqs-off        \n", size, spaces);
+        seq_printf(s, "#%.*s / _----=> need-resched    \n", size, spaces);
+        seq_printf(s, "#%.*s| / _---=> hardirq/softirq \n", size, spaces);
+        seq_printf(s, "#%.*s|| / _--=> preempt-depth   \n", size, spaces);
+        seq_printf(s, "#%.*s||| /                      \n", size, spaces);
+        seq_printf(s, "#%.*s||||                       \n", size, spaces);
+}
+
 static void print_graph_headers(struct seq_file *s)
 {
+        int lat = trace_flags & TRACE_ITER_LATENCY_FMT;
+
+        if (lat)
+                print_lat_header(s);
+
         /* 1st line */
-        seq_printf(s, "# ");
+        seq_printf(s, "#");
         if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
                 seq_printf(s, "     TIME       ");
         if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
-                seq_printf(s, "CPU");
+                seq_printf(s, " CPU");
         if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
-                seq_printf(s, "  TASK/PID      ");
+                seq_printf(s, "  TASK/PID       ");
+        if (lat)
+                seq_printf(s, "||||");
         if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
                 seq_printf(s, "  DURATION   ");
         seq_printf(s, "               FUNCTION CALLS\n");
 
         /* 2nd line */
-        seq_printf(s, "# ");
+        seq_printf(s, "#");
         if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
                 seq_printf(s, "      |         ");
         if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
-                seq_printf(s, "|  ");
+                seq_printf(s, " |  ");
         if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
-                seq_printf(s, "  |    |        ");
+                seq_printf(s, "   |    |        ");
+        if (lat)
+                seq_printf(s, "||||");
         if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
                 seq_printf(s, "   |   |      ");
         seq_printf(s, "               |   |   |   |\n");