Hi Masami,
The first patch here adds support for multiple hitcount fields.
The second and third fix up your v2 [1] patches on top of the first
just so I could test them.
It works fine for me. Let me know if you want me to update the v3
version instead of this one and I can do that instead.
Thanks,
Tom
[1] https://lore.kernel.org/lkml/165966330764.3826604.9358384228095103695.stgit@devnote2/
The following changes since commit 09c9cdd023f26244463b1276b251a91e72915178:
tracing/filter: Call filter predicate functions directly via a switch statement (2022-08-23 17:41:13 -0400)
are available in the Git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/masami-hitcount-v0
Masami Hiramatsu (Google) (2):
tracing: Add .percent suffix option to histogram values
tracing: Add .graph suffix option to histogram value
Tom Zanussi (1):
tracing: Allow multiple hitcount values in histograms
kernel/trace/trace.c | 3 +-
kernel/trace/trace_events_hist.c | 144 ++++++++++++++++++++++++++++---
2 files changed, 136 insertions(+), 11 deletions(-)
--
2.34.1
From: "Masami Hiramatsu (Google)" <[email protected]>
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) <[email protected]>
Conflicts:
kernel/trace/trace_events_hist.c
---
kernel/trace/trace_events_hist.c | 80 ++++++++++++++++++++++++++------
1 file changed, 66 insertions(+), 14 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 8e8942e62900..f31f1adab9fa 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -507,6 +507,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 {
@@ -1710,6 +1711,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;
}
@@ -2322,6 +2325,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));
@@ -4362,6 +4369,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;
}
@@ -5315,14 +5325,37 @@ static inline unsigned int __get_percentage(u64 val, u64 total)
return (unsigned int)div64_ul(val, total);
}
+#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;
+}
+
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;
hist_trigger_print_key(m, hist_data, key, elt);
@@ -5330,11 +5363,14 @@ static void hist_trigger_entry_print(struct seq_file *m,
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]);
+ pc = __get_percentage(val, maxs[i]);
if (pc == 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);
@@ -5347,12 +5383,16 @@ static void hist_trigger_entry_print(struct seq_file *m,
if (hist_data->fields[i]->flags & HIST_FIELD_FL_PERCENT) {
val = tracing_map_read_sum(elt, i);
- pc = __get_percentage(val, totals[i]);
+ pc = __get_percentage(val, maxs[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_GRAPH) {
+ val = 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));
@@ -5373,7 +5413,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;
+ u64 *maxs = NULL;
+ u64 val;
n_entries = tracing_map_sort_entries(map, hist_data->sort_keys,
hist_data->n_sort_keys,
@@ -5382,27 +5423,36 @@ static int print_entries(struct seq_file *m,
return n_entries;
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 (!maxs) {
+ maxs = kcalloc(hist_data->n_vals, sizeof(u64),
+ GFP_KERNEL);
+ if (!maxs) {
n_entries = -ENOMEM;
goto out;
}
}
- for (i = 0; i < n_entries; i++)
- totals[j] += 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 = 0; i < n_entries; i++) {
+ val = tracing_map_read_sum(sort_entries[i]->elt, j);
+ if (hist_data->fields[j]->flags & HIST_FIELD_FL_PERCENT)
+ maxs[j] += val;
+ else if (maxs[j] < val)
+ maxs[j] = val;
+ }
}
for (i = 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);
- kfree(totals);
+ kfree(maxs);
out:
tracing_map_destroy_sort_entries(sort_entries, n_entries);
@@ -5827,6 +5877,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, ".percent");
+ if (field->flags & HIST_FIELD_FL_GRAPH)
+ seq_puts(m, ".graph");
} else {
seq_puts(m, ",");
hist_field_print(m, field);
--
2.34.1
The hitcount is treated specially in the histograms - since it's
always expected to be there regardless of whether the user specified
anything or not, it's always added as the first histogram value.
Currently the code doesn't allow it to be added more than once as a
value, which is inconsistent with all the other possible values. It
would seem to be a pointless thing to want to do, but other features
being added such as percent and graph modifiers don't work properly
with the current hitcount restrictions.
Fix this by allowing multiple hitcounts to be added.
Signed -off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace_events_hist.c | 12 +++++++++---
1 file changed, 9 insertions(+), 3 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 92fbd72b6408..8f858e0bdaf3 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -1356,6 +1356,8 @@ static const char *hist_field_name(struct hist_field *field,
field_name = field->name;
} else if (field->flags & HIST_FIELD_FL_TIMESTAMP)
field_name = "common_timestamp";
+ else if (field->flags & HIST_FIELD_FL_HITCOUNT)
+ field_name = "hitcount";
if (field_name == NULL)
field_name = "";
@@ -2328,6 +2330,8 @@ parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file,
hist_data->attrs->ts_in_usecs = true;
} else if (strcmp(field_name, "common_cpu") == 0)
*flags |= HIST_FIELD_FL_CPU;
+ else if (strcmp(field_name, "hitcount") == 0)
+ *flags |= HIST_FIELD_FL_HITCOUNT;
else {
field = trace_find_event_field(file->event_call, field_name);
if (!field || !field->size) {
@@ -4328,8 +4332,8 @@ static int create_var_field(struct hist_trigger_data *hist_data,
static int create_val_fields(struct hist_trigger_data *hist_data,
struct trace_event_file *file)
{
+ unsigned int i, j = 1, n_hitcount;
char *fields_str, *field_str;
- unsigned int i, j = 1;
int ret;
ret = create_hitcount_val(hist_data);
@@ -4346,8 +4350,10 @@ static int create_val_fields(struct hist_trigger_data *hist_data,
if (!field_str)
break;
- if (strcmp(field_str, "hitcount") == 0)
- continue;
+ if (strcmp(field_str, "hitcount") == 0) {
+ if (!n_hitcount++)
+ continue;
+ }
ret = create_val_field(hist_data, j++, file, field_str);
if (ret)
--
2.34.1
From: "Masami Hiramatsu (Google)" <[email protected]>
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) <[email protected]>
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
Hi Tom,
On Thu, 25 Aug 2022 17:19:00 -0500
Tom Zanussi <[email protected]> wrote:
> Hi Masami,
>
> The first patch here adds support for multiple hitcount fields.
>
> The second and third fix up your v2 [1] patches on top of the first
> just so I could test them.
>
> It works fine for me. Let me know if you want me to update the v3
> version instead of this one and I can do that instead.
Thanks! I'll check it and rebase my v3 patches on it.
>
> Thanks,
>
> Tom
>
> [1] https://lore.kernel.org/lkml/165966330764.3826604.9358384228095103695.stgit@devnote2/
>
>
> The following changes since commit 09c9cdd023f26244463b1276b251a91e72915178:
>
> tracing/filter: Call filter predicate functions directly via a switch statement (2022-08-23 17:41:13 -0400)
>
> are available in the Git repository at:
>
> git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/masami-hitcount-v0
>
> Masami Hiramatsu (Google) (2):
> tracing: Add .percent suffix option to histogram values
> tracing: Add .graph suffix option to histogram value
>
> Tom Zanussi (1):
> tracing: Allow multiple hitcount values in histograms
>
> kernel/trace/trace.c | 3 +-
> kernel/trace/trace_events_hist.c | 144 ++++++++++++++++++++++++++++---
> 2 files changed, 136 insertions(+), 11 deletions(-)
>
> --
> 2.34.1
>
--
Masami Hiramatsu (Google) <[email protected]>