| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Date: Wed, 25 Mar 2009 19:30:19 +0100
From: Frederic Weisbecker <fweisbec@...il.com>
To: Steven Rostedt <rostedt@...dmis.org>
Cc: linux-kernel@...r.kernel.org, Ingo Molnar <mingo@...e.hu>,
Andrew Morton <akpm@...ux-foundation.org>,
Thomas Gleixner <tglx@...utronix.de>,
Peter Zijlstra <peterz@...radead.org>,
Tim Bird <tim.bird@...sony.com>,
Steven Rostedt <srostedt@...hat.com>
Subject: Re: [PATCH 3/5][RFC] tracing: adding function timings to function
profiler
On Tue, Mar 24, 2009 at 11:56:49PM -0400, Steven Rostedt wrote:
> From: Steven Rostedt <srostedt@...hat.com>
>
> 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
> [...]
Wow, that's great!
> Note the times are skewed due to the function graph tracer not taking
> into account schedules.
>
> Signed-off-by: Steven Rostedt <srostedt@...hat.com>
> ---
> kernel/trace/ftrace.c | 93 ++++++++++++++++++++++++++++++++--
> kernel/trace/trace.c | 11 ----
> kernel/trace/trace.h | 3 +-
> kernel/trace/trace_functions_graph.c | 17 +++++-
> kernel/trace/trace_output.c | 10 ++++
> kernel/trace/trace_output.h | 2 +
> 6 files changed, 117 insertions(+), 19 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);
I must confess I have some troubles to find what is protecting this mutex.
Usually I find them self-explained by their name if they are global or
by their situation inside a struture. But there, it's a bit difficult.
After a small delay reading: Ah, the static seq, sorry :-)
Thanks,
Frederic.
> +
> + 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:
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 67c6a21..821bf49 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -402,17 +402,6 @@ static ssize_t trace_seq_to_buffer(struct trace_seq *s, void *buf, size_t cnt)
> return cnt;
> }
>
> -static void
> -trace_print_seq(struct seq_file *m, struct trace_seq *s)
> -{
> - int len = s->len >= PAGE_SIZE ? PAGE_SIZE - 1 : s->len;
> -
> - s->buffer[len] = 0;
> - seq_puts(m, s->buffer);
> -
> - trace_seq_init(s);
> -}
> -
> /**
> * update_max_tr - snapshot all trace buffers from global_trace to max_tr
> * @tr: tracer
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index d7410bb..c66ca3b 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -605,6 +605,8 @@ extern unsigned long trace_flags;
> /* Standard output formatting function used for function return traces */
> #ifdef CONFIG_FUNCTION_GRAPH_TRACER
> extern enum print_line_t print_graph_function(struct trace_iterator *iter);
> +extern enum print_line_t
> +trace_print_graph_duration(unsigned long long duration, struct trace_seq *s);
>
> #ifdef CONFIG_DYNAMIC_FTRACE
> /* TODO: make this variable */
> @@ -636,7 +638,6 @@ static inline int ftrace_graph_addr(unsigned long addr)
> return 1;
> }
> #endif /* CONFIG_DYNAMIC_FTRACE */
> -
> #else /* CONFIG_FUNCTION_GRAPH_TRACER */
> static inline enum print_line_t
> print_graph_function(struct trace_iterator *iter)
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index d28687e..85bba0f 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -426,8 +426,8 @@ print_graph_irq(struct trace_iterator *iter, unsigned long addr,
> return TRACE_TYPE_HANDLED;
> }
>
> -static enum print_line_t
> -print_graph_duration(unsigned long long duration, struct trace_seq *s)
> +enum print_line_t
> +trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
> {
> unsigned long nsecs_rem = do_div(duration, 1000);
> /* log10(ULONG_MAX) + '\0' */
> @@ -464,12 +464,23 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s)
> if (!ret)
> return TRACE_TYPE_PARTIAL_LINE;
> }
> + return TRACE_TYPE_HANDLED;
> +}
> +
> +static enum print_line_t
> +print_graph_duration(unsigned long long duration, struct trace_seq *s)
> +{
> + int ret;
> +
> + ret = trace_print_graph_duration(duration, s);
> + if (ret != TRACE_TYPE_HANDLED)
> + return ret;
>
> ret = trace_seq_printf(s, "| ");
> if (!ret)
> return TRACE_TYPE_PARTIAL_LINE;
> - return TRACE_TYPE_HANDLED;
>
> + return TRACE_TYPE_HANDLED;
> }
>
> /* Case of a leaf function on its call entry */
> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> index 19261fd..a3b6e3f 100644
> --- a/kernel/trace/trace_output.c
> +++ b/kernel/trace/trace_output.c
> @@ -19,6 +19,16 @@ static struct hlist_head event_hash[EVENT_HASHSIZE] __read_mostly;
>
> static int next_event_type = __TRACE_LAST_TYPE + 1;
>
> +void trace_print_seq(struct seq_file *m, struct trace_seq *s)
> +{
> + int len = s->len >= PAGE_SIZE ? PAGE_SIZE - 1 : s->len;
> +
> + s->buffer[len] = 0;
> + seq_puts(m, s->buffer);
> +
> + trace_seq_init(s);
> +}
> +
> enum print_line_t trace_print_bprintk_msg_only(struct trace_iterator *iter)
> {
> struct trace_seq *s = &iter->seq;
> diff --git a/kernel/trace/trace_output.h b/kernel/trace/trace_output.h
> index 35c422f..1eac297 100644
> --- a/kernel/trace/trace_output.h
> +++ b/kernel/trace/trace_output.h
> @@ -20,6 +20,8 @@ trace_print_bprintk_msg_only(struct trace_iterator *iter);
> extern enum print_line_t
> trace_print_printk_msg_only(struct trace_iterator *iter);
>
> +extern void trace_print_seq(struct seq_file *m, struct trace_seq *s);
> +
> extern int trace_seq_printf(struct trace_seq *s, const char *fmt, ...)
> __attribute__ ((format (printf, 2, 3)));
> extern int
> --
> 1.6.2
>
> --
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists