From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail-wm1-f44.google.com (mail-wm1-f44.google.com [209.85.128.44]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 9A02C1DC9BC for ; Mon, 6 Jan 2025 17:14:32 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=209.85.128.44 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1736183674; cv=none; b=TzcoZQXmCdZ1e9Osx6F4ocK23Z9SQ5+aC3bAm7009iorla5mxf5vnNWm5vaXHNwPmq1N+L+isVRAY2z+0hXKOKlbUAhmkscKLlWI0OZPCh9rycwuj3Awi1oj/NaRzqZnstMmkhbh2GIYZhdEXSjwVmm/ZH4niITePD0qU4tV00I= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1736183674; c=relaxed/simple; bh=gYPX7ak35yKqpjfcfidNp35ku7greqbhh704o4wb97Q=; h=Message-ID:Date:MIME-Version:Subject:To:Cc:References:From: In-Reply-To:Content-Type; b=gWUhv8L4FlVHq+RE4HxVymEIoVkzLJIkw5n3jMAyXxXY7h51QpOARLAKdydgEa7p/SZ0O2Qwc4ylEi+Gi3eDM+1bJX/fJG0kkx1vK5tTAXCUqYv/5zr+TGWG94ExV7y4+GlQtb64FGFfVYEA3Rvn8id63WDKh6zZjyjZp6DhKos= ARC-Authentication-Results:i=1; smtp.subspace.kernel.org; dmarc=pass (p=none dis=none) header.from=linaro.org; spf=pass smtp.mailfrom=linaro.org; dkim=pass (2048-bit key) header.d=linaro.org header.i=@linaro.org header.b=G3Sd5VWg; arc=none smtp.client-ip=209.85.128.44 Authentication-Results: smtp.subspace.kernel.org; dmarc=pass (p=none dis=none) header.from=linaro.org Authentication-Results: smtp.subspace.kernel.org; spf=pass smtp.mailfrom=linaro.org Authentication-Results: smtp.subspace.kernel.org; dkim=pass (2048-bit key) header.d=linaro.org header.i=@linaro.org header.b="G3Sd5VWg" Received: by mail-wm1-f44.google.com with SMTP id 5b1f17b1804b1-43625c4a50dso100848345e9.0 for ; Mon, 06 Jan 2025 09:14:32 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=linaro.org; s=google; t=1736183671; x=1736788471; darn=vger.kernel.org; h=content-transfer-encoding:in-reply-to:from:content-language :references:cc:to:subject:user-agent:mime-version:date:message-id :from:to:cc:subject:date:message-id:reply-to; bh=By5FO0EVLUXQEFNClCmXQLNWlbEh6v8HuXoE6KBTHJw=; b=G3Sd5VWgKirfSA5fFCtqQbeDBIcuNvv8hrBvrANKhPjQgZ9NyLyMiliuts3X2/7TnC lUrzmAxZN4STQT1mHUovCBBHaH/i9jvR6kM35RnCMMykBUzHLNedVaw3HZS+iW12P7kE YtWgNbNh1xqVE6OJT6L52dMzXcrscg8lcsejSKcT09+KVgImZTDWNzqK/XbCmPVdwOOk LyfIFycSbilMfft53L5/C70nvR4lZcRyDC3pzN2tkUtyweHCbAuEOuy10hBPth9BGtvt dOhMcrUtfv68kdKDb/oBQQCLzXFmu5a5maKQ80SaNrE2auUW7/CFYlkDCTMZy8lBXbc/ M5qA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1736183671; x=1736788471; h=content-transfer-encoding:in-reply-to:from:content-language :references:cc:to:subject:user-agent:mime-version:date:message-id :x-gm-message-state:from:to:cc:subject:date:message-id:reply-to; bh=By5FO0EVLUXQEFNClCmXQLNWlbEh6v8HuXoE6KBTHJw=; b=chKF5SX3HB16k2duyoo4hw/hkpHGOV851gho0MrF63I74/t6O5eXVVhSkN37aJTL5L SkVi6/ZAyqYLwmoLzJl8/1TKP093cDlf/YCDoEAgAD7qN4WQfObnaYy6S7p617YNRhc+ ygkk3WzUHpcahto9wocvaHPH4VdXRjHOecKrw79JnqSX43YwQINLSfz/oQ7TzivWj45/ p6e2kZmnDPhz41XSE89utbBVtpTAKeeCG/rl5pvpyLX/R7HR/5x8WqI1PoGylst++ICp DKkK4VetM73+ZeR4R2coig+n6DNsT7nDxPxoFsa2gN87IVqr35YrVQ/+XBC74tjgaOjF CxBw== X-Forwarded-Encrypted: i=1; AJvYcCVFBmeRo35wLajzgSe4VJ+CL1vAv9YZ6ciVblsRMFlXdqAs9uB2rwuhPQI7luPD0+dlJvjKw+CJ14lBY4A=@vger.kernel.org X-Gm-Message-State: AOJu0Yxk/KPt7W5FyX5LOt6qlA579Zrv5e8hyzCY9GTG+D6ZU3sUQYm8 MxNhwEzpESTh5Oq6C0qG2zK3HqC6E4mY/kWml2t7Wwf/QxSBQjmhXdjx74DwWaY= X-Gm-Gg: ASbGncskpPZD3XlyQjv9t6OCPvEK/GoNAENti36uYiHtECBaQRZ/SsGAlo4AxyP6V+F AVrMCh30wdt0F5IGopcoccAcCWLbErZHg0QIdBy1fJR5M1eGlweQ2lI2xCQxrUBn8fEvV72+CVm FYPyE5oCP5VKvyuRJPonuUYfgm56+kF5azFQ2pmWcmjleGYvhxkZ5TA7dC4Vo0yEisZW2OUw1Ka 5r7n8oXDQjYmCINwMx15gt+Nekqibl84OxMO2ALA0wKGsLo4CvjneUaxa5iF5ec4QU= X-Google-Smtp-Source: AGHT+IG2kv6l6sn/Vui5wWFhKF7l6rM48110BNmcxfXFFXzAX67245U6lWTyxNGe2Tb58ldO2zIIiw== X-Received: by 2002:adf:a342:0:b0:38a:624b:e37b with SMTP id ffacd0b85a97d-38a624be4e4mr14170002f8f.53.1736183670763; Mon, 06 Jan 2025 09:14:30 -0800 (PST) Received: from [192.168.68.163] ([145.224.66.180]) by smtp.gmail.com with ESMTPSA id 5b1f17b1804b1-436611ea3e0sm580183545e9.7.2025.01.06.09.14.25 (version=TLS1_3 cipher=TLS_AES_128_GCM_SHA256 bits=128/128); Mon, 06 Jan 2025 09:14:30 -0800 (PST) Message-ID: Date: Mon, 6 Jan 2025 17:14:15 +0000 Precedence: bulk X-Mailing-List: linux-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 User-Agent: Mozilla Thunderbird Subject: Re: [PATCH 1/3] perf ftrace: Add --stats option to latency subcommand To: Namhyung Kim Cc: Jiri Olsa , Adrian Hunter , Peter Zijlstra , Ingo Molnar , LKML , linux-perf-users@vger.kernel.org, Arnaldo Carvalho de Melo , Ian Rogers , Kan Liang References: <20250103231630.928815-1-namhyung@kernel.org> Content-Language: en-US From: James Clark In-Reply-To: <20250103231630.928815-1-namhyung@kernel.org> Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit On 03/01/2025 11:16 pm, Namhyung Kim wrote: > Sometimes users also want to see average latency as well as histogram. > The --stats option is to display latency statistics at the end. > > $ sudo ./perf ftrace latency -ab --stats -T synchronize_rcu -- ... > # DURATION | COUNT | GRAPH | > 0 - 1 us | 0 | | > 1 - 2 us | 0 | | > 2 - 4 us | 0 | | > 4 - 8 us | 0 | | > 8 - 16 us | 0 | | > 16 - 32 us | 0 | | > 32 - 64 us | 0 | | > 64 - 128 us | 0 | | > 128 - 256 us | 0 | | > 256 - 512 us | 0 | | > 512 - 1024 us | 0 | | > 1 - 2 ms | 0 | | > 2 - 4 ms | 0 | | > 4 - 8 ms | 0 | | > 8 - 16 ms | 1 | ##### | > 16 - 32 ms | 7 | ######################################## | > 32 - 64 ms | 0 | | > 64 - 128 ms | 0 | | > 128 - 256 ms | 0 | | > 256 - 512 ms | 0 | | > 512 - 1024 ms | 0 | | > 1 - ... s | 0 | | > > # statistics (in usec) > total time: 171832 > avg time: 21479 > max time: 30906 > min time: 15869 > count: 8 > > Signed-off-by: Namhyung Kim > --- > tools/perf/Documentation/perf-ftrace.txt | 4 ++++ > tools/perf/builtin-ftrace.c | 24 ++++++++++++++++++++- > tools/perf/util/bpf_ftrace.c | 16 ++++++++++++-- > tools/perf/util/bpf_skel/func_latency.bpf.c | 19 ++++++++++++++++ > tools/perf/util/ftrace.h | 4 +++- > 5 files changed, 63 insertions(+), 4 deletions(-) > > diff --git a/tools/perf/Documentation/perf-ftrace.txt b/tools/perf/Documentation/perf-ftrace.txt > index eccc0483f7faecad..16b067eb5d84746d 100644 > --- a/tools/perf/Documentation/perf-ftrace.txt > +++ b/tools/perf/Documentation/perf-ftrace.txt > @@ -160,6 +160,10 @@ OPTIONS for 'perf ftrace latency' > -n/--use-nsec). The setting is ignored if the value results in more than > 22 buckets. > > +--stats:: > + Display latency statistics at the end. > + > + > OPTIONS for 'perf ftrace profile' > --------------------------------- > > diff --git a/tools/perf/builtin-ftrace.c b/tools/perf/builtin-ftrace.c > index 834074162a63bf2b..0ac2b20b272bd790 100644 > --- a/tools/perf/builtin-ftrace.c > +++ b/tools/perf/builtin-ftrace.c > @@ -43,6 +43,8 @@ > static volatile sig_atomic_t workload_exec_errno; > static volatile sig_atomic_t done; > > +static struct stats latency_stats; /* for tracepoints */ > + > static void sig_handler(int sig __maybe_unused) > { > done = true; > @@ -801,6 +803,13 @@ static void make_histogram(struct perf_ftrace *ftrace, int buckets[], > do_inc: > buckets[i]++; > > + if (ftrace->stats) { > + if (num >= min_latency) > + num += min_latency; > + > + update_stats(&latency_stats, num); > + } > + > next: > /* empty the line buffer for the next output */ > linebuf[0] = '\0'; > @@ -894,6 +903,14 @@ static void display_histogram(struct perf_ftrace *ftrace, int buckets[]) > printf(" | %10d | %.*s%*s |\n", buckets[NUM_BUCKET - 1], > bar_len, bar, bar_total - bar_len, ""); > > + if (ftrace->stats) { > + printf("\n# statistics (in %s)\n", ftrace->use_nsec ? "nsec" : "usec"); > + printf(" total time: %20.0f\n", latency_stats.mean * latency_stats.n); > + printf(" avg time: %20.0f\n", latency_stats.mean); > + printf(" max time: %20"PRIu64"\n", latency_stats.max); > + printf(" min time: %20"PRIu64"\n", latency_stats.min); > + printf(" count: %20.0f\n", latency_stats.n); > + } > } > > static int prepare_func_latency(struct perf_ftrace *ftrace) > @@ -932,6 +949,9 @@ static int prepare_func_latency(struct perf_ftrace *ftrace) > if (fd < 0) > pr_err("failed to open trace_pipe\n"); > > + if (ftrace->stats) > + init_stats(&latency_stats); > + > put_tracing_file(trace_file); > return fd; > } > @@ -961,7 +981,7 @@ static int stop_func_latency(struct perf_ftrace *ftrace) > static int read_func_latency(struct perf_ftrace *ftrace, int buckets[]) > { > if (ftrace->target.use_bpf) > - return perf_ftrace__latency_read_bpf(ftrace, buckets); > + return perf_ftrace__latency_read_bpf(ftrace, buckets, &latency_stats); > > return 0; > } > @@ -1620,6 +1640,8 @@ int cmd_ftrace(int argc, const char **argv) > "Minimum latency (1st bucket). Works only with --bucket-range."), > OPT_UINTEGER(0, "max-latency", &ftrace.max_latency, > "Maximum latency (last bucket). Works only with --bucket-range and total buckets less than 22."), > + OPT_BOOLEAN(0, "stats", &ftrace.stats, > + "Collect function latency stats too"), > OPT_PARENT(common_options), > }; > const struct option profile_options[] = { > diff --git a/tools/perf/util/bpf_ftrace.c b/tools/perf/util/bpf_ftrace.c > index bc484e65fb8f69ca..ecd5e16df9730e0d 100644 > --- a/tools/perf/util/bpf_ftrace.c > +++ b/tools/perf/util/bpf_ftrace.c > @@ -11,6 +11,7 @@ > #include "util/debug.h" > #include "util/evlist.h" > #include "util/bpf_counter.h" > +#include "util/stat.h" > > #include "util/bpf_skel/func_latency.skel.h" > > @@ -53,6 +54,7 @@ int perf_ftrace__latency_prepare_bpf(struct perf_ftrace *ftrace) > } > > skel->rodata->use_nsec = ftrace->use_nsec; > + skel->rodata->stats = ftrace->stats; > > set_max_rlimit(); > > @@ -86,6 +88,9 @@ int perf_ftrace__latency_prepare_bpf(struct perf_ftrace *ftrace) > } > } > > + if (ftrace->stats) > + skel->bss->min = INT64_MAX; > + > skel->links.func_begin = bpf_program__attach_kprobe(skel->progs.func_begin, > false, func->name); > if (IS_ERR(skel->links.func_begin)) { > @@ -121,8 +126,8 @@ int perf_ftrace__latency_stop_bpf(struct perf_ftrace *ftrace __maybe_unused) > return 0; > } > > -int perf_ftrace__latency_read_bpf(struct perf_ftrace *ftrace __maybe_unused, > - int buckets[]) > +int perf_ftrace__latency_read_bpf(struct perf_ftrace *ftrace, > + int buckets[], struct stats *stats) > { > int i, fd, err; > u32 idx; > @@ -146,6 +151,13 @@ int perf_ftrace__latency_read_bpf(struct perf_ftrace *ftrace __maybe_unused, > buckets[idx] += hist[i]; > } > > + if (ftrace->stats && skel->bss->count) { > + stats->mean = skel->bss->total / skel->bss->count; > + stats->n = skel->bss->count; > + stats->max = skel->bss->max; > + stats->min = skel->bss->min; > + } > + > free(hist); > return 0; > } > diff --git a/tools/perf/util/bpf_skel/func_latency.bpf.c b/tools/perf/util/bpf_skel/func_latency.bpf.c > index 4df54e1b1411b10a..9b68eea8fd444699 100644 > --- a/tools/perf/util/bpf_skel/func_latency.bpf.c > +++ b/tools/perf/util/bpf_skel/func_latency.bpf.c > @@ -38,12 +38,19 @@ struct { > > int enabled = 0; > > +// stats > +__s64 total; > +__s64 count; > +__s64 max; > +__s64 min; > + > const volatile int has_cpu = 0; > const volatile int has_task = 0; > const volatile int use_nsec = 0; > const volatile unsigned int bucket_range; > const volatile unsigned int min_latency; > const volatile unsigned int max_latency; > +const volatile int stats = 0; > > SEC("kprobe/func") > int BPF_PROG(func_begin) > @@ -136,6 +143,18 @@ int BPF_PROG(func_end) > return 0; > > *hist += 1; > + > + if (stats) { > + delta /= cmp_base; > + > + __sync_fetch_and_add(&total, delta); > + __sync_fetch_and_add(&count, 1); > + > + if (delta > max) > + max = delta; > + if (delta < min) > + min = delta; > + } > } > > return 0; > diff --git a/tools/perf/util/ftrace.h b/tools/perf/util/ftrace.h > index f218703063f74786..76038ed712085fbc 100644 > --- a/tools/perf/util/ftrace.h > +++ b/tools/perf/util/ftrace.h > @@ -7,6 +7,7 @@ > > struct evlist; > struct hashamp; > +struct stats; > > struct perf_ftrace { > struct evlist *evlist; > @@ -23,6 +24,7 @@ struct perf_ftrace { > unsigned int bucket_range; > unsigned int min_latency; > unsigned int max_latency; > + bool stats; > int graph_depth; > int func_stack_trace; > int func_irq_info; > @@ -46,7 +48,7 @@ int perf_ftrace__latency_prepare_bpf(struct perf_ftrace *ftrace); > int perf_ftrace__latency_start_bpf(struct perf_ftrace *ftrace); > int perf_ftrace__latency_stop_bpf(struct perf_ftrace *ftrace); > int perf_ftrace__latency_read_bpf(struct perf_ftrace *ftrace, > - int buckets[]); > + int buckets[], struct stats *stats); Hi Namhyung, There's a stub below for !HAVE_BPF_SKEL that needs updating too. Also a minor point, but it seems quite low impact so it could be always on and then get rid of the --stats option. Other than that: Reviewed-by: James Clark > int perf_ftrace__latency_cleanup_bpf(struct perf_ftrace *ftrace); > > #else /* !HAVE_BPF_SKEL */