[PATCH 0/3] ftrace: fix stddev calculation and add a test for it

[PATCH 0/3] ftrace: fix stddev calculation and add a test for it

[Juri Lelli]

While profiling kernel functions via ftrace I noticed values of s^2 that
seemed odd. I implemented a test to verify correctness of averages and
s^2 calculations and proved the latter to be wrong. Then I fixed them up.

The first patch refactors function_stat_show() code a bit in order to be
able to implement the test (second patch). Third patch fixes up s^2
calculation (applying Welford's method).

Juri Lelli (3):
  ftrace: refactor basis statistics calculation code
  ftrace: test basic statistics calculation
  ftrace: fix stddev calculation

 kernel/trace/ftrace.c         |   50 ++++++++++++++--------------
 kernel/trace/trace.h          |   16 +++++++++
 kernel/trace/trace_selftest.c |   72 +++++++++++++++++++++++++++++++++++++++++
 3 files changed, 114 insertions(+), 24 deletions(-)

-- 
1.7.9.5

[PATCH 1/3] ftrace: refactor basis statistics calculation code

[Juri Lelli]

Refactor function_stat_show() code grouping avg and stddev calculations
inside a single function (function_stat_calc()). We are now able to call
it from different places.

Signed-off-by: Juri Lelli <juri.lelli@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@redhat.com>
---
 kernel/trace/ftrace.c |   46 ++++++++++++++++++++++------------------------
 kernel/trace/trace.h  |   16 ++++++++++++++++
 2 files changed, 38 insertions(+), 24 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 6c508ff..6caaa0e 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -473,16 +473,6 @@ static void ftrace_update_pid_func(void)
 }
 
 #ifdef CONFIG_FUNCTION_PROFILER
-struct ftrace_profile {
-	struct hlist_node		node;
-	unsigned long			ip;
-	unsigned long			counter;
-#ifdef CONFIG_FUNCTION_GRAPH_TRACER
-	unsigned long long		time;
-	unsigned long long		time_squared;
-#endif
-};
-
 struct ftrace_profile_page {
 	struct ftrace_profile_page	*next;
 	unsigned long			index;
@@ -592,6 +582,27 @@ static int function_stat_headers(struct seq_file *m)
 	return 0;
 }
 
