[PATCH] ftrace: print sample std dev when function profiling

[PATCH] ftrace: print sample std dev when function profiling

[Chase Douglas]

When combined with function graph tracing the ftrace function profiler
also prints the average run time of functions. While this gives us some
good information, it doesn't tell us anything about the variance of the
run times of the function. This change prints out the s^2 sample
standard deviation alongside the average.

This change adds one entry to the profile record structure. This
increases the memory footprint of the function profiler by 1/3 on a
32-bit system, and by 1/5 on a 64-bit system when function graphing is
enabled, though the memory is only allocated when the profiler is turned
on. During the profiling, one extra line of code adds the squared
calltime to the new record entry, so this should not adversly affect
performance.

Note that the square of the sample standard deviation is printed because
there is no sqrt implementation for unsigned long long in the kernel.

Signed-off-by: Chase Douglas <chase.douglas@canonical.com>
---
 kernel/trace/ftrace.c |   20 +++++++++++++++++---
 1 files changed, 17 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 0cccb6c..07deba1 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -253,6 +253,7 @@ struct ftrace_profile {
 	unsigned long			counter;
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 	unsigned long long		time;
+	unsigned long long		time_squared;
 #endif
 };
 
@@ -355,9 +356,9 @@ static int function_stat_headers(struct seq_file *m)
 {
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 	seq_printf(m, "  Function                               "
-		   "Hit    Time            Avg\n"
+		   "Hit    Time            Avg             s^2\n"
 		      "  --------                               "
-		   "---    ----            ---\n");
+		   "---    ----            ---             ---\n");
 #else
 	seq_printf(m, "  Function                               Hit\n"
 		      "  --------                               ---\n");
@@ -373,6 +374,7 @@ static int function_stat_show(struct seq_file *m, void *v)
 	static DEFINE_MUTEX(mutex);
 	static struct trace_seq s;
 	unsigned long long avg;
+	unsigned long long stddev;
 #endif
 
 	kallsyms_lookup(rec->ip, NULL, NULL, NULL, str);
@@ -383,11 +385,21 @@ static int function_stat_show(struct seq_file *m, void *v)
 	avg = rec->time;
 	do_div(avg, rec->counter);
 
+	/* Sample standard deviation (s^2) */
+	if (rec->counter <= 1)
+		stddev = 0;
+	else {
+		stddev = rec->time_squared - rec->counter * avg * avg;
+		do_div(stddev, (rec->counter - 1) * 1000); /* ns^2 -> us^2 */
+	}
+
 	mutex_lock(&mutex);
 	trace_seq_init(&s);
 	trace_print_graph_duration(rec->time, &s);
 	trace_seq_puts(&s, "    ");
 	trace_print_graph_duration(avg, &s);
+	trace_seq_puts(&s, "    ");
+	trace_print_graph_duration(stddev, &s);
 	trace_print_seq(m, &s);
 	mutex_unlock(&mutex);
 #endif
@@ -657,8 +669,10 @@ static void profile_graph_return(struct ftrace_graph_ret *trace)
 	}
 
 	rec = ftrace_find_profiled_func(stat, trace->func);
-	if (rec)
+	if (rec) {
 		rec->time += calltime;
+		rec->time_squared += calltime * calltime;
+	}
 
  out:
 	local_irq_restore(flags);
-- 
1.7.0.4

Re: [PATCH] ftrace: print sample std dev when function profiling

[Steven Rostedt]

On Mon, 2010-04-26 at 14:02 -0400, Chase Douglas wrote:

> +	/* Sample standard deviation (s^2) */
> +	if (rec->counter <= 1)
> +		stddev = 0;
> +	else {
> +		stddev = rec->time_squared - rec->counter * avg * avg;
> +		do_div(stddev, (rec->counter - 1) * 1000); /* ns^2 -> us^2 */

Shouldn't this be:

	do_div(stddev, (rec->counter - 1) * 1000000); ?

(x / 1000)^2 == x^2 / 1000^2


-- Steve

> +	}
> +

Re: [PATCH] ftrace: print sample std dev when function profiling

[Chase Douglas]

On Tue, Apr 27, 2010 at 4:50 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Mon, 2010-04-26 at 14:02 -0400, Chase Douglas wrote:
>
>> +     /* Sample standard deviation (s^2) */
>> +     if (rec->counter <= 1)
>> +             stddev = 0;
>> +     else {
>> +             stddev = rec->time_squared - rec->counter * avg * avg;
>> +             do_div(stddev, (rec->counter - 1) * 1000); /* ns^2 -> us^2 */
>
> Shouldn't this be:
>
>        do_div(stddev, (rec->counter - 1) * 1000000); ?
>
> (x / 1000)^2 == x^2 / 1000^2

The trace_print_graph_duration function divides the value by 1000
again to display in us units. I could make the comment more clear, but
I didn't want to make a big fuss over a unit conversion.

I also figured this out *after* I had some really wrong looking
numbers :). I made sure this patch produced the correct value after
two events, so I assume the math is correct.

-- Chase

Re: [PATCH] ftrace: print sample std dev when function profiling

[Steven Rostedt]

