tracing/function-graph-tracer: fix traces weirdness while absolute time printing

Impact: trace output cleanup/reordering

When an interrupt occurs and and the abstime option is selected:

  echo funcgraph-abstime > /debug/tracing/trace_options

then we observe broken traces:

30581.025422 |   0)   Xorg-4291    |   0.503 us    |      idle_cpu();
30581.025424 |   0)   Xorg-4291    |   2.576 us    |    }
30581.025424 |   0)   Xorg-4291    | + 75.771 us   |  }
 0)   Xorg-4291    |   <========== |
30581.025425 |   0)   Xorg-4291    |               |  schedule() {
30581.025426 |   0)   Xorg-4291    |               |    __schedule() {
30581.025426 |   0)   Xorg-4291    |   0.705 us    |      _spin_lock_irq();

With this patch, the interrupts output better adapts
to absolute time printing:

  414.856543 |   1)   Xorg-4279    |   8.816 us    |                        }
  414.856544 |   1)   Xorg-4279    |   0.525 us    |                        rcu_irq_exit();
  414.856545 |   1)   Xorg-4279    |   0.526 us    |                        idle_cpu();
  414.856546 |   1)   Xorg-4279    | + 12.157 us   |                      }
  414.856549 |   1)   Xorg-4279    | ! 104.114 us  |                    }
  414.856549 |   1)   Xorg-4279    |   <========== |
  414.856549 |   1)   Xorg-4279    | ! 107.944 us  |                  }
  414.856550 |   1)   Xorg-4279    | ! 137.010 us  |                }
  414.856551 |   1)   Xorg-4279    |   0.624 us    |                _read_unlock();
  414.856552 |   1)   Xorg-4279    | ! 140.930 us  |              }
  414.856552 |   1)   Xorg-4279    | ! 166.159 us  |            }

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 6c7738e..8f4004a 100644 (file)
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -351,16 +351,35 @@ print_graph_overhead(unsigned long long duration, struct trace_seq *s)
        return trace_seq_printf(s, "  ");
 }
 
+static int print_graph_abs_time(u64 t, struct trace_seq *s)
+{
+       unsigned long usecs_rem;
+
+       usecs_rem = do_div(t, NSEC_PER_SEC);
+       usecs_rem /= 1000;
+
+       return trace_seq_printf(s, "%5lu.%06lu |  ",
+                       (unsigned long)t, usecs_rem);
+}
+
 static enum print_line_t
-print_graph_irq(struct trace_seq *s, unsigned long addr,
+print_graph_irq(struct trace_iterator *iter, unsigned long addr,
                enum trace_type type, int cpu, pid_t pid)
 {
        int ret;
+       struct trace_seq *s = &iter->seq;
 
        if (addr < (unsigned long)__irqentry_text_start ||
                addr >= (unsigned long)__irqentry_text_end)
                return TRACE_TYPE_UNHANDLED;
 
+       /* Absolute time */
+       if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) {
+               ret = print_graph_abs_time(iter->ts, s);
+               if (!ret)
+                       return TRACE_TYPE_PARTIAL_LINE;
+       }
+
        /* Cpu */
        if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
                ret = print_graph_cpu(s, cpu);
@@ -446,17 +465,6 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s)
 
 }
 
-static int print_graph_abs_time(u64 t, struct trace_seq *s)
-{
-       unsigned long usecs_rem;
-
-       usecs_rem = do_div(t, 1000000000);
-       usecs_rem /= 1000;
-
-       return trace_seq_printf(s, "%5lu.%06lu |  ",
-                       (unsigned long)t, usecs_rem);
-}
-
 /* Case of a leaf function on its call entry */
 static enum print_line_t
 print_graph_entry_leaf(struct trace_iterator *iter,
@@ -561,7 +569,7 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
                return TRACE_TYPE_PARTIAL_LINE;
 
        /* Interrupt */
-       ret = print_graph_irq(s, call->func, TRACE_GRAPH_ENT, cpu, ent->pid);
+       ret = print_graph_irq(iter, call->func, TRACE_GRAPH_ENT, cpu, ent->pid);
        if (ret == TRACE_TYPE_PARTIAL_LINE)
                return TRACE_TYPE_PARTIAL_LINE;
 
@@ -581,7 +589,7 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
 
        /* Proc */
        if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
-               ret = print_graph_proc(s, ent->pid);
+               ret = print_graph_proc(s, pid);
                if (ret == TRACE_TYPE_PARTIAL_LINE)
                        return TRACE_TYPE_PARTIAL_LINE;
 
@@ -605,11 +613,11 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
        int i;
        int ret;
        int cpu = iter->cpu;
-       pid_t *last_pid = iter->private;
+       pid_t *last_pid = iter->private, pid = ent->pid;
        unsigned long long duration = trace->rettime - trace->calltime;
 
        /* Pid */
-       if (verif_pid(s, ent->pid, cpu, last_pid) == TRACE_TYPE_PARTIAL_LINE)
+       if (verif_pid(s, pid, cpu, last_pid) == TRACE_TYPE_PARTIAL_LINE)
                return TRACE_TYPE_PARTIAL_LINE;
 
        /* Absolute time */
@@ -668,7 +676,7 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
                        return TRACE_TYPE_PARTIAL_LINE;
        }
 
-       ret = print_graph_irq(s, trace->func, TRACE_GRAPH_RET, cpu, ent->pid);
+       ret = print_graph_irq(iter, trace->func, TRACE_GRAPH_RET, cpu, pid);
        if (ret == TRACE_TYPE_PARTIAL_LINE)
                return TRACE_TYPE_PARTIAL_LINE;
 
@@ -684,6 +692,10 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
        int cpu = iter->cpu;
        pid_t *last_pid = iter->private;
 
+       /* Pid */
+       if (verif_pid(s, ent->pid, cpu, last_pid) == TRACE_TYPE_PARTIAL_LINE)
+               return TRACE_TYPE_PARTIAL_LINE;
+
        /* Absolute time */
        if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) {
                ret = print_graph_abs_time(iter->ts, s);
@@ -691,10 +703,6 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
                        return TRACE_TYPE_PARTIAL_LINE;
        }
 
-       /* Pid */
-       if (verif_pid(s, ent->pid, cpu, last_pid) == TRACE_TYPE_PARTIAL_LINE)
-               return TRACE_TYPE_PARTIAL_LINE;
-
        /* Cpu */
        if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
                ret = print_graph_cpu(s, cpu);