[PATCH] ftrace: fix stddev calculation in function profiler (again)

[PATCH] ftrace: fix stddev calculation in function profiler (again)

[Matthias Schiffer]

It is well-known that it is not possible to accurately calculate variances
just by accumulating squared samples; in fact, such an approach can even
result in negative numbers. An earlier attempt to fix the calculation
referred to Welford's method, but did not implement it correctly, leading
to meeaningless output like the following:

  nf_conntrack_proto_fini     50    373.523 us    7.470 us    3234315951 us

Welford's method uses one do_div() in the tracing path; this cannot be
avoided. The average time is added to struct ftrace_profile, so only a
single division is required. I also considered the following alternatives:

1) Only keeping the avg field and removing the aggregated time would
greatly lead to severe rounding errors in calculating the total time based
on counter and avg.

2) Calculating both the old and the new average in profile_graph_return()
instead of storing it in struct ftrace_profile would require a second
division.

3) I managed to transform Welford's equations in a way that uses the total
time instead of the average and requires only a single division.
Unfortunately, the divisor is counter^3 in this case, easily overflowing
even 64bit integers.

Ruling out the above alternatives, I chose the present approach to fix the
issue.

Fixes: e330b3bcd831 ("tracing: Show sample std dev in function profiling")
Fixes: 52d85d763086 ("ftrace: Fix stddev calculation in function profiler")
Signed-off-by: Matthias Schiffer <mschiffer@universe-factory.net>
---
 kernel/trace/ftrace.c | 33 +++++++++++++++++++--------------
 1 file changed, 19 insertions(+), 14 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index eac9ce2c57a2..16dce67b855a 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -460,7 +460,8 @@ struct ftrace_profile {
 	unsigned long			counter;
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 	unsigned long long		time;
-	unsigned long long		time_squared;
+	unsigned long long		avg;
+	unsigned long long		stddev;
 #endif
 };
 
@@ -580,7 +581,6 @@ static int function_stat_show(struct seq_file *m, void *v)
 	int ret = 0;
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 	static struct trace_seq s;
-	unsigned long long avg;
 	unsigned long long stddev;
 #endif
 	mutex_lock(&ftrace_profile_lock);
@@ -592,9 +592,7 @@ static int function_stat_show(struct seq_file *m, void *v)
 	}
 
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
-	avg = rec->time;
-	do_div(avg, rec->counter);
-	if (tracing_thresh && (avg < tracing_thresh))
+	if (tracing_thresh && (rec->avg < tracing_thresh))
 		goto out;
 #endif
 
@@ -608,24 +606,19 @@ static int function_stat_show(struct seq_file *m, void *v)
 	if (rec->counter <= 1)
 		stddev = 0;
 	else {
-		/*
-		 * Apply Welford's method:
-		 * s^2 = 1 / (n * (n-1)) * (n * \Sum (x_i)^2 - (\Sum x_i)^2)
-		 */
-		stddev = rec->counter * rec->time_squared -
-			 rec->time * rec->time;
+		stddev = rec->stddev;
 
 		/*
 		 * Divide only 1000 for ns^2 -> us^2 conversion.
 		 * trace_print_graph_duration will divide 1000 again.
 		 */
-		do_div(stddev, rec->counter * (rec->counter - 1) * 1000);
+		do_div(stddev, 1000 * (rec->counter - 1));
 	}
 
 	trace_seq_init(&s);
 	trace_print_graph_duration(rec->time, &s);
 	trace_seq_puts(&s, "    ");
-	trace_print_graph_duration(avg, &s);
+	trace_print_graph_duration(rec->avg, &s);
 	trace_seq_puts(&s, "    ");
 	trace_print_graph_duration(stddev, &s);
 	trace_print_seq(m, &s);
@@ -905,8 +898,20 @@ static void profile_graph_return(struct ftrace_graph_ret *trace)
 
 	rec = ftrace_find_profiled_func(stat, trace->func);
 	if (rec) {
+		unsigned long long avg, delta1, delta2;
+
 		rec->time += calltime;
-		rec->time_squared += calltime * calltime;
+
+		/* Apply Welford's method */
+		delta1 = calltime - rec->avg;
+
+		avg = rec->time;
+		do_div(avg, rec->counter);
+		rec->avg = avg;
+
+		delta2 = calltime - rec->avg;
+
+		rec->stddev += delta1 * delta2;
 	}
 
  out:
-- 
2.16.2

