aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorFrederic Weisbecker <fweisbec@gmail.com>2008-11-16 21:22:41 -0500
committerIngo Molnar <mingo@elte.hu>2008-11-18 05:11:00 -0500
commit0231022cc32d5f2e7f3c06b75691dda0ad6aec33 (patch)
treeb45429e95fc7d52bae32e62ef514f3d7ccf62ce6
parent0619faf657806b943e6acf51f60f1cd023a96c78 (diff)
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>
-rw-r--r--arch/x86/include/asm/thread_info.h7
-rw-r--r--arch/x86/kernel/ftrace.c10
-rw-r--r--include/linux/ftrace.h2
-rw-r--r--include/linux/sched.h1
-rw-r--r--kernel/trace/trace.c1
-rw-r--r--kernel/trace/trace.h1
-rw-r--r--kernel/trace/trace_functions_return.c38
7 files changed, 51 insertions, 9 deletions
diff --git a/arch/x86/include/asm/thread_info.h b/arch/x86/include/asm/thread_info.h
index a71158369fd4..e90e81ef6ab9 100644
--- a/arch/x86/include/asm/thread_info.h
+++ b/arch/x86/include/asm/thread_info.h
@@ -21,6 +21,7 @@ struct task_struct;
21struct exec_domain; 21struct exec_domain;
22#include <asm/processor.h> 22#include <asm/processor.h>
23#include <asm/ftrace.h> 23#include <asm/ftrace.h>
24#include <asm/atomic.h>
24 25
25struct thread_info { 26struct thread_info {
26 struct task_struct *task; /* main task structure */ 27 struct task_struct *task; /* main task structure */
@@ -45,6 +46,11 @@ struct thread_info {
45 int curr_ret_stack; 46 int curr_ret_stack;
46 /* Stack of return addresses for return function tracing */ 47 /* Stack of return addresses for return function tracing */
47 struct ftrace_ret_stack ret_stack[FTRACE_RET_STACK_SIZE]; 48 struct ftrace_ret_stack ret_stack[FTRACE_RET_STACK_SIZE];
49 /*
50 * Number of functions that haven't been traced
51 * because of depth overrun.
52 */
53 atomic_t trace_overrun;
48#endif 54#endif
49}; 55};
50 56
@@ -61,6 +67,7 @@ struct thread_info {
61 .fn = do_no_restart_syscall, \ 67 .fn = do_no_restart_syscall, \
62 }, \ 68 }, \
63 .curr_ret_stack = -1,\ 69 .curr_ret_stack = -1,\
70 .trace_overrun = ATOMIC_INIT(0) \
64} 71}
65#else 72#else
66#define INIT_THREAD_INFO(tsk) \ 73#define INIT_THREAD_INFO(tsk) \
diff --git a/arch/x86/kernel/ftrace.c b/arch/x86/kernel/ftrace.c
index 924153edd973..356bb1eb6e9a 100644
--- a/arch/x86/kernel/ftrace.c
+++ b/arch/x86/kernel/ftrace.c
@@ -353,8 +353,10 @@ static int push_return_trace(unsigned long ret, unsigned long long time,
353 struct thread_info *ti = current_thread_info(); 353 struct thread_info *ti = current_thread_info();
354 354
355 /* The return trace stack is full */ 355 /* The return trace stack is full */
356 if (ti->curr_ret_stack == FTRACE_RET_STACK_SIZE - 1) 356 if (ti->curr_ret_stack == FTRACE_RET_STACK_SIZE - 1) {
357 atomic_inc(&ti->trace_overrun);
357 return -EBUSY; 358 return -EBUSY;
359 }
358 360
359 index = ++ti->curr_ret_stack; 361 index = ++ti->curr_ret_stack;
360 barrier(); 362 barrier();
@@ -367,7 +369,7 @@ static int push_return_trace(unsigned long ret, unsigned long long time,
367 369
368/* Retrieve a function return address to the trace stack on thread info.*/ 370/* Retrieve a function return address to the trace stack on thread info.*/
369static void pop_return_trace(unsigned long *ret, unsigned long long *time, 371static void pop_return_trace(unsigned long *ret, unsigned long long *time,
370 unsigned long *func) 372 unsigned long *func, unsigned long *overrun)
371{ 373{
372 int index; 374 int index;
373 375
@@ -376,6 +378,7 @@ static void pop_return_trace(unsigned long *ret, unsigned long long *time,
376 *ret = ti->ret_stack[index].ret; 378 *ret = ti->ret_stack[index].ret;
377 *func = ti->ret_stack[index].func; 379 *func = ti->ret_stack[index].func;
378 *time = ti->ret_stack[index].calltime; 380 *time = ti->ret_stack[index].calltime;
381 *overrun = atomic_read(&ti->trace_overrun);
379 ti->curr_ret_stack--; 382 ti->curr_ret_stack--;
380} 383}
381 384
@@ -386,7 +389,8 @@ static void pop_return_trace(unsigned long *ret, unsigned long long *time,
386unsigned long ftrace_return_to_handler(void) 389unsigned long ftrace_return_to_handler(void)
387{ 390{
388 struct ftrace_retfunc trace; 391 struct ftrace_retfunc trace;
389 pop_return_trace(&trace.ret, &trace.calltime, &trace.func); 392 pop_return_trace(&trace.ret, &trace.calltime, &trace.func,
393 &trace.overrun);
390 trace.rettime = cpu_clock(raw_smp_processor_id()); 394 trace.rettime = cpu_clock(raw_smp_processor_id());
391 ftrace_function_return(&trace); 395 ftrace_function_return(&trace);
392 396
diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index f1af1aab00e6..f7ba4ea5e128 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -318,6 +318,8 @@ struct ftrace_retfunc {
318 unsigned long func; /* Current function */ 318 unsigned long func; /* Current function */
319 unsigned long long calltime; 319 unsigned long long calltime;
320 unsigned long long rettime; 320 unsigned long long rettime;
321 /* Number of functions that overran the depth limit for current task */
322 unsigned long overrun;
321}; 323};
322 324
323#ifdef CONFIG_FUNCTION_RET_TRACER 325#ifdef CONFIG_FUNCTION_RET_TRACER
diff --git a/include/linux/sched.h b/include/linux/sched.h
index 61c8cc36028a..c8e0db464206 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -2016,6 +2016,7 @@ static inline void setup_thread_stack(struct task_struct *p, struct task_struct
2016 * used. 2016 * used.
2017 */ 2017 */
2018 task_thread_info(p)->curr_ret_stack = -1; 2018 task_thread_info(p)->curr_ret_stack = -1;
2019 atomic_set(&task_thread_info(p)->trace_overrun, 0);
2019#endif 2020#endif
2020} 2021}
2021 2022
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,
853 entry->parent_ip = trace->ret; 853 entry->parent_ip = trace->ret;
854 entry->rettime = trace->rettime; 854 entry->rettime = trace->rettime;
855 entry->calltime = trace->calltime; 855 entry->calltime = trace->calltime;
856 entry->overrun = trace->overrun;
856 ring_buffer_unlock_commit(global_trace.buffer, event, irq_flags); 857 ring_buffer_unlock_commit(global_trace.buffer, event, irq_flags);
857} 858}
858#endif 859#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 {
60 unsigned long parent_ip; 60 unsigned long parent_ip;
61 unsigned long long calltime; 61 unsigned long long calltime;
62 unsigned long long rettime; 62 unsigned long long rettime;
63 unsigned long overrun;
63}; 64};
64extern struct tracer boot_tracer; 65extern struct tracer boot_tracer;
65 66
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 @@
14#include "trace.h" 14#include "trace.h"
15 15
16 16
17#define TRACE_RETURN_PRINT_OVERRUN 0x1
18static struct tracer_opt trace_opts[] = {
19 /* Display overruns or not */
20 { TRACER_OPT(overrun, TRACE_RETURN_PRINT_OVERRUN) },
21 { } /* Empty entry */
22};
23
24static struct tracer_flags tracer_flags = {
25 .val = 0, /* Don't display overruns by default */
26 .opts = trace_opts
27};
28
29
17static int return_trace_init(struct trace_array *tr) 30static int return_trace_init(struct trace_array *tr)
18{ 31{
19 int cpu; 32 int cpu;
@@ -42,26 +55,39 @@ print_return_function(struct trace_iterator *iter)
42 ret = trace_seq_printf(s, "%pF -> ", (void *)field->parent_ip); 55 ret = trace_seq_printf(s, "%pF -> ", (void *)field->parent_ip);
43 if (!ret) 56 if (!ret)
44 return TRACE_TYPE_PARTIAL_LINE; 57 return TRACE_TYPE_PARTIAL_LINE;
58
45 ret = seq_print_ip_sym(s, field->ip, 59 ret = seq_print_ip_sym(s, field->ip,
46 trace_flags & TRACE_ITER_SYM_MASK); 60 trace_flags & TRACE_ITER_SYM_MASK);
47 if (!ret) 61 if (!ret)
48 return TRACE_TYPE_PARTIAL_LINE; 62 return TRACE_TYPE_PARTIAL_LINE;
49 ret = trace_seq_printf(s, " (%llu ns)\n", 63
64 ret = trace_seq_printf(s, " (%llu ns)",
50 field->rettime - field->calltime); 65 field->rettime - field->calltime);
51 if (!ret) 66 if (!ret)
52 return TRACE_TYPE_PARTIAL_LINE; 67 return TRACE_TYPE_PARTIAL_LINE;
53 else 68
54 return TRACE_TYPE_HANDLED; 69 if (tracer_flags.val & TRACE_RETURN_PRINT_OVERRUN) {
70 ret = trace_seq_printf(s, " (Overruns: %lu)",
71 field->overrun);
72 if (!ret)
73 return TRACE_TYPE_PARTIAL_LINE;
74 }
75
76 ret = trace_seq_printf(s, "\n");
77 if (!ret)
78 return TRACE_TYPE_PARTIAL_LINE;
79
80 return TRACE_TYPE_HANDLED;
55 } 81 }
56 return TRACE_TYPE_UNHANDLED; 82 return TRACE_TYPE_UNHANDLED;
57} 83}
58 84
59static struct tracer return_trace __read_mostly = 85static struct tracer return_trace __read_mostly = {
60{
61 .name = "return", 86 .name = "return",
62 .init = return_trace_init, 87 .init = return_trace_init,
63 .reset = return_trace_reset, 88 .reset = return_trace_reset,
64 .print_line = print_return_function 89 .print_line = print_return_function,
90 .flags = &tracer_flags,
65}; 91};
66 92
67static __init int init_return_trace(void) 93static __init int init_return_trace(void)