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>

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index b3749a2c3132b00bc0779c84c8b9096102fa52fc..ee791a9650c5b1dd03f6d4d8a518f9e8c827e86d 100644 (file)
--- 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");