Re: [PATCH] ftrace: fix stddev calculation in function profiler (again)

[Matthias Schiffer]

[-- Attachment #1.1: Type: text/plain, Size: 4730 bytes --]

On 03/24/2018 05:26 PM, Matthias Schiffer wrote:
> It is well-known that it is not possible to accurately calculate variances
> just by accumulating squared samples; in fact, such an approach can even
> result in negative numbers. An earlier attempt to fix the calculation
> referred to Welford's method, but did not implement it correctly, leading
> to meeaningless output like the following:
> 
>   nf_conntrack_proto_fini     50    373.523 us    7.470 us    3234315951 us
> 
> Welford's method uses one do_div() in the tracing path; this cannot be
> avoided. The average time is added to struct ftrace_profile, so only a
> single division is required. I also considered the following alternatives:
> 
> 1) Only keeping the avg field and removing the aggregated time would
> greatly lead to severe rounding errors in calculating the total time based
> on counter and avg.
> 
> 2) Calculating both the old and the new average in profile_graph_return()
> instead of storing it in struct ftrace_profile would require a second
> division.
> 
> 3) I managed to transform Welford's equations in a way that uses the total
> time instead of the average and requires only a single division.
> Unfortunately, the divisor is counter^3 in this case, easily overflowing
> even 64bit integers.
> 
> Ruling out the above alternatives, I chose the present approach to fix the
> issue.
> 
> Fixes: e330b3bcd831 ("tracing: Show sample std dev in function profiling")
> Fixes: 52d85d763086 ("ftrace: Fix stddev calculation in function profiler")
> Signed-off-by: Matthias Schiffer <mschiffer@universe-factory.net>


Hmm, in further testing, I'm seeing profile_graph_return() being called
without rec->counter getting incremented a lot, completely throwing off the
stddev calculation (and also slightly displacing the average). Is this
expected?

Should we possibly move the counter increment to profile_graph_return() in
the CONFIG_FUNCTION_GRAPH_TRACER case, or introduce a second counter for
returns?

Matthias



> ---
>  kernel/trace/ftrace.c | 33 +++++++++++++++++++--------------
>  1 file changed, 19 insertions(+), 14 deletions(-)
> 
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index eac9ce2c57a2..16dce67b855a 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -460,7 +460,8 @@ struct ftrace_profile {
>  	unsigned long			counter;
>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
>  	unsigned long long		time;
> -	unsigned long long		time_squared;
> +	unsigned long long		avg;
> +	unsigned long long		stddev;
>  #endif
>  };
>  
> @@ -580,7 +581,6 @@ static int function_stat_show(struct seq_file *m, void *v)
>  	int ret = 0;
>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
>  	static struct trace_seq s;
> -	unsigned long long avg;
>  	unsigned long long stddev;
>  #endif
>  	mutex_lock(&ftrace_profile_lock);
> @@ -592,9 +592,7 @@ static int function_stat_show(struct seq_file *m, void *v)
>  	}
>  
>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
> -	avg = rec->time;
> -	do_div(avg, rec->counter);
> -	if (tracing_thresh && (avg < tracing_thresh))
> +	if (tracing_thresh && (rec->avg < tracing_thresh))
>  		goto out;
>  #endif
>  
> @@ -608,24 +606,19 @@ static int function_stat_show(struct seq_file *m, void *v)
>  	if (rec->counter <= 1)
>  		stddev = 0;
>  	else {
> -		/*
> -		 * Apply Welford's method:
> -		 * s^2 = 1 / (n * (n-1)) * (n * \Sum (x_i)^2 - (\Sum x_i)^2)
> -		 */
> -		stddev = rec->counter * rec->time_squared -
> -			 rec->time * rec->time;
> +		stddev = rec->stddev;
>  
>  		/*
>  		 * Divide only 1000 for ns^2 -> us^2 conversion.
>  		 * trace_print_graph_duration will divide 1000 again.
>  		 */
> -		do_div(stddev, rec->counter * (rec->counter - 1) * 1000);
> +		do_div(stddev, 1000 * (rec->counter - 1));
>  	}
>  
>  	trace_seq_init(&s);
>  	trace_print_graph_duration(rec->time, &s);
>  	trace_seq_puts(&s, "    ");
> -	trace_print_graph_duration(avg, &s);
> +	trace_print_graph_duration(rec->avg, &s);
>  	trace_seq_puts(&s, "    ");
>  	trace_print_graph_duration(stddev, &s);
>  	trace_print_seq(m, &s);
> @@ -905,8 +898,20 @@ static void profile_graph_return(struct ftrace_graph_ret *trace)
>  
>  	rec = ftrace_find_profiled_func(stat, trace->func);
>  	if (rec) {
> +		unsigned long long avg, delta1, delta2;
> +
>  		rec->time += calltime;
> -		rec->time_squared += calltime * calltime;
> +
> +		/* Apply Welford's method */
> +		delta1 = calltime - rec->avg;
> +
> +		avg = rec->time;
> +		do_div(avg, rec->counter);
> +		rec->avg = avg;
> +
> +		delta2 = calltime - rec->avg;
> +
> +		rec->stddev += delta1 * delta2;
>  	}
>  
>   out:
> 



