Received: by 10.213.65.68 with SMTP id h4csp1322754imn; Sat, 24 Mar 2018 09:27:56 -0700 (PDT) X-Google-Smtp-Source: AG47ELvjqqA5DDrAyFGiMyPlolFGsu7xtaC3/Z+se9RLD+gmnl9+DuBzqiWqTjv9tAbO1BAd8zC/ X-Received: by 10.167.128.194 with SMTP id a2mr28033615pfn.186.1521908876405; Sat, 24 Mar 2018 09:27:56 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1521908876; cv=none; d=google.com; s=arc-20160816; b=g6J7eD2GpYVK2zxkGnqA4vt2D3No/0+Isys0uUaxrAmGVV/HXTttvyCAXVLs1n6Sep PamNGpMLJGZDcro/qJ7IuAMtTkAbUWb76tXESKeXOebZAP0ZFxX3wnrheTv1FRaG/XQO ZAAV+dZmaXqaGlHyjxjasAEVCmAMkuvwA6li4n8WXL3NsvhLUpsSk1b4b7HPhmQQH1e+ hVLRaz0j1jM2gN+VDDiKKBDDcT9iZmiXacAKIX6poHKISkNlQvX+TJiBLRVz4zOl18k+ jXRKLN/AzS73jCExW1QtbIlXdu34tKrOoxjkpzL348JRMV+5cySgkUmwL21B/E393zTS +org== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:sender:message-id:date:subject:cc:to:from :arc-authentication-results; bh=kg798qR7jMAreJlQFrtkMsSBmCxTUO8bU3klnrtwwJU=; b=TlSzJm+7CXlY+b5TFgU7noM18pkRMsdmsd9PW0J6P1ujbJ4LuTerSnJ34PJX/44CYA P9oegIm+n6xod526P3hx9WzMXimOCMYLmDBuuIKxFxT9GRg+7+wPM5+r1TMrNk13eFZZ qrJTPAZFzFKCmpXaRPvuSmNiSphvOjkhrF7M1hanjAXCM0M4zE5fbxCDv1V4QwOVIX2g SOllGvNrzRbjf9dWkc+KjAJMManq+LsOrTFvQEKJRe86ccnVxbXaSkiJcogYxFGgf6ck Hj9IAwrz/VIpscwtspFFX6RcUw7Td24nSrGdFPEUzOzgD3nIxbhlxt5JhgZmWA/dUcUe dibw== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Return-Path: Received: from vger.kernel.org (vger.kernel.org. [209.132.180.67]) by mx.google.com with ESMTP id s15-v6si11744160plj.701.2018.03.24.09.27.39; Sat, 24 Mar 2018 09:27:56 -0700 (PDT) Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67; Authentication-Results: mx.google.com; spf=pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752488AbeCXQ0q (ORCPT + 99 others); Sat, 24 Mar 2018 12:26:46 -0400 Received: from orthanc.universe-factory.net ([104.238.176.138]:53240 "EHLO orthanc.universe-factory.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752167AbeCXQ0o (ORCPT ); Sat, 24 Mar 2018 12:26:44 -0400 Received: from localhost.localdomain (unknown [IPv6:2001:19f0:6c01:100::2]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by orthanc.universe-factory.net (Postfix) with ESMTPSA id 39CEE1F516; Sat, 24 Mar 2018 17:26:43 +0100 (CET) From: Matthias Schiffer To: rostedt@goodmis.org, mingo@redhat.com Cc: linux-kernel@vger.kernel.org, mschiffer@universe-factory.net Subject: [PATCH] ftrace: fix stddev calculation in function profiler (again) Date: Sat, 24 Mar 2018 17:26:38 +0100 Message-Id: X-Mailer: git-send-email 2.16.2 Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 --- 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