Commit 0706f1c4 authored by Steven Rostedt's avatar Steven Rostedt
Browse files

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: default avatarSteven Rostedt <srostedt@redhat.com>
parent 493762fc

kernel/trace/ftrace.c

+89 −4
Original line number Diff line number Diff line
@@ -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:

kernel/trace/trace.c

+0 −11
Original line number Diff line number Diff line
@@ -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

kernel/trace/trace.h

+2 −1
Original line number Diff line number Diff line
@@ -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)

kernel/trace/trace_functions_graph.c

+14 −3
Original line number Diff line number Diff line
@@ -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 */

kernel/trace/trace_output.c

+10 −0
Original line number Diff line number Diff line
@@ -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;

CRA Git | Maintained and supported by SUSTech CRA and CCSE