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 <mschif...@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:
>
signature.asc
Description: OpenPGP digital signature