+void function_stat_calc(struct ftrace_profile *rec,
+			       unsigned long long *avg,
+			       unsigned long long *stddev)
+{
+	*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);
+	}
+}
+
 static int function_stat_show(struct seq_file *m, void *v)
 {
 	struct ftrace_profile *rec = v;
@@ -615,20 +626,7 @@ static int function_stat_show(struct seq_file *m, void *v)
 
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 	seq_printf(m, "    ");
-	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);
-	}
+	function_stat_calc(rec, &avg, &stddev);
 
 	trace_seq_init(&s);
 	trace_print_graph_duration(rec->time, &s);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 711ca7d..89c8a7b 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1062,4 +1062,20 @@ int perf_ftrace_event_register(struct ftrace_event_call *call,
 #define perf_ftrace_event_register NULL
 #endif
 
+#ifdef CONFIG_FUNCTION_PROFILER
+struct ftrace_profile {
+	struct hlist_node		node;
+	unsigned long			ip;
+	unsigned long			counter;
+#ifdef CONFIG_FUNCTION_GRAPH_TRACER
+	unsigned long long		time;
+	unsigned long long		time_squared;
+#endif
+};
+
+void function_stat_calc(struct ftrace_profile *rec,
+			       unsigned long long *avg,
+			       unsigned long long *stddev);
+#endif
+
 #endif /* _LINUX_KERNEL_TRACE_H */
-- 
1.7.9.5

[PATCH 2/3] ftrace: test basic statistics calculation

[Juri Lelli]

Perform a simple test comparing static and running (implemented by
function_stat_calc()) average and stddev calculations.

Signed-off-by: Juri Lelli <juri.lelli@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@redhat.com>
---
 kernel/trace/trace_selftest.c |   72 +++++++++++++++++++++++++++++++++++++++++
 1 file changed, 72 insertions(+)

diff --git a/kernel/trace/trace_selftest.c b/kernel/trace/trace_selftest.c
index 2901e3b..e8ecb9a 100644
--- a/kernel/trace/trace_selftest.c
+++ b/kernel/trace/trace_selftest.c
@@ -4,6 +4,7 @@
 #include <linux/kthread.h>
 #include <linux/delay.h>
 #include <linux/slab.h>
+#include <linux/random.h>
 
 static inline int trace_valid_entry(struct trace_entry *entry)
 {
@@ -724,6 +725,74 @@ static int trace_graph_entry_watchdog(struct ftrace_graph_ent *trace)
 }
 
 /*
+ * Test the trace basic running statistic calculations to see if they
+ * agree with static one.
+ */
+#define	TIME_ENTRIES	50
+#define	MAX_DURATION	1000000 /* ns */
+
+static int trace_test_stat(void)
+{
+	unsigned long long time_array[TIME_ENTRIES];
+	unsigned long long averages[TIME_ENTRIES], stddevs[TIME_ENTRIES];
+	int i, j, count;
+	unsigned long long avg, stddev;
+	struct ftrace_profile rec;
+
+	/*
+	 * Fill-up time_array, each element corresponds to the time spent
+	 * executing some function.
+	 */
+	for (i = 0; i < TIME_ENTRIES; i++) {
+		get_random_bytes(&time_array[i], sizeof(unsigned long long));
+		time_array[i] %= MAX_DURATION;
+		averages[i] = stddevs[i] = 0;
+	}
+
+	/*
+	 * Calculate stats in the static way.
+	 */
+	for (i = 0; i < TIME_ENTRIES; i++) {
+		if (i == 0) {
+			averages[i] = time_array[i];
+			stddevs[i] = 0;
+			continue;
+		}
+
+		count = 0;
+		for (j = 0; j < i + 1; j++) {
+			count++;
+			averages[i] += time_array[j];
+		}
+		do_div(averages[i], count);
+
+		for (j = 0; j < count; j++)
+			stddevs[i] += (time_array[j] - averages[i]) *
+				      (time_array[j] - averages[i]);
+		/* Reflect ns^2 -> us^2 conversion. */
+		do_div(stddevs[i], (count - 1) * 1000);
+	}
+
+	/*
+	 * Now do the same using running stats and compare results.
+	 */
+	rec.time = rec.time_squared = 0;
+
+	for (i = 0; i < TIME_ENTRIES; i++) {
+		avg = stddev = 0;
+		rec.counter = i + 1;
+		rec.time += time_array[i];
+		rec.time_squared += time_array[i] * time_array[i];
+		function_stat_calc(&rec, &avg, &stddev);
+
+		if (avg != averages[i] || stddev != stddevs[i])
+			return 1;
+	}
+
+	return 0;
+}
+
+/*
  * Pretty much the same than for the function tracer from which the selftest
  * has been borrowed.
  */
@@ -774,6 +843,9 @@ trace_selftest_startup_function_graph(struct tracer *trace,
 
 	/* Don't test dynamic tracing, the function tracer already did */
 
+	/* Check basic statistics */
+	ret = trace_test_stat();
+
 out:
 	/* Stop it if we failed */
 	if (ret)
-- 
1.7.9.5

Re: [PATCH 2/3] ftrace: test basic statistics calculation

[Steven Rostedt]

On Tue, 2013-06-11 at 11:08 +0200, Juri Lelli wrote:
> Perform a simple test comparing static and running (implemented by
> function_stat_calc()) average and stddev calculations.

Thanks, as these are not regressions but just bugs since its
incorporation, they are too late for 3.10. I'll queue them up for 3.11.

But this has a small bug...

> 
> Signed-off-by: Juri Lelli <juri.lelli@gmail.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Ingo Molnar <mingo@redhat.com>
> ---
>  kernel/trace/trace_selftest.c |   72 +++++++++++++++++++++++++++++++++++++++++
>  1 file changed, 72 insertions(+)
> 
> diff --git a/kernel/trace/trace_selftest.c b/kernel/trace/trace_selftest.c
> index 2901e3b..e8ecb9a 100644
> --- a/kernel/trace/trace_selftest.c
> +++ b/kernel/trace/trace_selftest.c
> @@ -4,6 +4,7 @@
>  #include <linux/kthread.h>
>  #include <linux/delay.h>
>  #include <linux/slab.h>
> +#include <linux/random.h>
>  
>  static inline int trace_valid_entry(struct trace_entry *entry)
>  {
> @@ -724,6 +725,74 @@ static int trace_graph_entry_watchdog(struct ftrace_graph_ent *trace)
>  }

Need to encapsulate this with:

#ifdef CONFIG_FUNCTION_PROFILER

>  
>  /*
> + * Test the trace basic running statistic calculations to see if they
> + * agree with static one.
> + */
> +#define	TIME_ENTRIES	50
> +#define	MAX_DURATION	1000000 /* ns */
> +
> +static int trace_test_stat(void)
> +{
> +	unsigned long long time_array[TIME_ENTRIES];
> +	unsigned long long averages[TIME_ENTRIES], stddevs[TIME_ENTRIES];
> +	int i, j, count;
> +	unsigned long long avg, stddev;
> +	struct ftrace_profile rec;
> +
> +	/*
> +	 * Fill-up time_array, each element corresponds to the time spent
> +	 * executing some function.
> +	 */
> +	for (i = 0; i < TIME_ENTRIES; i++) {
> +		get_random_bytes(&time_array[i], sizeof(unsigned long long));
> +		time_array[i] %= MAX_DURATION;
> +		averages[i] = stddevs[i] = 0;
> +	}
> +
> +	/*
> +	 * Calculate stats in the static way.
> +	 */
> +	for (i = 0; i < TIME_ENTRIES; i++) {
> +		if (i == 0) {
> +			averages[i] = time_array[i];
> +			stddevs[i] = 0;
> +			continue;
> +		}
> +
> +		count = 0;
> +		for (j = 0; j < i + 1; j++) {
> +			count++;
> +			averages[i] += time_array[j];
> +		}
> +		do_div(averages[i], count);
> +
> +		for (j = 0; j < count; j++)
> +			stddevs[i] += (time_array[j] - averages[i]) *
> +				      (time_array[j] - averages[i]);
> +		/* Reflect ns^2 -> us^2 conversion. */
> +		do_div(stddevs[i], (count - 1) * 1000);
> +	}
> +
> +	/*
> +	 * Now do the same using running stats and compare results.
> +	 */
> +	rec.time = rec.time_squared = 0;
> +
> +	for (i = 0; i < TIME_ENTRIES; i++) {
> +		avg = stddev = 0;
> +		rec.counter = i + 1;
> +		rec.time += time_array[i];
> +		rec.time_squared += time_array[i] * time_array[i];
> +		function_stat_calc(&rec, &avg, &stddev);
> +
> +		if (avg != averages[i] || stddev != stddevs[i])
> +			return 1;
> +	}
> +
> +	return 0;
> +}
> +

#else

static int trace_test_stat(void)
{
	return 0;
}

#endif /* CONFIG_FUNCTION_PROFILER */

-- Steve

> +/*
>   * Pretty much the same than for the function tracer from which the selftest
>   * has been borrowed.
>   */
> @@ -774,6 +843,9 @@ trace_selftest_startup_function_graph(struct tracer *trace,
>  
>  	/* Don't test dynamic tracing, the function tracer already did */
>  
> +	/* Check basic statistics */
> +	ret = trace_test_stat();
> +
>  out:
>  	/* Stop it if we failed */
>  	if (ret)

[PATCH 3/3] ftrace: fix stddev calculation

[Juri Lelli]

When FUNCTION_GRAPH_TRACER is enabled, ftrace can profile kernel functions
and print basic statistics about them. Unfortunately, running stddev
calculation is wrong. This patch corrects it implementing Welford’s method:

        s^2 = 1 / (n * (n-1)) * (n * \Sum (x_i)^2 - (\Sum x_i)^2) .

Signed-off-by: Juri Lelli <juri.lelli@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@redhat.com>
---
 kernel/trace/ftrace.c |    8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 6caaa0e..073a328 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -593,13 +593,17 @@ void function_stat_calc(struct ftrace_profile *rec,
 	if (rec->counter <= 1)
 		*stddev = 0;
 	else {
-		*stddev = rec->time_squared - rec->counter * (*avg) * (*avg);
+		/*
+		 * Apply Welford's method.
+		 */
+		*stddev = rec->counter * rec->time_squared -
+			  rec->time * rec->time;
 
 		/*
 		 * Divide only 1000 for ns^2 -> us^2 conversion.
 		 * trace_print_graph_duration will divide 1000 again.
 		 */
-		do_div(*stddev, (rec->counter - 1) * 1000);
+		do_div(*stddev, rec->counter * (rec->counter - 1) * 1000);
 	}
 }
 
-- 
1.7.9.5

Re: [PATCH 3/3] ftrace: fix stddev calculation

[Steven Rostedt]

On Tue, 2013-06-11 at 11:08 +0200, Juri Lelli wrote:
> When FUNCTION_GRAPH_TRACER is enabled, ftrace can profile kernel functions
> and print basic statistics about them. Unfortunately, running stddev
> calculation is wrong. This patch corrects it implementing Welford’s method:
> 
>         s^2 = 1 / (n * (n-1)) * (n * \Sum (x_i)^2 - (\Sum x_i)^2) .

Looking at this further, we only need this fix. We don't need the other
two patches, as that's just verifying the algorithm, and not something
we need to do for run time tests. The run time tests is to test
functionality, not calculations that can be done out of the kernel.

Can you resubmit with just this change. And add the above line as a
comment below.

> 
> Signed-off-by: Juri Lelli <juri.lelli@gmail.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Ingo Molnar <mingo@redhat.com>
> ---
>  kernel/trace/ftrace.c |    8 ++++++--
>  1 file changed, 6 insertions(+), 2 deletions(-)
> 
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index 6caaa0e..073a328 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -593,13 +593,17 @@ void function_stat_calc(struct ftrace_profile *rec,
>  	if (rec->counter <= 1)
>  		*stddev = 0;
>  	else {
> -		*stddev = rec->time_squared - rec->counter * (*avg) * (*avg);
> +		/*
> +		 * Apply Welford's method.

Welford's method is not well known. Please add:

		* s^2 = 1 / (n * (n-1)) * (n * \Sum (x_i)^2 - (\Sum x_i)^2)

Thanks!

-- Steve

> +		 */
> +		*stddev = rec->counter * rec->time_squared -
> +			  rec->time * rec->time;
>  
>  		/*
>  		 * Divide only 1000 for ns^2 -> us^2 conversion.
>  		 * trace_print_graph_duration will divide 1000 again.
>  		 */
> -		do_div(*stddev, (rec->counter - 1) * 1000);
> +		do_div(*stddev, rec->counter * (rec->counter - 1) * 1000);
>  	}
>  }
>  

Re: [PATCH 3/3] ftrace: fix stddev calculation

[Juri Lelli]

On 06/12/2013 05:09 AM, Steven Rostedt wrote:
> On Tue, 2013-06-11 at 11:08 +0200, Juri Lelli wrote:
>> When FUNCTION_GRAPH_TRACER is enabled, ftrace can profile kernel functions
>> and print basic statistics about them. Unfortunately, running stddev
>> calculation is wrong. This patch corrects it implementing Welford’s method:
>>
>>          s^2 = 1 / (n * (n-1)) * (n * \Sum (x_i)^2 - (\Sum x_i)^2) .
>
> Looking at this further, we only need this fix. We don't need the other
> two patches, as that's just verifying the algorithm, and not something
> we need to do for run time tests. The run time tests is to test
> functionality, not calculations that can be done out of the kernel.
>
> Can you resubmit with just this change. And add the above line as a
> comment below.
>

Sure! No problem.

>>
>> Signed-off-by: Juri Lelli <juri.lelli@gmail.com>
>> Cc: Steven Rostedt <rostedt@goodmis.org>
>> Cc: Frederic Weisbecker <fweisbec@gmail.com>
>> Cc: Ingo Molnar <mingo@redhat.com>
>> ---
>>   kernel/trace/ftrace.c |    8 ++++++--
>>   1 file changed, 6 insertions(+), 2 deletions(-)
>>
>> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
>> index 6caaa0e..073a328 100644
>> --- a/kernel/trace/ftrace.c
>> +++ b/kernel/trace/ftrace.c
>> @@ -593,13 +593,17 @@ void function_stat_calc(struct ftrace_profile *rec,
>>   	if (rec->counter <= 1)
>>   		*stddev = 0;
>>   	else {
>> -		*stddev = rec->time_squared - rec->counter * (*avg) * (*avg);
>> +		/*
>> +		 * Apply Welford's method.
>
> Welford's method is not well known. Please add:
>
> 		* s^2 = 1 / (n * (n-1)) * (n * \Sum (x_i)^2 - (\Sum x_i)^2)
>

Ok.

BTW, it is in general more interesting to look at distributions before
doing averages and std devs (one can miss multimodal distributions, etc.).
Is there any lightweight way to get single duration values of functions?
I mean, apart from parsing function graph trace off-line.

Thanks,

- Juri

>> +		 */
>> +		*stddev = rec->counter * rec->time_squared -
>> +			  rec->time * rec->time;
>>
>>   		/*
>>   		 * Divide only 1000 for ns^2 -> us^2 conversion.
>>   		 * trace_print_graph_duration will divide 1000 again.
>>   		 */
>> -		do_div(*stddev, (rec->counter - 1) * 1000);
>> +		do_div(*stddev, rec->counter * (rec->counter - 1) * 1000);
>>   	}
>>   }
>>
>
>