[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [PATCH] ftrace: fix stddev calculation in function profiler (again)

[Matthias Schiffer]

[-- Attachment #1.1: Type: text/plain, Size: 5934 bytes --]

On 03/24/2018 11:03 PM, Matthias Schiffer wrote:
> On 03/24/2018 05:26 PM, Matthias Schiffer wrote:
>> It is well-known that it is not possible to accurately calculate variances
>> just by accumulating squared samples; in fact, such an approach can even
>> result in negative numbers. An earlier attempt to fix the calculation
>> referred to Welford's method, but did not implement it correctly, leading
>> to meeaningless output like the following:
>>
>>   nf_conntrack_proto_fini     50    373.523 us    7.470 us    3234315951 us
>>
>> Welford's method uses one do_div() in the tracing path; this cannot be
>> avoided. The average time is added to struct ftrace_profile, so only a
>> single division is required. I also considered the following alternatives:
>>
>> 1) Only keeping the avg field and removing the aggregated time would
>> greatly lead to severe rounding errors in calculating the total time based
>> on counter and avg.
>>
>> 2) Calculating both the old and the new average in profile_graph_return()
>> instead of storing it in struct ftrace_profile would require a second
>> division.
>>
>> 3) I managed to transform Welford's equations in a way that uses the total
>> time instead of the average and requires only a single division.
>> Unfortunately, the divisor is counter^3 in this case, easily overflowing
>> even 64bit integers.
>>
>> Ruling out the above alternatives, I chose the present approach to fix the
>> issue.
>>
>> Fixes: e330b3bcd831 ("tracing: Show sample std dev in function profiling")
>> Fixes: 52d85d763086 ("ftrace: Fix stddev calculation in function profiler")
>> Signed-off-by: Matthias Schiffer <mschiffer@universe-factory.net>
> 
> 
> Hmm, in further testing, I'm seeing profile_graph_return() being called
> without rec->counter getting incremented a lot, completely throwing off the
> stddev calculation (and also slightly displacing the average). Is this
> expected?
> 
> Should we possibly move the counter increment to profile_graph_return() in
> the CONFIG_FUNCTION_GRAPH_TRACER case, or introduce a second counter for
> returns?
> 
> Matthias

profile_graph_return() being called without rec->counter getting
incremented turned out to be another MIPS-specific bug, I'll send patch for
that, too.


I have two more questions/issues regarding the generic code:

1) There is a small window when enabling the profiler where rec->counter
gets incremented, but profile_graph_return() does not record times yet. For
functions that are called a lot, the effect is negligible, but for very
infrequent calls, the shown average time and variance are way off. Moving
the rec->counter increment to profile_graph_return() when
CONFIG_FUNCTION_GRAPH_TRACER is enabled would fix this. Does this sound
reasonable?

2) I noticed that my patch does not handle rec->counter overflows correctly
and will cause a zero division. I can think of two solutions for handling
overflows that keep the avg / stddev fields meaningful:
- Reset time/avg/stddev to 0 on overflows
- Stop updating the record at 0xffffffff, avoiding the overflow

Matthias


