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
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <20090325183016.GD5932@nowhere>
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

Powered by Openwall GNU/*/Linux Powered by OpenVZ