From nobody Sat Apr 11 21:13:58 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id E16ADC19F2D for ; Fri, 5 Aug 2022 01:37:09 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S240427AbiHEBf2 (ORCPT ); Thu, 4 Aug 2022 21:35:28 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:47956 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S239634AbiHEBfZ (ORCPT ); Thu, 4 Aug 2022 21:35:25 -0400 Received: from ams.source.kernel.org (ams.source.kernel.org [145.40.68.75]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 614E36431 for ; Thu, 4 Aug 2022 18:35:23 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ams.source.kernel.org (Postfix) with ESMTPS id EC355B82415 for ; Fri, 5 Aug 2022 01:35:21 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id CF3C2C433D6; Fri, 5 Aug 2022 01:35:19 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=kernel.org; s=k20201202; t=1659663320; bh=Ztli622f+ksDSgP2B6lolORJ2RzHynM5tQpo7fyEms0=; h=From:To:Cc:Subject:Date:In-Reply-To:References:From; b=QAolu1H3Xrt0cerZdqgkEe/weSoLPGja1qMss+vdO2bzVF8dUcES+XmFCCNHK5HQl uwGFpTDFco3b0Xlj34XI97NI7BY2eHCJGaSluq2co9dO2VfbShhpLTJz1liqMNtP+N u5yX9F2/GA876TBTh+raiE1nIt4rjcXrr0vt+dVZpQrLXyE8o1+Gf9kqEfjICo8vRA jQVxi+Pc3/xqpmSFI42bRRMW09BF9tpcxCHw4Ay/yF7Pgo7+4kH2dO0ko9lSteGtku n34DNH7bQRPWNDROg9BX4/UySRnRK4pdtrrQGtwjDsbRLWM/l44v8n+5i7vkx5nd7F LrdoZMGt2RhHw== From: "Masami Hiramatsu (Google)" To: Steven Rostedt Cc: Tom Zanussi , Ingo Molnar , linux-kernel@vger.kernel.org Subject: [PATCH v2 1/2] tracing: Add .percent suffix option to histogram values Date: Fri, 5 Aug 2022 10:35:17 +0900 Message-Id: <165966331728.3826604.8334449332454082730.stgit@devnote2> X-Mailer: git-send-email 2.25.1 In-Reply-To: <165966330764.3826604.9358384228095103695.stgit@devnote2> References: <165966330764.3826604.9358384228095103695.stgit@devnote2> User-Agent: StGit/0.19 MIME-Version: 1.0 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: quoted-printable Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org From: Masami Hiramatsu (Google) Add .percent suffix option to show the histogram values in percentage. This feature is useful when we need yo undersntand the overall trend for the histograms of large values. E.g. this shows the runtime percentage for each tasks. ------ # cd /sys/kernel/debug/tracing/ # echo hist:keys=3Dpid:vals=3Dhitcount,runtime.percent:sort=3Dpid > \ events/sched/sched_stat_runtime/trigger # sleep 10 # cat events/sched/sched_stat_runtime/hist # event histogram # # trigger info: hist:keys=3Dpid:vals=3Dhitcount,runtime.percent:sort=3Dpid= :size=3D2048 [active] # { pid: 14 } hitcount: 9 runtime: 2.48 { pid: 16 } hitcount: 38 runtime: 5.11 { pid: 59 } hitcount: 30 runtime: 10.30 { pid: 61 } hitcount: 73 runtime: 13.19 { pid: 64 } hitcount: 1 runtime: 0.22 { pid: 65 } hitcount: 13 runtime: 2.53 { pid: 67 } hitcount: 11 runtime: 2.35 { pid: 69 } hitcount: 8 runtime: 1.40 { pid: 77 } hitcount: 7 runtime: 1.83 { pid: 145 } hitcount: 41 runtime: 33.03 { pid: 152 } hitcount: 8 runtime: 11.90 { pid: 153 } hitcount: 6 runtime: 8.09 { pid: 154 } hitcount: 5 runtime: 7.50 Totals: Hits: 250 Entries: 13 Dropped: 0 ----- Signed-off-by: Masami Hiramatsu (Google) --- Changes in v2: - Use div64_*(). - Show an error when failing to calculate the percentage. --- kernel/trace/trace.c | 3 + kernel/trace/trace_events_hist.c | 79 ++++++++++++++++++++++++++++++++++= +--- 2 files changed, 74 insertions(+), 8 deletions(-) diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 7eb5bce62500..4f54f2494370 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -5700,7 +5700,8 @@ static const char readme_msg[] =3D "\t .syscall display a syscall id as a syscall name\n" "\t .log2 display log2 value rather than raw number\n" "\t .buckets=3Dsize display values in groups of size rather t= han raw number\n" - "\t .usecs display a common_timestamp in microseconds\n\n" + "\t .usecs display a common_timestamp in microseconds\n" + "\t .percent display a number of percentage value\n\n" "\t The 'pause' parameter can be used to pause an existing hist\n" "\t trigger or to start a hist trigger but not log any events\n" "\t until told to do so. 'continue' can be used to start or\n" diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_h= ist.c index fdf784620c28..c774d2ff02a8 100644 --- a/kernel/trace/trace_events_hist.c +++ b/kernel/trace/trace_events_hist.c @@ -477,6 +477,7 @@ enum hist_field_flags { HIST_FIELD_FL_ALIAS =3D 1 << 16, HIST_FIELD_FL_BUCKET =3D 1 << 17, HIST_FIELD_FL_CONST =3D 1 << 18, + HIST_FIELD_FL_PERCENT =3D 1 << 19, }; =20 struct var_defs { @@ -1682,6 +1683,8 @@ static const char *get_hist_field_flags(struct hist_f= ield *hist_field) flags_str =3D "buckets"; else if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP_USECS) flags_str =3D "usecs"; + else if (hist_field->flags & HIST_FIELD_FL_PERCENT) + flags_str =3D "percent"; =20 return flags_str; } @@ -2290,6 +2293,10 @@ parse_field(struct hist_trigger_data *hist_data, str= uct trace_event_file *file, if (ret || !(*buckets)) goto error; *flags |=3D HIST_FIELD_FL_BUCKET; + } else if (strncmp(modifier, "percent", 7) =3D=3D 0) { + if (*flags & (HIST_FIELD_FL_VAR | HIST_FIELD_FL_KEY)) + goto error; + *flags |=3D HIST_FIELD_FL_PERCENT; } else { error: hist_err(tr, HIST_ERR_BAD_FIELD_MODIFIER, errpos(modifier)); @@ -4254,8 +4261,13 @@ static int create_val_fields(struct hist_trigger_dat= a *hist_data, if (!field_str) break; =20 - if (strcmp(field_str, "hitcount") =3D=3D 0) + if (strncmp(field_str, "hitcount", 8) =3D=3D 0 && + (field_str[8] =3D=3D '.' || field_str[8] =3D=3D '\0')) { + if (strncmp(field_str + 8, ".percent", 8) =3D=3D 0) + hist_data->fields[HITCOUNT_IDX]->flags |=3D + HIST_FIELD_FL_PERCENT; continue; + } =20 ret =3D create_val_field(hist_data, j++, file, field_str); if (ret) @@ -5190,18 +5202,44 @@ static void hist_trigger_print_key(struct seq_file = *m, seq_puts(m, "}"); } =20 +/* Get the 100 times of the percentage of @val in @total */ +static inline unsigned int __get_percentage(u64 val, u64 total) +{ + if (!total) + return UINT_MAX; + + if (val < (U64_MAX / 10000)) + return (unsigned int)div64_ul(val * 10000, total); + + total =3D div64_u64(total, 10000); + if (!total) + return UINT_MAX; + + return (unsigned int)div64_ul(val, total); +} + static void hist_trigger_entry_print(struct seq_file *m, struct hist_trigger_data *hist_data, + u64 *totals, void *key, struct tracing_map_elt *elt) { const char *field_name; - unsigned int i; + unsigned int i, pc; + u64 val; =20 hist_trigger_print_key(m, hist_data, key, elt); =20 - seq_printf(m, " hitcount: %10llu", - tracing_map_read_sum(elt, HITCOUNT_IDX)); + i =3D HITCOUNT_IDX; + val =3D tracing_map_read_sum(elt, i); + if (hist_data->fields[i]->flags & HIST_FIELD_FL_PERCENT) { + pc =3D __get_percentage(val, totals[i]); + if (pc =3D=3D UINT_MAX) + seq_puts(m, " hitcount: [ERROR]"); + else + seq_printf(m, " hitcount: %7u.%02u", pc / 100, pc % 100); + } else + seq_printf(m, " hitcount: %10llu", val); =20 for (i =3D 1; i < hist_data->n_vals; i++) { field_name =3D hist_field_name(hist_data->fields[i], 0); @@ -5210,7 +5248,15 @@ static void hist_trigger_entry_print(struct seq_file= *m, hist_data->fields[i]->flags & HIST_FIELD_FL_EXPR) continue; =20 - if (hist_data->fields[i]->flags & HIST_FIELD_FL_HEX) { + if (hist_data->fields[i]->flags & HIST_FIELD_FL_PERCENT) { + val =3D tracing_map_read_sum(elt, i); + pc =3D __get_percentage(val, totals[i]); + if (pc =3D=3D UINT_MAX) + seq_printf(m, " %s: [ERROR]", field_name); + else + seq_printf(m, " %s: %7u.%02u", field_name, + pc / 100, pc % 100); + } else if (hist_data->fields[i]->flags & HIST_FIELD_FL_HEX) { seq_printf(m, " %s: %10llx", field_name, tracing_map_read_sum(elt, i)); } else { @@ -5229,7 +5275,8 @@ static int print_entries(struct seq_file *m, { struct tracing_map_sort_entry **sort_entries =3D NULL; struct tracing_map *map =3D hist_data->map; - int i, n_entries; + int i, j, n_entries; + u64 *totals =3D NULL; =20 n_entries =3D tracing_map_sort_entries(map, hist_data->sort_keys, hist_data->n_sort_keys, @@ -5237,11 +5284,29 @@ static int print_entries(struct seq_file *m, if (n_entries < 0) return n_entries; =20 + for (j =3D 0; j < hist_data->n_vals; j++) { + if (!(hist_data->fields[j]->flags & HIST_FIELD_FL_PERCENT)) + continue; + if (!totals) { + totals =3D kcalloc(hist_data->n_vals, sizeof(u64), + GFP_KERNEL); + if (!totals) { + n_entries =3D -ENOMEM; + goto out; + } + } + for (i =3D 0; i < n_entries; i++) + totals[j] +=3D tracing_map_read_sum( + sort_entries[i]->elt, j); + } + for (i =3D 0; i < n_entries; i++) - hist_trigger_entry_print(m, hist_data, + hist_trigger_entry_print(m, hist_data, totals, sort_entries[i]->key, sort_entries[i]->elt); =20 + kfree(totals); +out: tracing_map_destroy_sort_entries(sort_entries, n_entries); =20 return n_entries; From nobody Sat Apr 11 21:13:58 2026 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 0946DC3F6B0 for ; Fri, 5 Aug 2022 01:37:10 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S240420AbiHEBfg (ORCPT ); Thu, 4 Aug 2022 21:35:36 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:48146 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S240425AbiHEBfc (ORCPT ); Thu, 4 Aug 2022 21:35:32 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [139.178.84.217]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 586C76431 for ; Thu, 4 Aug 2022 18:35:31 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dfw.source.kernel.org (Postfix) with ESMTPS id DB65A6194D for ; Fri, 5 Aug 2022 01:35:30 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 05E75C433D6; Fri, 5 Aug 2022 01:35:28 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=kernel.org; s=k20201202; t=1659663330; bh=vfY2k+u4yIXPvcqWi/tdQyVM65pO/1c8tUVm53H+awM=; h=From:To:Cc:Subject:Date:In-Reply-To:References:From; b=ebq0bGrFq8GGmKrv2KZjjj3ZbidNQUvf3w2zqx/3KjMyz06yf7MGxTfmx2ELWdRX8 BugfLJTd6+FKp8a/6U+UNGN7y1X3TSA07nm3bsSzdzhhENPk2cvhp6C4CwROeVoqAv 8gBrGExW2NsvJ+z2QMpOh3VfWpqX9lS7OJaJMEAQS41JfV4PdBnNgYAXWaDyk06fnx FfOqM+L7XERg7BsbL2Q3j567o27dANMfNEMMRc/3oby8SaTi0ZJRhTvd23fnbxNLTh E7pyGl4CTYtLpx7KDBKxfBbDhuA2duRuz4KhMtqCqDgH3iRUDbMFpRoioqnMSusL23 gDtiQ8n2PbrXA== From: "Masami Hiramatsu (Google)" To: Steven Rostedt Cc: Tom Zanussi , Ingo Molnar , linux-kernel@vger.kernel.org Subject: [PATCH v2 2/2] tracing: Add .graph suffix option to histogram value Date: Fri, 5 Aug 2022 10:35:26 +0900 Message-Id: <165966332610.3826604.10632938036058057943.stgit@devnote2> X-Mailer: git-send-email 2.25.1 In-Reply-To: <165966330764.3826604.9358384228095103695.stgit@devnote2> References: <165966330764.3826604.9358384228095103695.stgit@devnote2> User-Agent: StGit/0.19 MIME-Version: 1.0 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: quoted-printable Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org From: Masami Hiramatsu (Google) Add the .graph suffix which shows the bar graph of the histogram value. For example, the below example shows that the bar graph of the histogram of the runtime for each tasks. ------ # cd /sys/kernel/debug/tracing/ # echo hist:keys=3Dpid:vals=3Druntime.graph:sort=3Dpid > \ events/sched/sched_stat_runtime/trigger # sleep 10 # cat events/sched/sched_stat_runtime/hist # event histogram # # trigger info: hist:keys=3Dpid:vals=3Dhitcount,runtime.graph:sort=3Dpid:s= ize=3D2048 [active] # { pid: 14 } hitcount: 2 runtime: { pid: 16 } hitcount: 8 runtime: { pid: 26 } hitcount: 1 runtime: { pid: 57 } hitcount: 3 runtime: { pid: 61 } hitcount: 20 runtime: ### { pid: 66 } hitcount: 2 runtime: { pid: 70 } hitcount: 3 runtime: { pid: 72 } hitcount: 2 runtime: { pid: 145 } hitcount: 14 runtime: #################### { pid: 152 } hitcount: 5 runtime: ####### { pid: 153 } hitcount: 2 runtime: #### Totals: Hits: 62 Entries: 11 Dropped: 0 ------- Signed-off-by: Masami Hiramatsu (Google) --- Changes in v2: - Show an error when failing to calculate the percentage. --- kernel/trace/trace_events_hist.c | 78 +++++++++++++++++++++++++++++++---= ---- 1 file changed, 64 insertions(+), 14 deletions(-) diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_h= ist.c index c774d2ff02a8..3d609f457e8c 100644 --- a/kernel/trace/trace_events_hist.c +++ b/kernel/trace/trace_events_hist.c @@ -478,6 +478,7 @@ enum hist_field_flags { HIST_FIELD_FL_BUCKET =3D 1 << 17, HIST_FIELD_FL_CONST =3D 1 << 18, HIST_FIELD_FL_PERCENT =3D 1 << 19, + HIST_FIELD_FL_GRAPH =3D 1 << 20, }; =20 struct var_defs { @@ -1685,6 +1686,8 @@ static const char *get_hist_field_flags(struct hist_f= ield *hist_field) flags_str =3D "usecs"; else if (hist_field->flags & HIST_FIELD_FL_PERCENT) flags_str =3D "percent"; + else if (hist_field->flags & HIST_FIELD_FL_GRAPH) + flags_str =3D "graph"; =20 return flags_str; } @@ -2297,6 +2300,10 @@ parse_field(struct hist_trigger_data *hist_data, str= uct trace_event_file *file, if (*flags & (HIST_FIELD_FL_VAR | HIST_FIELD_FL_KEY)) goto error; *flags |=3D HIST_FIELD_FL_PERCENT; + } else if (strncmp(modifier, "graph", 5) =3D=3D 0) { + if (*flags & (HIST_FIELD_FL_VAR | HIST_FIELD_FL_KEY)) + goto error; + *flags |=3D HIST_FIELD_FL_GRAPH; } else { error: hist_err(tr, HIST_ERR_BAD_FIELD_MODIFIER, errpos(modifier)); @@ -4266,6 +4273,9 @@ static int create_val_fields(struct hist_trigger_data= *hist_data, if (strncmp(field_str + 8, ".percent", 8) =3D=3D 0) hist_data->fields[HITCOUNT_IDX]->flags |=3D HIST_FIELD_FL_PERCENT; + if (strncmp(field_str + 8, ".graph", 8) =3D=3D 0) + hist_data->fields[HITCOUNT_IDX]->flags |=3D + HIST_FIELD_FL_GRAPH; continue; } =20 @@ -5218,14 +5228,37 @@ static inline unsigned int __get_percentage(u64 val= , u64 total) return (unsigned int)div64_ul(val, total); } =20 +#define BAR_CHAR '#' + +static inline const char *__fill_bar_str(char *buf, int size, u64 val, u64= max) +{ + unsigned int len =3D __get_percentage(val, max); + int i; + + if (len =3D=3D UINT_MAX) { + snprintf(buf, size, "[ERROR]"); + return buf; + } + + len =3D len * size / 10000; + for (i =3D 0; i < len && i < size; i++) + buf[i] =3D BAR_CHAR; + while (i < size) + buf[i++] =3D ' '; + buf[size] =3D '\0'; + + return buf; +} + static void hist_trigger_entry_print(struct seq_file *m, struct hist_trigger_data *hist_data, - u64 *totals, + u64 *maxs, void *key, struct tracing_map_elt *elt) { const char *field_name; unsigned int i, pc; + char bar[21]; u64 val; =20 hist_trigger_print_key(m, hist_data, key, elt); @@ -5233,11 +5266,14 @@ static void hist_trigger_entry_print(struct seq_fil= e *m, i =3D HITCOUNT_IDX; val =3D tracing_map_read_sum(elt, i); if (hist_data->fields[i]->flags & HIST_FIELD_FL_PERCENT) { - pc =3D __get_percentage(val, totals[i]); + pc =3D __get_percentage(val, maxs[i]); if (pc =3D=3D UINT_MAX) seq_puts(m, " hitcount: [ERROR]"); else seq_printf(m, " hitcount: %7u.%02u", pc / 100, pc % 100); + } else if (hist_data->fields[i]->flags & HIST_FIELD_FL_GRAPH) { + seq_printf(m, " hitcount: %20s", + __fill_bar_str(bar, 20, val, maxs[i])); } else seq_printf(m, " hitcount: %10llu", val); =20 @@ -5250,12 +5286,16 @@ static void hist_trigger_entry_print(struct seq_fil= e *m, =20 if (hist_data->fields[i]->flags & HIST_FIELD_FL_PERCENT) { val =3D tracing_map_read_sum(elt, i); - pc =3D __get_percentage(val, totals[i]); + pc =3D __get_percentage(val, maxs[i]); if (pc =3D=3D UINT_MAX) seq_printf(m, " %s: [ERROR]", field_name); else seq_printf(m, " %s: %7u.%02u", field_name, pc / 100, pc % 100); + } else if (hist_data->fields[i]->flags & HIST_FIELD_FL_GRAPH) { + val =3D tracing_map_read_sum(elt, i); + seq_printf(m, " %s: %20s", field_name, + __fill_bar_str(bar, 20, val, maxs[i])); } else if (hist_data->fields[i]->flags & HIST_FIELD_FL_HEX) { seq_printf(m, " %s: %10llx", field_name, tracing_map_read_sum(elt, i)); @@ -5276,7 +5316,8 @@ static int print_entries(struct seq_file *m, struct tracing_map_sort_entry **sort_entries =3D NULL; struct tracing_map *map =3D hist_data->map; int i, j, n_entries; - u64 *totals =3D NULL; + u64 *maxs =3D NULL; + u64 val; =20 n_entries =3D tracing_map_sort_entries(map, hist_data->sort_keys, hist_data->n_sort_keys, @@ -5285,27 +5326,36 @@ static int print_entries(struct seq_file *m, return n_entries; =20 for (j =3D 0; j < hist_data->n_vals; j++) { - if (!(hist_data->fields[j]->flags & HIST_FIELD_FL_PERCENT)) + if (!(hist_data->fields[j]->flags & + (HIST_FIELD_FL_PERCENT | HIST_FIELD_FL_GRAPH))) continue; - if (!totals) { - totals =3D kcalloc(hist_data->n_vals, sizeof(u64), - GFP_KERNEL); - if (!totals) { + if (!maxs) { + maxs =3D kcalloc(hist_data->n_vals, sizeof(u64), + GFP_KERNEL); + if (!maxs) { n_entries =3D -ENOMEM; goto out; } } - for (i =3D 0; i < n_entries; i++) - totals[j] +=3D tracing_map_read_sum( - sort_entries[i]->elt, j); + /* + * If the n-th field shows percentage, the maxs[n] has the + * total, or it has the maximum number. + */ + for (i =3D 0; i < n_entries; i++) { + val =3D tracing_map_read_sum(sort_entries[i]->elt, j); + if (hist_data->fields[j]->flags & HIST_FIELD_FL_PERCENT) + maxs[j] +=3D val; + else if (maxs[j] < val) + maxs[j] =3D val; + } } =20 for (i =3D 0; i < n_entries; i++) - hist_trigger_entry_print(m, hist_data, totals, + hist_trigger_entry_print(m, hist_data, maxs, sort_entries[i]->key, sort_entries[i]->elt); =20 - kfree(totals); + kfree(maxs); out: tracing_map_destroy_sort_entries(sort_entries, n_entries);