From mboxrd@z Thu Jan 1 00:00:00 1970 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 B7A22ECAAA3 for ; Thu, 25 Aug 2022 22:19:22 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229703AbiHYWTV (ORCPT ); Thu, 25 Aug 2022 18:19:21 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:53066 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S244022AbiHYWTO (ORCPT ); Thu, 25 Aug 2022 18:19:14 -0400 Received: from dfw.source.kernel.org (dfw.source.kernel.org [139.178.84.217]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id D7885C578C for ; Thu, 25 Aug 2022 15:19:11 -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 39FBE61CB1 for ; Thu, 25 Aug 2022 22:19:11 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 34B85C433D6; Thu, 25 Aug 2022 22:19:10 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=kernel.org; s=k20201202; t=1661465950; bh=aKYs7w547Jp8vvSfTubH2wMG01toDMrP0GtXygE3TUw=; h=From:To:Cc:Subject:Date:In-Reply-To:References:From; b=umy9ZThtECMWAt/Of35Luc6oskgqRtxeH408Jw73Mm/TO/kcA9gbQbzGb6AVoPaS2 s2dIx2t9/4NMfRcHlFdXqJDsoivXY+dY/A3pBr+ESwxsgdadZExkRuUCKomALLAuN9 +JG53KbkehGZnNJqWyOAP++c01dyDB+l9cqqMq5LkjMOqBujGKG6oCKpXcs9bNeS5W 2pS4G726L/39banxDUUNI5MkVnT7o9HvRYMLp74W6yAUAgNBaRb6Sb+ICrHqel8qQ4 3Y/DgBrMMWmNmbM8/7krSftMsaNUVPeLK7jJdXpkVrLg1oW7AC4WpK1H9KkEpwNJOl AJeZD4JqXJZAA== From: Tom Zanussi To: rostedt@goodmis.org Cc: mhiramat@kernel.org, linux-kernel@vger.kernel.org Subject: [PATCH 2/3] tracing: Add .percent suffix option to histogram values Date: Thu, 25 Aug 2022 17:19:02 -0500 Message-Id: <35c7c2503c318782dd74a93d5a942985dedcbbd1.1661464992.git.zanussi@kernel.org> X-Mailer: git-send-email 2.34.1 In-Reply-To: References: MIME-Version: 1.0 Content-Transfer-Encoding: 8bit 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=pid:vals=hitcount,runtime.percent:sort=pid > \ events/sched/sched_stat_runtime/trigger # sleep 10 # cat events/sched/sched_stat_runtime/hist # event histogram # # trigger info: hist:keys=pid:vals=hitcount,runtime.percent:sort=pid:size=2048 [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) Conflicts: kernel/trace/trace_events_hist.c --- kernel/trace/trace.c | 3 +- kernel/trace/trace_events_hist.c | 88 ++++++++++++++++++++++++++++---- 2 files changed, 79 insertions(+), 12 deletions(-) diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index d3005279165d..5e5efc550ac4 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -5700,7 +5700,8 @@ static const char readme_msg[] = "\t .syscall display a syscall id as a syscall name\n" "\t .log2 display log2 value rather than raw number\n" "\t .buckets=size display values in groups of size rather than 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_hist.c index 8f858e0bdaf3..8e8942e62900 100644 --- a/kernel/trace/trace_events_hist.c +++ b/kernel/trace/trace_events_hist.c @@ -506,6 +506,7 @@ enum hist_field_flags { HIST_FIELD_FL_ALIAS = 1 << 16, HIST_FIELD_FL_BUCKET = 1 << 17, HIST_FIELD_FL_CONST = 1 << 18, + HIST_FIELD_FL_PERCENT = 1 << 19, }; struct var_defs { @@ -1707,6 +1708,8 @@ static const char *get_hist_field_flags(struct hist_field *hist_field) flags_str = "buckets"; else if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP_USECS) flags_str = "usecs"; + else if (hist_field->flags & HIST_FIELD_FL_PERCENT) + flags_str = "percent"; return flags_str; } @@ -2315,6 +2318,10 @@ parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file, if (ret || !(*buckets)) goto error; *flags |= HIST_FIELD_FL_BUCKET; + } else if (strncmp(modifier, "percent", 7) == 0) { + if (*flags & (HIST_FIELD_FL_VAR | HIST_FIELD_FL_KEY)) + goto error; + *flags |= HIST_FIELD_FL_PERCENT; } else { error: hist_err(tr, HIST_ERR_BAD_FIELD_MODIFIER, errpos(modifier)); @@ -4350,9 +4357,13 @@ static int create_val_fields(struct hist_trigger_data *hist_data, if (!field_str) break; - if (strcmp(field_str, "hitcount") == 0) { - if (!n_hitcount++) - continue; + if (!n_hitcount++ && strncmp(field_str, "hitcount", 8) == 0) { + if (field_str[8] == '.' || field_str[8] == '\0') { + if (strncmp(field_str + 8, ".percent", 8) == 0) + hist_data->fields[HITCOUNT_IDX]->flags |= + HIST_FIELD_FL_PERCENT; + } + continue; } ret = create_val_field(hist_data, j++, file, field_str); @@ -5288,18 +5299,44 @@ static void hist_trigger_print_key(struct seq_file *m, seq_puts(m, "}"); } +/* 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 = 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; hist_trigger_print_key(m, hist_data, key, elt); - seq_printf(m, " hitcount: %10llu", - tracing_map_read_sum(elt, HITCOUNT_IDX)); + i = HITCOUNT_IDX; + val = tracing_map_read_sum(elt, i); + if (hist_data->fields[i]->flags & HIST_FIELD_FL_PERCENT) { + pc = __get_percentage(val, totals[i]); + if (pc == 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); for (i = 1; i < hist_data->n_vals; i++) { field_name = hist_field_name(hist_data->fields[i], 0); @@ -5308,7 +5345,15 @@ static void hist_trigger_entry_print(struct seq_file *m, hist_data->fields[i]->flags & HIST_FIELD_FL_EXPR) continue; - if (hist_data->fields[i]->flags & HIST_FIELD_FL_HEX) { + if (hist_data->fields[i]->flags & HIST_FIELD_FL_PERCENT) { + val = tracing_map_read_sum(elt, i); + pc = __get_percentage(val, totals[i]); + if (pc == 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 { @@ -5327,7 +5372,8 @@ static int print_entries(struct seq_file *m, { struct tracing_map_sort_entry **sort_entries = NULL; struct tracing_map *map = hist_data->map; - int i, n_entries; + int i, j, n_entries; + u64 *totals = NULL; n_entries = tracing_map_sort_entries(map, hist_data->sort_keys, hist_data->n_sort_keys, @@ -5335,11 +5381,29 @@ static int print_entries(struct seq_file *m, if (n_entries < 0) return n_entries; + for (j = 0; j < hist_data->n_vals; j++) { + if (!(hist_data->fields[j]->flags & HIST_FIELD_FL_PERCENT)) + continue; + if (!totals) { + totals = kcalloc(hist_data->n_vals, sizeof(u64), + GFP_KERNEL); + if (!totals) { + n_entries = -ENOMEM; + goto out; + } + } + for (i = 0; i < n_entries; i++) + totals[j] += tracing_map_read_sum( + sort_entries[i]->elt, j); + } + for (i = 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); + kfree(totals); +out: tracing_map_destroy_sort_entries(sort_entries, n_entries); return n_entries; @@ -5759,9 +5823,11 @@ static int event_hist_trigger_print(struct seq_file *m, continue; } - if (i == HITCOUNT_IDX) + if (i == HITCOUNT_IDX) { seq_puts(m, "hitcount"); - else { + if (field->flags & HIST_FIELD_FL_PERCENT) + seq_puts(m, ".percent"); + } else { seq_puts(m, ","); hist_field_print(m, field); } -- 2.34.1