On Tue, 2010-04-27 at 17:06 -0400, Chase Douglas wrote:
> On Tue, Apr 27, 2010 at 4:50 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> > On Mon, 2010-04-26 at 14:02 -0400, Chase Douglas wrote:
> >
> >> +     /* Sample standard deviation (s^2) */
> >> +     if (rec->counter <= 1)
> >> +             stddev = 0;
> >> +     else {
> >> +             stddev = rec->time_squared - rec->counter * avg * avg;
> >> +             do_div(stddev, (rec->counter - 1) * 1000); /* ns^2 -> us^2 */
> >
> > Shouldn't this be:
> >
> >        do_div(stddev, (rec->counter - 1) * 1000000); ?
> >
> > (x / 1000)^2 == x^2 / 1000^2
> 
> The trace_print_graph_duration function divides the value by 1000
> again to display in us units. I could make the comment more clear, but
> I didn't want to make a big fuss over a unit conversion.
> 
> I also figured this out *after* I had some really wrong looking
> numbers :). I made sure this patch produced the correct value after
> two events, so I assume the math is correct.

OK, I see that now. I'll add this patch but I'll also fix the comment.

Thanks,

-- Steve

[tip:tracing/core] tracing: Show sample std dev in function profiling

[tip-bot for Chase Douglas]

Commit-ID:  e330b3bcd83199dd63a819d8d12e40f9edae6c77
Gitweb:     http://git.kernel.org/tip/e330b3bcd83199dd63a819d8d12e40f9edae6c77
Author:     Chase Douglas <chase.douglas@canonical.com>
AuthorDate: Mon, 26 Apr 2010 14:02:05 -0400
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Tue, 27 Apr 2010 18:23:15 -0400

tracing: Show sample std dev in function profiling

When combined with function graph tracing the ftrace function profiler
also prints the average run time of functions. While this gives us some
good information, it doesn't tell us anything about the variance of the
run times of the function. This change prints out the s^2 sample
standard deviation alongside the average.

This change adds one entry to the profile record structure. This
increases the memory footprint of the function profiler by 1/3 on a
32-bit system, and by 1/5 on a 64-bit system when function graphing is
enabled, though the memory is only allocated when the profiler is turned
on. During the profiling, one extra line of code adds the squared
calltime to the new record entry, so this should not adversly affect
performance.

Note that the square of the sample standard deviation is printed because
there is no sqrt implementation for unsigned long long in the kernel.

Signed-off-by: Chase Douglas <chase.douglas@canonical.com>
LKML-Reference: <1272304925-2436-1-git-send-email-chase.douglas@canonical.com>

[ fixed comment about ns^2 -> us^2 conversion ]
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/ftrace.c |   24 +++++++++++++++++++++---
 1 files changed, 21 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 2404b59..3bcb340 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -264,6 +264,7 @@ struct ftrace_profile {
 	unsigned long			counter;
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 	unsigned long long		time;
+	unsigned long long		time_squared;
 #endif
 };
 
@@ -366,9 +367,9 @@ static int function_stat_headers(struct seq_file *m)
 {
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 	seq_printf(m, "  Function                               "
-		   "Hit    Time            Avg\n"
+		   "Hit    Time            Avg             s^2\n"
 		      "  --------                               "
-		   "---    ----            ---\n");
+		   "---    ----            ---             ---\n");
 #else
 	seq_printf(m, "  Function                               Hit\n"
 		      "  --------                               ---\n");
@@ -384,6 +385,7 @@ static int function_stat_show(struct seq_file *m, void *v)
 	static DEFINE_MUTEX(mutex);
 	static struct trace_seq s;
 	unsigned long long avg;
+	unsigned long long stddev;
 #endif
 
 	kallsyms_lookup(rec->ip, NULL, NULL, NULL, str);
@@ -394,11 +396,25 @@ static int function_stat_show(struct seq_file *m, void *v)
 	avg = rec->time;
 	do_div(avg, rec->counter);
 
+	/* Sample standard deviation (s^2) */
+	if (rec->counter <= 1)
+		stddev = 0;
+	else {
+		stddev = rec->time_squared - rec->counter * avg * avg;
+		/*
+		 * Divide only 1000 for ns^2 -> us^2 conversion.
+		 * trace_print_graph_duration will divide 1000 again.
+		 */
+		do_div(stddev, (rec->counter - 1) * 1000);
+	}
+
 	mutex_lock(&mutex);
 	trace_seq_init(&s);
 	trace_print_graph_duration(rec->time, &s);
 	trace_seq_puts(&s, "    ");
 	trace_print_graph_duration(avg, &s);
+	trace_seq_puts(&s, "    ");
+	trace_print_graph_duration(stddev, &s);
 	trace_print_seq(m, &s);
 	mutex_unlock(&mutex);
 #endif
@@ -668,8 +684,10 @@ static void profile_graph_return(struct ftrace_graph_ret *trace)
 	}
 
 	rec = ftrace_find_profiled_func(stat, trace->func);
-	if (rec)
+	if (rec) {
 		rec->time += calltime;
+		rec->time_squared += calltime * calltime;
+	}
 
  out:
 	local_irq_restore(flags);