> 
> 
> 
>> ---
>>  kernel/trace/ftrace.c | 33 +++++++++++++++++++--------------
>>  1 file changed, 19 insertions(+), 14 deletions(-)
>>
>> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
>> index eac9ce2c57a2..16dce67b855a 100644
>> --- a/kernel/trace/ftrace.c
>> +++ b/kernel/trace/ftrace.c
>> @@ -460,7 +460,8 @@ struct ftrace_profile {
>>  	unsigned long			counter;
>>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
>>  	unsigned long long		time;
>> -	unsigned long long		time_squared;
>> +	unsigned long long		avg;
>> +	unsigned long long		stddev;
>>  #endif
>>  };
>>  
>> @@ -580,7 +581,6 @@ static int function_stat_show(struct seq_file *m, void *v)
>>  	int ret = 0;
>>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
>>  	static struct trace_seq s;
>> -	unsigned long long avg;
>>  	unsigned long long stddev;
>>  #endif
>>  	mutex_lock(&ftrace_profile_lock);
>> @@ -592,9 +592,7 @@ static int function_stat_show(struct seq_file *m, void *v)
>>  	}
>>  
>>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
>> -	avg = rec->time;
>> -	do_div(avg, rec->counter);
>> -	if (tracing_thresh && (avg < tracing_thresh))
>> +	if (tracing_thresh && (rec->avg < tracing_thresh))
>>  		goto out;
>>  #endif
>>  
>> @@ -608,24 +606,19 @@ static int function_stat_show(struct seq_file *m, void *v)
>>  	if (rec->counter <= 1)
>>  		stddev = 0;
>>  	else {
>> -		/*
>> -		 * Apply Welford's method:
>> -		 * s^2 = 1 / (n * (n-1)) * (n * \Sum (x_i)^2 - (\Sum x_i)^2)
>> -		 */
>> -		stddev = rec->counter * rec->time_squared -
>> -			 rec->time * rec->time;
>> +		stddev = rec->stddev;
>>  
>>  		/*
>>  		 * Divide only 1000 for ns^2 -> us^2 conversion.
>>  		 * trace_print_graph_duration will divide 1000 again.
>>  		 */
>> -		do_div(stddev, rec->counter * (rec->counter - 1) * 1000);
>> +		do_div(stddev, 1000 * (rec->counter - 1));
>>  	}
>>  
>>  	trace_seq_init(&s);
>>  	trace_print_graph_duration(rec->time, &s);
>>  	trace_seq_puts(&s, "    ");
>> -	trace_print_graph_duration(avg, &s);
>> +	trace_print_graph_duration(rec->avg, &s);
>>  	trace_seq_puts(&s, "    ");
>>  	trace_print_graph_duration(stddev, &s);
>>  	trace_print_seq(m, &s);
>> @@ -905,8 +898,20 @@ static void profile_graph_return(struct ftrace_graph_ret *trace)
>>  
>>  	rec = ftrace_find_profiled_func(stat, trace->func);
>>  	if (rec) {
>> +		unsigned long long avg, delta1, delta2;
>> +
>>  		rec->time += calltime;
>> -		rec->time_squared += calltime * calltime;
>> +
>> +		/* Apply Welford's method */
>> +		delta1 = calltime - rec->avg;
>> +
>> +		avg = rec->time;
>> +		do_div(avg, rec->counter);
>> +		rec->avg = avg;
>> +
>> +		delta2 = calltime - rec->avg;
>> +
>> +		rec->stddev += delta1 * delta2;
>>  	}
>>  
>>   out:
>>
> 
> 



[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [PATCH] ftrace: fix stddev calculation in function profiler (again)

[Steven Rostedt]

On Sun, 25 Mar 2018 19:09:39 +0200
Matthias Schiffer <mschiffer@universe-factory.net> wrote:

> 
> I have two more questions/issues regarding the generic code:
> 
> 1) There is a small window when enabling the profiler where rec->counter
> gets incremented, but profile_graph_return() does not record times yet. For
> functions that are called a lot, the effect is negligible, but for very
> infrequent calls, the shown average time and variance are way off. Moving
> the rec->counter increment to profile_graph_return() when
> CONFIG_FUNCTION_GRAPH_TRACER is enabled would fix this. Does this sound
> reasonable?

Because the counter is done with function_profile_call() which is used
by function tracer (when graph tracer is not enabled), I wouldn't move
it.

But instead, we could make a function_profile_call() helper that does
all that function_profile_call does, and return a value if it does
something. For example:

static int
calculate_profile_call(unsigned long ip, unsigned long parent_ip,
		       struct ftrace_ops *ops, struct pt_regs *regs)
{
	struct ftrace_profile_stat *stat;
	struct ftrace_profile *rec;
	unsigned long flags;
	int ret = 0;

	if (!ftrace_profile_enabled)
		return 0;

	local_irq_save(flags);

	stat = this_cpu_ptr(&ftrace_profile_stats);
	if (!stat->hash || !ftrace_profile_enabled)
		goto out;

