* [PATCH v3 2/3] tracing: Add .percent suffix option to histogram values
2022-08-23 2:58 [PATCH v3 0/3] tracing/hist: Add percentage histogram suffixes Masami Hiramatsu (Google)
2022-08-23 2:59 ` [PATCH v3 1/3] tracing: Fix to check event_mutex is held while accessing trigger list Masami Hiramatsu (Google)
@ 2022-08-23 2:59 ` Masami Hiramatsu (Google)
2022-08-23 2:59 ` [PATCH v3 3/3] tracing: Add .graph suffix option to histogram value Masami Hiramatsu (Google)
2 siblings, 0 replies; 4+ messages in thread
From: Masami Hiramatsu (Google) @ 2022-08-23 2:59 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Tom Zanussi, Ingo Molnar, linux-kernel
From: Masami Hiramatsu (Google) <mhiramat@kernel.org>
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: 8 } hitcount: 7 runtime (%): 4.14
{ pid: 14 } hitcount: 5 runtime (%): 3.69
{ pid: 16 } hitcount: 11 runtime (%): 3.41
{ pid: 61 } hitcount: 41 runtime (%): 19.75
{ pid: 65 } hitcount: 4 runtime (%): 1.48
{ pid: 70 } hitcount: 6 runtime (%): 3.60
{ pid: 72 } hitcount: 2 runtime (%): 1.10
{ pid: 144 } hitcount: 10 runtime (%): 32.01
{ pid: 151 } hitcount: 8 runtime (%): 22.66
{ pid: 152 } hitcount: 2 runtime (%): 8.10
Totals:
Hits: 96
Entries: 10
Dropped: 0
-----
Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
---
Changes in v3:
- Show "(%)" in the field name.
- Return div0 error only if the value is not zero.
- Simplify the print code with hist_trigger_print_val().
- Show hitcount percentage correctly.
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 | 107 ++++++++++++++++++++++++++++++++------
2 files changed, 92 insertions(+), 18 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 27febd4ee33e..174c91ae957e 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 fdf784620c28..d285a2d55f88 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 = 1 << 16,
HIST_FIELD_FL_BUCKET = 1 << 17,
HIST_FIELD_FL_CONST = 1 << 18,
+ HIST_FIELD_FL_PERCENT = 1 << 19,
};
struct var_defs {
@@ -1682,6 +1683,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;
}
@@ -2290,6 +2293,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));
@@ -4254,8 +4261,13 @@ static int create_val_fields(struct hist_trigger_data *hist_data,
if (!field_str)
break;
- if (strcmp(field_str, "hitcount") == 0)
+ if (strncmp(field_str, "hitcount", 8) == 0 &&
+ (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);
if (ret)
@@ -5190,33 +5202,73 @@ 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)
+ goto div0;
+
+ if (val < (U64_MAX / 10000))
+ return (unsigned int)div64_ul(val * 10000, total);
+
+ total = div64_u64(total, 10000);
+ if (!total)
+ goto div0;
+
+ return (unsigned int)div64_ul(val, total);
+div0:
+ return val ? UINT_MAX : 0;
+}
+
+static void hist_trigger_print_val(struct seq_file *m, unsigned int idx,
+ const char *field_name, unsigned long flags,
+ u64 *totals, struct tracing_map_elt *elt)
+{
+ u64 val = tracing_map_read_sum(elt, idx);
+ unsigned int pc;
+
+ if (flags & HIST_FIELD_FL_PERCENT) {
+ pc = __get_percentage(val, totals[idx]);
+ if (pc == UINT_MAX)
+ seq_printf(m, " %s (%%):[ERROR]", field_name);
+ else
+ seq_printf(m, " %s (%%): %3u.%02u", field_name,
+ pc / 100, pc % 100);
+ } else if (flags & HIST_FIELD_FL_HEX) {
+ seq_printf(m, " %s: %10llx", field_name, val);
+ } else {
+ seq_printf(m, " %s: %10llu", field_name, val);
+ }
+}
+
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 = HITCOUNT_IDX;
+ unsigned long flags;
hist_trigger_print_key(m, hist_data, key, elt);
- seq_printf(m, " hitcount: %10llu",
- tracing_map_read_sum(elt, HITCOUNT_IDX));
+ hist_trigger_print_val(m, i, "hitcount", 0, totals, elt);
+
+ flags = hist_data->fields[i]->flags;
+ if (flags & HIST_FIELD_FL_PERCENT)
+ hist_trigger_print_val(m, i, " hitcount",
+ HIST_FIELD_FL_PERCENT, totals, elt);
for (i = 1; i < hist_data->n_vals; i++) {
field_name = hist_field_name(hist_data->fields[i], 0);
+ flags = hist_data->fields[i]->flags;
- if (hist_data->fields[i]->flags & HIST_FIELD_FL_VAR ||
- hist_data->fields[i]->flags & HIST_FIELD_FL_EXPR)
+ if (flags & HIST_FIELD_FL_VAR || flags & HIST_FIELD_FL_EXPR)
continue;
- if (hist_data->fields[i]->flags & HIST_FIELD_FL_HEX) {
- seq_printf(m, " %s: %10llx", field_name,
- tracing_map_read_sum(elt, i));
- } else {
- seq_printf(m, " %s: %10llu", field_name,
- tracing_map_read_sum(elt, i));
- }
+ seq_puts(m, " ");
+ hist_trigger_print_val(m, i, field_name, flags, totals, elt);
}
print_actions(m, hist_data, elt);
@@ -5229,7 +5281,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,
@@ -5237,11 +5290,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;
@@ -5661,9 +5732,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, ",hitcount.percent");
+ } else {
seq_puts(m, ",");
hist_field_print(m, field);
}
^ permalink raw reply related [flat|nested] 4+ messages in thread* [PATCH v3 3/3] tracing: Add .graph suffix option to histogram value
2022-08-23 2:58 [PATCH v3 0/3] tracing/hist: Add percentage histogram suffixes Masami Hiramatsu (Google)
2022-08-23 2:59 ` [PATCH v3 1/3] tracing: Fix to check event_mutex is held while accessing trigger list Masami Hiramatsu (Google)
2022-08-23 2:59 ` [PATCH v3 2/3] tracing: Add .percent suffix option to histogram values Masami Hiramatsu (Google)
@ 2022-08-23 2:59 ` Masami Hiramatsu (Google)
2 siblings, 0 replies; 4+ messages in thread
From: Masami Hiramatsu (Google) @ 2022-08-23 2:59 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Tom Zanussi, Ingo Molnar, linux-kernel
From: Masami Hiramatsu (Google) <mhiramat@kernel.org>
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=pid:vals=runtime.graph: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.graph:sort=pid:size=2048 [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) <mhiramat@kernel.org>
---
Changes in v3:
- Show hitcount.graph in trigger info correctly.
- Show both hitcount.percent and hitcount.graph on the same histogram.
Changes in v2:
- Show an error when failing to calculate the percentage.
---
kernel/trace/trace_events_hist.c | 87 +++++++++++++++++++++++++++++++-------
1 file changed, 70 insertions(+), 17 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index d285a2d55f88..e3d2a623e6bd 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 = 1 << 17,
HIST_FIELD_FL_CONST = 1 << 18,
HIST_FIELD_FL_PERCENT = 1 << 19,
+ HIST_FIELD_FL_GRAPH = 1 << 20,
};
struct var_defs {
@@ -1685,6 +1686,8 @@ static const char *get_hist_field_flags(struct hist_field *hist_field)
flags_str = "usecs";
else if (hist_field->flags & HIST_FIELD_FL_PERCENT)
flags_str = "percent";
+ else if (hist_field->flags & HIST_FIELD_FL_GRAPH)
+ flags_str = "graph";
return flags_str;
}
@@ -2297,6 +2300,10 @@ parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file,
if (*flags & (HIST_FIELD_FL_VAR | HIST_FIELD_FL_KEY))
goto error;
*flags |= HIST_FIELD_FL_PERCENT;
+ } else if (strncmp(modifier, "graph", 5) == 0) {
+ if (*flags & (HIST_FIELD_FL_VAR | HIST_FIELD_FL_KEY))
+ goto error;
+ *flags |= 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) == 0)
hist_data->fields[HITCOUNT_IDX]->flags |=
HIST_FIELD_FL_PERCENT;
+ if (strncmp(field_str + 8, ".graph", 8) == 0)
+ hist_data->fields[HITCOUNT_IDX]->flags |=
+ HIST_FIELD_FL_GRAPH;
continue;
}
@@ -5220,20 +5230,52 @@ static inline unsigned int __get_percentage(u64 val, u64 total)
return val ? UINT_MAX : 0;
}
+#define BAR_CHAR '#'
+
+static inline const char *__fill_bar_str(char *buf, int size, u64 val, u64 max)
+{
+ unsigned int len = __get_percentage(val, max);
+ int i;
+
+ if (len == UINT_MAX) {
+ snprintf(buf, size, "[ERROR]");
+ return buf;
+ }
+
+ len = len * size / 10000;
+ for (i = 0; i < len && i < size; i++)
+ buf[i] = BAR_CHAR;
+ while (i < size)
+ buf[i++] = ' ';
+ buf[size] = '\0';
+
+ return buf;
+}
+
+struct hist_val_stat {
+ u64 max;
+ u64 total;
+};
+
static void hist_trigger_print_val(struct seq_file *m, unsigned int idx,
const char *field_name, unsigned long flags,
- u64 *totals, struct tracing_map_elt *elt)
+ struct hist_val_stat *stats,
+ struct tracing_map_elt *elt)
{
u64 val = tracing_map_read_sum(elt, idx);
unsigned int pc;
+ char bar[21];
if (flags & HIST_FIELD_FL_PERCENT) {
- pc = __get_percentage(val, totals[idx]);
+ pc = __get_percentage(val, stats[idx].total);
if (pc == UINT_MAX)
seq_printf(m, " %s (%%):[ERROR]", field_name);
else
seq_printf(m, " %s (%%): %3u.%02u", field_name,
pc / 100, pc % 100);
+ } else if (flags & HIST_FIELD_FL_GRAPH) {
+ seq_printf(m, " %s: %20s", field_name,
+ __fill_bar_str(bar, 20, val, stats[idx].max));
} else if (flags & HIST_FIELD_FL_HEX) {
seq_printf(m, " %s: %10llx", field_name, val);
} else {
@@ -5243,7 +5285,7 @@ static void hist_trigger_print_val(struct seq_file *m, unsigned int idx,
static void hist_trigger_entry_print(struct seq_file *m,
struct hist_trigger_data *hist_data,
- u64 *totals,
+ struct hist_val_stat *stats,
void *key,
struct tracing_map_elt *elt)
{
@@ -5253,12 +5295,15 @@ static void hist_trigger_entry_print(struct seq_file *m,
hist_trigger_print_key(m, hist_data, key, elt);
- hist_trigger_print_val(m, i, "hitcount", 0, totals, elt);
+ hist_trigger_print_val(m, i, "hitcount", 0, stats, elt);
flags = hist_data->fields[i]->flags;
if (flags & HIST_FIELD_FL_PERCENT)
hist_trigger_print_val(m, i, " hitcount",
- HIST_FIELD_FL_PERCENT, totals, elt);
+ HIST_FIELD_FL_PERCENT, stats, elt);
+ if (flags & HIST_FIELD_FL_GRAPH)
+ hist_trigger_print_val(m, i, " hitcount",
+ HIST_FIELD_FL_GRAPH, stats, elt);
for (i = 1; i < hist_data->n_vals; i++) {
field_name = hist_field_name(hist_data->fields[i], 0);
@@ -5268,7 +5313,7 @@ static void hist_trigger_entry_print(struct seq_file *m,
continue;
seq_puts(m, " ");
- hist_trigger_print_val(m, i, field_name, flags, totals, elt);
+ hist_trigger_print_val(m, i, field_name, flags, stats, elt);
}
print_actions(m, hist_data, elt);
@@ -5282,7 +5327,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, j, n_entries;
- u64 *totals = NULL;
+ struct hist_val_stat *stats = NULL;
+ u64 val;
n_entries = tracing_map_sort_entries(map, hist_data->sort_keys,
hist_data->n_sort_keys,
@@ -5290,28 +5336,33 @@ static int print_entries(struct seq_file *m,
if (n_entries < 0)
return n_entries;
+ /* Calculate the max and the total for each field if needed. */
for (j = 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 = kcalloc(hist_data->n_vals, sizeof(u64),
- GFP_KERNEL);
- if (!totals) {
+ if (!stats) {
+ stats = kcalloc(hist_data->n_vals, sizeof(*stats),
+ GFP_KERNEL);
+ if (!stats) {
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++) {
+ val = tracing_map_read_sum(sort_entries[i]->elt, j);
+ stats[j].total += val;
+ if (stats[j].max < val)
+ stats[j].max = val;
+ }
}
for (i = 0; i < n_entries; i++)
- hist_trigger_entry_print(m, hist_data, totals,
+ hist_trigger_entry_print(m, hist_data, stats,
sort_entries[i]->key,
sort_entries[i]->elt);
- kfree(totals);
+ kfree(stats);
out:
tracing_map_destroy_sort_entries(sort_entries, n_entries);
@@ -5736,6 +5787,8 @@ static int event_hist_trigger_print(struct seq_file *m,
seq_puts(m, "hitcount");
if (field->flags & HIST_FIELD_FL_PERCENT)
seq_puts(m, ",hitcount.percent");
+ if (field->flags & HIST_FIELD_FL_GRAPH)
+ seq_puts(m, ",hitcount.graph");
} else {
seq_puts(m, ",");
hist_field_print(m, field);
^ permalink raw reply related [flat|nested] 4+ messages in thread