* [PATCH 0/3] ftrace: fix stddev calculation and add a test for it
@ 2013-06-11 9:08 Juri Lelli
2013-06-11 9:08 ` [PATCH 1/3] ftrace: refactor basis statistics calculation code Juri Lelli
` (2 more replies)
0 siblings, 3 replies; 7+ messages in thread
From: Juri Lelli @ 2013-06-11 9:08 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, 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
^ permalink raw reply [flat|nested] 7+ messages in thread
* [PATCH 1/3] ftrace: refactor basis statistics calculation code
2013-06-11 9:08 [PATCH 0/3] ftrace: fix stddev calculation and add a test for it Juri Lelli
@ 2013-06-11 9:08 ` Juri Lelli
2013-06-11 9:08 ` [PATCH 2/3] ftrace: test basic statistics calculation Juri Lelli
2013-06-11 9:08 ` [PATCH 3/3] ftrace: fix stddev calculation Juri Lelli
2 siblings, 0 replies; 7+ messages in thread
From: Juri Lelli @ 2013-06-11 9:08 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, 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
^ permalink raw reply related [flat|nested] 7+ messages in thread
* [PATCH 2/3] ftrace: test basic statistics calculation
2013-06-11 9:08 [PATCH 0/3] ftrace: fix stddev calculation and add a test for it Juri Lelli
2013-06-11 9:08 ` [PATCH 1/3] ftrace: refactor basis statistics calculation code Juri Lelli
@ 2013-06-11 9:08 ` Juri Lelli
2013-06-12 0:00 ` Steven Rostedt
2013-06-11 9:08 ` [PATCH 3/3] ftrace: fix stddev calculation Juri Lelli
2 siblings, 1 reply; 7+ messages in thread
From: Juri Lelli @ 2013-06-11 9:08 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, 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
^ permalink raw reply related [flat|nested] 7+ messages in thread
* [PATCH 3/3] ftrace: fix stddev calculation
2013-06-11 9:08 [PATCH 0/3] ftrace: fix stddev calculation and add a test for it Juri Lelli
2013-06-11 9:08 ` [PATCH 1/3] ftrace: refactor basis statistics calculation code Juri Lelli
2013-06-11 9:08 ` [PATCH 2/3] ftrace: test basic statistics calculation Juri Lelli
@ 2013-06-11 9:08 ` Juri Lelli
2013-06-12 3:09 ` Steven Rostedt
2 siblings, 1 reply; 7+ messages in thread
From: Juri Lelli @ 2013-06-11 9:08 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, 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
^ permalink raw reply related [flat|nested] 7+ messages in thread
* Re: [PATCH 2/3] ftrace: test basic statistics calculation
2013-06-11 9:08 ` [PATCH 2/3] ftrace: test basic statistics calculation Juri Lelli
@ 2013-06-12 0:00 ` Steven Rostedt
0 siblings, 0 replies; 7+ messages in thread
From: Steven Rostedt @ 2013-06-12 0:00 UTC (permalink / raw)
To: Juri Lelli; +Cc: fweisbec, mingo, linux-kernel, Chase Douglas
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)
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH 3/3] ftrace: fix stddev calculation
2013-06-11 9:08 ` [PATCH 3/3] ftrace: fix stddev calculation Juri Lelli
@ 2013-06-12 3:09 ` Steven Rostedt
2013-06-12 9:34 ` Juri Lelli
0 siblings, 1 reply; 7+ messages in thread
From: Steven Rostedt @ 2013-06-12 3:09 UTC (permalink / raw)
To: Juri Lelli; +Cc: fweisbec, mingo, linux-kernel, Chase Douglas
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);
> }
> }
>
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH 3/3] ftrace: fix stddev calculation
2013-06-12 3:09 ` Steven Rostedt
@ 2013-06-12 9:34 ` Juri Lelli
0 siblings, 0 replies; 7+ messages in thread
From: Juri Lelli @ 2013-06-12 9:34 UTC (permalink / raw)
To: Steven Rostedt; +Cc: fweisbec, mingo, linux-kernel, Chase Douglas
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);
>> }
>> }
>>
>
>
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2013-06-12 9:35 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2013-06-11 9:08 [PATCH 0/3] ftrace: fix stddev calculation and add a test for it Juri Lelli
2013-06-11 9:08 ` [PATCH 1/3] ftrace: refactor basis statistics calculation code Juri Lelli
2013-06-11 9:08 ` [PATCH 2/3] ftrace: test basic statistics calculation Juri Lelli
2013-06-12 0:00 ` Steven Rostedt
2013-06-11 9:08 ` [PATCH 3/3] ftrace: fix stddev calculation Juri Lelli
2013-06-12 3:09 ` Steven Rostedt
2013-06-12 9:34 ` Juri Lelli
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.