ftrace: display start of CPU buffer in trace output

Impact: change in trace output

Because the trace buffers are per cpu ring buffers, the start of
the trace can be confusing. If one CPU is very active at the
end of the trace, its history will not go as far back as the
other CPU traces.  This means that output for a particular CPU
may not appear for the first part of a trace.

To help annotate what is happening, and to prevent any more
confusion, this patch adds a line that annotates the start of
a CPU buffer output.

For example:

       automount-3495  [001]   184.596443: dnotify_parent <-vfs_write
[...]
       automount-3495  [001]   184.596449: dput <-path_put
       automount-3496  [002]   184.596450: down_read_trylock <-do_page_fault
[...]
           sshd-3497  [001]   184.597069: up_read <-do_page_fault
          <idle>-0     [000]   184.597074: __exit_idle <-exit_idle
[...]
       automount-3496  [002]   184.597257: filemap_fault <-__do_fault
          <idle>-0     [003]   184.597261: exit_idle <-smp_apic_timer_interrupt

Note, parsers of a trace output should always ignore any lines that
start with a '#'.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 58435415b366402e35b7f38883539f418ebcebcc..f147f198b9a690ab634db0b39486fe492004c568 100644 (file)
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1478,6 +1478,17 @@ void trace_seq_print_cont(struct trace_seq *s, struct trace_iterator *iter)
                trace_seq_putc(s, '\n');
 }
 
+static void test_cpu_buff_start(struct trace_iterator *iter)
+{
+       struct trace_seq *s = &iter->seq;
+
+       if (cpu_isset(iter->cpu, iter->started))
+               return;
+
+       cpu_set(iter->cpu, iter->started);
+       trace_seq_printf(s, "##### CPU %u buffer started ####\n", iter->cpu);
+}
+
 static enum print_line_t
 print_lat_fmt(struct trace_iterator *iter, unsigned int trace_idx, int cpu)
 {
@@ -1497,6 +1508,8 @@ print_lat_fmt(struct trace_iterator *iter, unsigned int trace_idx, int cpu)
        if (entry->type == TRACE_CONT)
                return TRACE_TYPE_HANDLED;
 
+       test_cpu_buff_start(iter);
+
        next_entry = find_next_entry(iter, NULL, &next_ts);
        if (!next_entry)
                next_ts = iter->ts;
@@ -1612,6 +1625,8 @@ static enum print_line_t print_trace_fmt(struct trace_iterator *iter)
        if (entry->type == TRACE_CONT)
                return TRACE_TYPE_HANDLED;
 
+       test_cpu_buff_start(iter);
+
        comm = trace_find_cmdline(iter->ent->pid);
 
        t = ns2usecs(iter->ts);
@@ -2631,6 +2646,10 @@ static int tracing_open_pipe(struct inode *inode, struct file *filp)
                return -ENOMEM;
 
        mutex_lock(&trace_types_lock);
+
+       /* trace pipe does not show start of buffer */
+       cpus_setall(iter->started);
+
        iter->tr = &global_trace;
        iter->trace = current_trace;
        filp->private_data = iter;

diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index cfda9d219e667e5a7813e0d7883a2f1c2f46f6f0..978145088fb8641cacc2b4c6a91092b5796141bc 100644 (file)
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -277,6 +277,8 @@ struct trace_iterator {
        unsigned long           iter_flags;
        loff_t                  pos;
        long                    idx;
+
+       cpumask_t               started;
 };
 
 int tracing_is_enabled(void);