summaryrefslogtreecommitdiffstats
path: root/kernel/trace/ftrace.c
diff options
context:
space:
mode:
authorSteven Rostedt <srostedt@redhat.com>2009-03-23 23:12:58 -0400
committerSteven Rostedt <srostedt@redhat.com>2009-03-24 23:41:09 -0400
commit0706f1c48ca8a7ab478090b4e38f2e578ae2bfe0 (patch)
tree26b79090f8e7e62796bb871ff089d04799919855 /kernel/trace/ftrace.c
parent493762fc534c71d11d489f872c4b4a2c61173668 (diff)
downloadop-kernel-dev-0706f1c48ca8a7ab478090b4e38f2e578ae2bfe0.zip
op-kernel-dev-0706f1c48ca8a7ab478090b4e38f2e578ae2bfe0.tar.gz
tracing: adding function timings to function profiler
If the function graph trace is enabled, the function profiler will use it to take the timing of the functions. cat /debug/tracing/trace_stat/functions Function Hit Time -------- --- ---- mwait_idle 127 183028.4 us schedule 26 151997.7 us __schedule 31 151975.1 us sys_wait4 2 74080.53 us do_wait 2 74077.80 us sys_newlstat 138 39929.16 us do_path_lookup 179 39845.79 us vfs_lstat_fd 138 39761.97 us user_path_at 153 39469.58 us path_walk 179 39435.76 us __link_path_walk 189 39143.73 us [...] Note the times are skewed due to the function graph tracer not taking into account schedules. Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Diffstat (limited to 'kernel/trace/ftrace.c')
-rw-r--r--kernel/trace/ftrace.c93
1 files changed, 89 insertions, 4 deletions
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 24dac44..a9ccd71 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -33,7 +33,7 @@
#include <asm/ftrace.h>
-#include "trace.h"
+#include "trace_output.h"
#include "trace_stat.h"
#define FTRACE_WARN_ON(cond) \
@@ -246,6 +246,9 @@ struct ftrace_profile {
struct hlist_node node;
unsigned long ip;
unsigned long counter;
+#ifdef CONFIG_FUNCTION_GRAPH_TRACER
+ unsigned long long time;
+#endif
};
struct ftrace_profile_page {
@@ -303,6 +306,22 @@ static void *function_stat_start(struct tracer_stat *trace)
return function_stat_next(&profile_pages_start->records[0], 0);
}
+#ifdef CONFIG_FUNCTION_GRAPH_TRACER
+/* function graph compares on total time */
+static int function_stat_cmp(void *p1, void *p2)
+{
+ struct ftrace_profile *a = p1;
+ struct ftrace_profile *b = p2;
+
+ if (a->time < b->time)
+ return -1;
+ if (a->time > b->time)
+ return 1;
+ else
+ return 0;
+}
+#else
+/* not function graph compares against hits */
static int function_stat_cmp(void *p1, void *p2)
{
struct ftrace_profile *a = p1;
@@ -315,11 +334,17 @@ static int function_stat_cmp(void *p1, void *p2)
else
return 0;
}
+#endif
static int function_stat_headers(struct seq_file *m)
{
+#ifdef CONFIG_FUNCTION_GRAPH_TRACER
+ seq_printf(m, " Function Hit Time\n"
+ " -------- --- ----\n");
+#else
seq_printf(m, " Function Hit\n"
" -------- ---\n");
+#endif
return 0;
}
@@ -327,10 +352,25 @@ static int function_stat_show(struct seq_file *m, void *v)
{
struct ftrace_profile *rec = v;
char str[KSYM_SYMBOL_LEN];
+#ifdef CONFIG_FUNCTION_GRAPH_TRACER
+ static struct trace_seq s;
+ static DEFINE_MUTEX(mutex);
+
+ mutex_lock(&mutex);
+ trace_seq_init(&s);
+ trace_print_graph_duration(rec->time, &s);
+#endif
kallsyms_lookup(rec->ip, NULL, NULL, NULL, str);
+ seq_printf(m, " %-30.30s %10lu", str, rec->counter);
+
+#ifdef CONFIG_FUNCTION_GRAPH_TRACER
+ seq_printf(m, " ");
+ trace_print_seq(m, &s);
+ mutex_unlock(&mutex);
+#endif
+ seq_putc(m, '\n');
- seq_printf(m, " %-30.30s %10lu\n", str, rec->counter);
return 0;
}
@@ -534,11 +574,52 @@ function_profile_call(unsigned long ip, unsigned long parent_ip)
local_irq_restore(flags);
}
+#ifdef CONFIG_FUNCTION_GRAPH_TRACER
+static int profile_graph_entry(struct ftrace_graph_ent *trace)
+{
+ function_profile_call(trace->func, 0);
+ return 1;
+}
+
+static void profile_graph_return(struct ftrace_graph_ret *trace)
+{
+ unsigned long flags;
+ struct ftrace_profile *rec;
+
+ local_irq_save(flags);
+ rec = ftrace_find_profiled_func(trace->func);
+ if (rec)
+ rec->time += trace->rettime - trace->calltime;
+ local_irq_restore(flags);
+}
+
+static int register_ftrace_profiler(void)
+{
+ return register_ftrace_graph(&profile_graph_return,
+ &profile_graph_entry);
+}
+
+static void unregister_ftrace_profiler(void)
+{
+ unregister_ftrace_graph();
+}
+#else
static struct ftrace_ops ftrace_profile_ops __read_mostly =
{
.func = function_profile_call,
};
+static int register_ftrace_profiler(void)
+{
+ return register_ftrace_function(&ftrace_profile_ops);
+}
+
+static void unregister_ftrace_profiler(void)
+{
+ unregister_ftrace_function(&ftrace_profile_ops);
+}
+#endif /* CONFIG_FUNCTION_GRAPH_TRACER */
+
static ssize_t
ftrace_profile_write(struct file *filp, const char __user *ubuf,
size_t cnt, loff_t *ppos)
@@ -570,11 +651,15 @@ ftrace_profile_write(struct file *filp, const char __user *ubuf,
goto out;
}
- register_ftrace_function(&ftrace_profile_ops);
+ ret = register_ftrace_profiler();
+ if (ret < 0) {
+ cnt = ret;
+ goto out;
+ }
ftrace_profile_enabled = 1;
} else {
ftrace_profile_enabled = 0;
- unregister_ftrace_function(&ftrace_profile_ops);
+ unregister_ftrace_profiler();
}
}
out:
OpenPOWER on IntegriCloud