	rec = ftrace_find_profiled_func(stat, ip);
	if (!rec) {
		rec = ftrace_profile_alloc(stat, ip);
		if (!rec)
			goto out;
	}

	rec->counter++;
	ret = 1;
 out:
	local_irq_restore(flags);
	return ret;
}

static void
function_profile_call(unsigned long ip, unsigned long parent_ip,
		      struct ftrace_ops *ops, struct pt_regs *regs)
{
	calculate_profile_call(ip, parent_ip, ops, regs);
}

#ifdef CONFIG_FUNCTION_GRAPH_TRACER
static int profile_graph_entry(struct ftrace_graph_ent *trace)
{
	int index = trace->depth;

	if (!calculate_profile_call(trace->func, 0, NULL, NULL))
		return 0;

	/* If function graph is shutting down, ret_stack can be NULL */
	if (!current->ret_stack)
		return 0;

	if (index >= 0 && index < FTRACE_RETFUNC_DEPTH)
		current->ret_stack[index].subtime = 0;

	return 1;
}

If we don't calculate the profile call, then we return 0, this will
tell the function graph tracer not to perform the return part of the
tracing.

> 
> 2) I noticed that my patch does not handle rec->counter overflows correctly
> and will cause a zero division. I can think of two solutions for handling
> overflows that keep the avg / stddev fields meaningful:
> - Reset time/avg/stddev to 0 on overflows
> - Stop updating the record at 0xffffffff, avoiding the overflow

Or add an option that lets the user decide. But I still would like to
find a way not to add a that division on every function call. That's
really heavy weight.

-- Steve

> 
> Matthias
> 
> 
> > 
> > 
> >   
> >> ---
> >>  kernel/trace/ftrace.c | 33 +++++++++++++++++++--------------
> >>  1 file changed, 19 insertions(+), 14 deletions(-)
> >>
> >> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> >> index eac9ce2c57a2..16dce67b855a 100644
> >> --- a/kernel/trace/ftrace.c
> >> +++ b/kernel/trace/ftrace.c
> >> @@ -460,7 +460,8 @@ struct ftrace_profile {
> >>  	unsigned long			counter;
> >>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
> >>  	unsigned long long		time;
> >> -	unsigned long long		time_squared;
> >> +	unsigned long long		avg;
> >> +	unsigned long long		stddev;
> >>  #endif
> >>  };
> >>  
> >> @@ -580,7 +581,6 @@ static int function_stat_show(struct seq_file *m, void *v)
> >>  	int ret = 0;
> >>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
> >>  	static struct trace_seq s;
> >> -	unsigned long long avg;
> >>  	unsigned long long stddev;
> >>  #endif
> >>  	mutex_lock(&ftrace_profile_lock);
> >> @@ -592,9 +592,7 @@ static int function_stat_show(struct seq_file *m, void *v)
> >>  	}
> >>  
> >>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
> >> -	avg = rec->time;
> >> -	do_div(avg, rec->counter);
> >> -	if (tracing_thresh && (avg < tracing_thresh))
> >> +	if (tracing_thresh && (rec->avg < tracing_thresh))
> >>  		goto out;
> >>  #endif
> >>  
> >> @@ -608,24 +606,19 @@ static int function_stat_show(struct seq_file *m, void *v)
> >>  	if (rec->counter <= 1)
> >>  		stddev = 0;
> >>  	else {
> >> -		/*
> >> -		 * Apply Welford's method:
> >> -		 * s^2 = 1 / (n * (n-1)) * (n * \Sum (x_i)^2 - (\Sum x_i)^2)
> >> -		 */
> >> -		stddev = rec->counter * rec->time_squared -
> >> -			 rec->time * rec->time;
> >> +		stddev = rec->stddev;
> >>  
> >>  		/*
> >>  		 * Divide only 1000 for ns^2 -> us^2 conversion.
> >>  		 * trace_print_graph_duration will divide 1000 again.
> >>  		 */
> >> -		do_div(stddev, rec->counter * (rec->counter - 1) * 1000);
> >> +		do_div(stddev, 1000 * (rec->counter - 1));
> >>  	}
> >>  
> >>  	trace_seq_init(&s);
> >>  	trace_print_graph_duration(rec->time, &s);
> >>  	trace_seq_puts(&s, "    ");
> >> -	trace_print_graph_duration(avg, &s);
> >> +	trace_print_graph_duration(rec->avg, &s);
> >>  	trace_seq_puts(&s, "    ");
> >>  	trace_print_graph_duration(stddev, &s);
> >>  	trace_print_seq(m, &s);
> >> @@ -905,8 +898,20 @@ static void profile_graph_return(struct ftrace_graph_ret *trace)
> >>  
> >>  	rec = ftrace_find_profiled_func(stat, trace->func);
> >>  	if (rec) {
> >> +		unsigned long long avg, delta1, delta2;
> >> +
> >>  		rec->time += calltime;
> >> -		rec->time_squared += calltime * calltime;
> >> +
> >> +		/* Apply Welford's method */
> >> +		delta1 = calltime - rec->avg;
> >> +
> >> +		avg = rec->time;
> >> +		do_div(avg, rec->counter);
> >> +		rec->avg = avg;
> >> +
> >> +		delta2 = calltime - rec->avg;
> >> +
> >> +		rec->stddev += delta1 * delta2;
> >>  	}
> >>  
> >>   out:
> >>  
> > 
> >   
> 
> 

