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>
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 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 @@
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 @@
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 @@
{
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);
- seq_printf(m, " %-30.30s %10lu\n", str, rec->counter);
+#ifdef CONFIG_FUNCTION_GRAPH_TRACER
+ seq_printf(m, " ");
+ trace_print_seq(m, &s);
+ mutex_unlock(&mutex);
+#endif
+ seq_putc(m, '\n');
+
return 0;
}
@@ -534,11 +574,52 @@
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 @@
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: