tracing/function-return-tracer: add the overrun field

Impact: help to find the better depth of trace

We decided to arbitrary define the depth of function return trace as
"20". Perhaps this is not enough. To help finding an optimal depth, we
measure now the overrun: the number of functions that have been missed
for the current thread. By default this is not displayed, we have to
do set a particular flag on the return tracer: echo overrun >
/debug/tracing/trace_options And the overrun will be printed on the
right.

As the trace shows below, the current 20 depth is not enough.

update_wall_time+0x37f/0x8c0 -> update_xtime_cache (345 ns) (Overruns: 2838)
update_wall_time+0x384/0x8c0 -> clocksource_get_next (1141 ns) (Overruns: 2838)
do_timer+0x23/0x100 -> update_wall_time (3882 ns) (Overruns: 2838)
tick_do_update_jiffies64+0xbf/0x160 -> do_timer (5339 ns) (Overruns: 2838)
tick_sched_timer+0x6a/0xf0 -> tick_do_update_jiffies64 (7209 ns) (Overruns: 2838)
vgacon_set_cursor_size+0x98/0x120 -> native_io_delay (2613 ns) (Overruns: 274)
vgacon_cursor+0x16e/0x1d0 -> vgacon_set_cursor_size (33151 ns) (Overruns: 274)
set_cursor+0x5f/0x80 -> vgacon_cursor (36432 ns) (Overruns: 274)
con_flush_chars+0x34/0x40 -> set_cursor (38790 ns) (Overruns: 274)
release_console_sem+0x1ec/0x230 -> up (721 ns) (Overruns: 274)
release_console_sem+0x225/0x230 -> wake_up_klogd (316 ns) (Overruns: 274)
con_flush_chars+0x39/0x40 -> release_console_sem (2996 ns) (Overruns: 274)
con_write+0x22/0x30 -> con_flush_chars (46067 ns) (Overruns: 274)
n_tty_write+0x1cc/0x360 -> con_write (292670 ns) (Overruns: 274)
smp_apic_timer_interrupt+0x2a/0x90 -> native_apic_mem_write (330 ns) (Overruns: 274)
irq_enter+0x17/0x70 -> idle_cpu (413 ns) (Overruns: 274)
smp_apic_timer_interrupt+0x2f/0x90 -> irq_enter (1525 ns) (Overruns: 274)
ktime_get_ts+0x40/0x70 -> getnstimeofday (465 ns) (Overruns: 274)
ktime_get_ts+0x60/0x70 -> set_normalized_timespec (436 ns) (Overruns: 274)
ktime_get+0x16/0x30 -> ktime_get_ts (2501 ns) (Overruns: 274)
hrtimer_interrupt+0x77/0x1a0 -> ktime_get (3439 ns) (Overruns: 274)

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Acked-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>

3 files changed, 34 insertions, 6 deletions

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 9531fddcfb8d..e97c29a6e7b0 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -853,6 +853,7 @@ static void __trace_function_return(struct trace_array *tr,
         entry->parent_ip        = trace->ret;
         entry->rettime          = trace->rettime;
         entry->calltime         = trace->calltime;
+        entry->overrun          = trace->overrun;
         ring_buffer_unlock_commit(global_trace.buffer, event, irq_flags);
 }
 #endif
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 9d22618bf99f..2cb12fd98f6b 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -60,6 +60,7 @@ struct ftrace_ret_entry {
         unsigned long           parent_ip;
         unsigned long long      calltime;
         unsigned long long      rettime;
+        unsigned long           overrun;
 };
 extern struct tracer boot_tracer;
 
diff --git a/kernel/trace/trace_functions_return.c b/kernel/trace/trace_functions_return.c
index a68564af022b..e00d64509c9c 100644
--- a/kernel/trace/trace_functions_return.c
+++ b/kernel/trace/trace_functions_return.c
@@ -14,6 +14,19 @@
 #include "trace.h"
 
 
+#define TRACE_RETURN_PRINT_OVERRUN      0x1
+static struct tracer_opt trace_opts[] = {
+        /* Display overruns or not */
+        { TRACER_OPT(overrun, TRACE_RETURN_PRINT_OVERRUN) },
+        { } /* Empty entry */
+};
+
+static struct tracer_flags tracer_flags = {
+        .val = 0, /* Don't display overruns by default */
+        .opts = trace_opts
+};
+
+
 static int return_trace_init(struct trace_array *tr)
 {
         int cpu;
@@ -42,26 +55,39 @@ print_return_function(struct trace_iterator *iter)
                 ret = trace_seq_printf(s, "%pF -> ", (void *)field->parent_ip);
                 if (!ret)
                         return TRACE_TYPE_PARTIAL_LINE;
+
                 ret = seq_print_ip_sym(s, field->ip,
                                         trace_flags & TRACE_ITER_SYM_MASK);
                 if (!ret)
                         return TRACE_TYPE_PARTIAL_LINE;
-                ret = trace_seq_printf(s, " (%llu ns)\n",
+
+                ret = trace_seq_printf(s, " (%llu ns)",
                                         field->rettime - field->calltime);
                 if (!ret)
                         return TRACE_TYPE_PARTIAL_LINE;
-                else
-                        return TRACE_TYPE_HANDLED;
+
+                if (tracer_flags.val & TRACE_RETURN_PRINT_OVERRUN) {
+                        ret = trace_seq_printf(s, " (Overruns: %lu)",
+                                                field->overrun);
+                        if (!ret)
+                                return TRACE_TYPE_PARTIAL_LINE;
+                }
+
+                ret = trace_seq_printf(s, "\n");
+                if (!ret)
+                        return TRACE_TYPE_PARTIAL_LINE;
+
+                return TRACE_TYPE_HANDLED;
         }
         return TRACE_TYPE_UNHANDLED;
 }
 
-static struct tracer return_trace __read_mostly =
-{
+static struct tracer return_trace __read_mostly = {
         .name        = "return",
         .init        = return_trace_init,
         .reset       = return_trace_reset,
-        .print_line = print_return_function
+        .print_line = print_return_function,
+        .flags          = &tracer_flags,
 };
 
 static __init int init_return_trace(void)