Re: [PATCH] ftrace: fix stddev calculation in function profiler (again)

[Steven Rostedt]

On Sat, 24 Mar 2018 17:26:38 +0100
Matthias Schiffer <mschiffer@universe-factory.net> wrote:

> @@ -905,8 +898,20 @@ static void profile_graph_return(struct ftrace_graph_ret *trace)
>  
>  	rec = ftrace_find_profiled_func(stat, trace->func);
>  	if (rec) {
> +		unsigned long long avg, delta1, delta2;
> +
>  		rec->time += calltime;
> -		rec->time_squared += calltime * calltime;
> +
> +		/* Apply Welford's method */
> +		delta1 = calltime - rec->avg;
> +
> +		avg = rec->time;
> +		do_div(avg, rec->counter);

Can you find a way not to do a divide in every function call?

-- Steve

> +		rec->avg = avg;
> +
> +		delta2 = calltime - rec->avg;
> +
> +		rec->stddev += delta1 * delta2;
>  	}
>  
>   out:

Re: [PATCH] ftrace: fix stddev calculation in function profiler (again)

[Matthias Schiffer]

[-- Attachment #1.1: Type: text/plain, Size: 1435 bytes --]

On 03/26/2018 06:51 PM, Steven Rostedt wrote:
> On Sat, 24 Mar 2018 17:26:38 +0100
> Matthias Schiffer <mschiffer@universe-factory.net> wrote:
> 
>> @@ -905,8 +898,20 @@ static void profile_graph_return(struct ftrace_graph_ret *trace)
>>  
>>  	rec = ftrace_find_profiled_func(stat, trace->func);
>>  	if (rec) {
>> +		unsigned long long avg, delta1, delta2;
>> +
>>  		rec->time += calltime;
>> -		rec->time_squared += calltime * calltime;
>> +
>> +		/* Apply Welford's method */
>> +		delta1 = calltime - rec->avg;
>> +
>> +		avg = rec->time;
>> +		do_div(avg, rec->counter);
> 
> Can you find a way not to do a divide in every function call?

I think the current method based on the sum of squares is the best we can
do without a divide for each sample. The completely bogus result

  nf_conntrack_proto_fini     50    373.523 us    7.470 us    3234315951 us

I mentioned in my commit message was caused by the second MIPS-specific
issue I mentioned in my last mail, so while this method may lead to
inaccurate results [1], and it is certainly not Welford's method, it might
be good enough in practice, and you can disregard my patch.

Matthias


[1]
http://jonisalonen.com/2013/deriving-welfords-method-for-computing-variance/


> 
> -- Steve
> 
>> +		rec->avg = avg;
>> +
>> +		delta2 = calltime - rec->avg;
>> +
>> +		rec->stddev += delta1 * delta2;
>>  	}
>>  
>>   out:
> 



[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [PATCH] ftrace: fix stddev calculation in function profiler (again)

[Steven Rostedt]

On Tue, 27 Mar 2018 16:51:49 +0200
Matthias Schiffer <mschiffer@universe-factory.net> wrote:

> I mentioned in my commit message was caused by the second MIPS-specific
> issue I mentioned in my last mail, so while this method may lead to
> inaccurate results [1], and it is certainly not Welford's method, it might
> be good enough in practice, and you can disregard my patch.

Thanks for verifying.

Did you have any other patches to this code I need to look at?

-- Steve