[PATCH v2 0/2] tracing/hist: Add percentage histogram suffixes

[PATCH v2 0/2] tracing/hist: Add percentage histogram suffixes

[Masami Hiramatsu (Google)]

Hi,

Here is the 2nd version of .percent and .graph suffixes for histogram
trigger to show the value in percentage and in bar-graph respectively.

This version uses div64_*() for calculating percentages and show an
error if it fails to calculate it.

This will help us to check the trend of the histogram instantly
without the post processing tool.

Here shows the example of the percentage and the bar graph of
the runtime of the running tasks.

/sys/kernel/tracing # echo hist:keys=pid:vals=runtime.percent,runtime.graph:sort
=pid >> events/sched/sched_stat_runtime/trigger
/sys/kernel/tracing # sleep 10
/sys/kernel/tracing # cat events/sched/sched_stat_runtime/hist
# event histogram
#
# trigger info: hist:keys=pid:vals=hitcount,runtime.percent,runtime.graph:sort=pid:size=2048 [active]
#

{ pid:          8 } hitcount:         11  runtime:       4.11  runtime: #                   
{ pid:          9 } hitcount:          4  runtime:       1.28  runtime:                     
{ pid:         14 } hitcount:         10  runtime:       2.22  runtime:                     
{ pid:         15 } hitcount:          1  runtime:       0.07  runtime:                     
{ pid:         16 } hitcount:         21  runtime:       3.35  runtime: #                   
{ pid:         57 } hitcount:          6  runtime:       2.41  runtime: #                   
{ pid:         61 } hitcount:         42  runtime:       9.79  runtime: ####                
{ pid:         66 } hitcount:          5  runtime:       0.69  runtime:                     
{ pid:        147 } hitcount:         36  runtime:      45.33  runtime: ####################
{ pid:       8548 } hitcount:          9  runtime:      17.25  runtime: #######             
{ pid:       8549 } hitcount:          8  runtime:      13.43  runtime: #####               

Totals:
    Hits: 153
    Entries: 11
    Dropped: 0


Thank you,

---

Masami Hiramatsu (Google) (2):
      tracing: Add .percent suffix option to histogram values
      tracing: Add .graph suffix option to histogram value


 kernel/trace/trace.c             |    3 +
 kernel/trace/trace_events_hist.c |  129 ++++++++++++++++++++++++++++++++++++--
 2 files changed, 124 insertions(+), 8 deletions(-)

--
Masami Hiramatsu (Google) <mhiramat@kernel.org>

[PATCH v2 1/2] tracing: Add .percent suffix option to histogram values

[Masami Hiramatsu (Google)]

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:         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) <mhiramat@kernel.org>
---
 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[] =
 	"\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..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		= 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,18 +5202,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);
@@ -5210,7 +5248,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 {
@@ -5229,7 +5275,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 +5284,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;

[PATCH v2 2/2] tracing: Add .graph suffix option to histogram value

[Masami Hiramatsu (Google)]

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 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_hist.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		= 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;
 		}
 
@@ -5218,14 +5228,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);
@@ -5233,11 +5266,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);
 
@@ -5250,12 +5286,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));
@@ -5276,7 +5316,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,
@@ -5285,27 +5326,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);
 

Re: [PATCH v2 0/2] tracing/hist: Add percentage histogram suffixes

[Tom Zanussi]

Hi Masami,

On Fri, 2022-08-05 at 10:35 +0900, Masami Hiramatsu (Google) wrote:
> Hi,
> 
> Here is the 2nd version of .percent and .graph suffixes for histogram
> trigger to show the value in percentage and in bar-graph respectively.
> 
> This version uses div64_*() for calculating percentages and show an
> error if it fails to calculate it.
> 

> This will help us to check the trend of the histogram instantly
> without the post processing tool.
> 
> Here shows the example of the percentage and the bar graph of
> the runtime of the running tasks.
> 
> /sys/kernel/tracing # echo hist:keys=pid:vals=runtime.percent,runtime.graph:sort
> =pid >> events/sched/sched_stat_runtime/trigger
> /sys/kernel/tracing # sleep 10
> /sys/kernel/tracing # cat events/sched/sched_stat_runtime/hist
> # event histogram
> #
> # trigger info: hist:keys=pid:vals=hitcount,runtime.percent,runtime.graph:sort=pid:size=2048 [active]
> #
> 
> { pid:          8 } hitcount:         11  runtime:       4.11  runtime: #                   
> { pid:          9 } hitcount:          4  runtime:       1.28  runtime:                     
> { pid:         14 } hitcount:         10  runtime:       2.22  runtime:                     
> { pid:         15 } hitcount:          1  runtime:       0.07  runtime:                     
> { pid:         16 } hitcount:         21  runtime:       3.35  runtime: #                   
> { pid:         57 } hitcount:          6  runtime:       2.41  runtime: #                   
> { pid:         61 } hitcount:         42  runtime:       9.79  runtime: ####                
> { pid:         66 } hitcount:          5  runtime:       0.69  runtime:                     
> { pid:        147 } hitcount:         36  runtime:      45.33  runtime: ####################
> { pid:       8548 } hitcount:          9  runtime:      17.25  runtime: #######             
> { pid:       8549 } hitcount:          8  runtime:      13.43  runtime: #####    
> 

This is a really nice new feature, thanks for adding it!

I did notice some anomalies when it comes to hitcount, though.  For
instance, If I do similar to above with hitcount:

  # echo 'hist:keys=pid:vals=hitcount.percent,hitcount.graph:sort=pid'
    >> sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
  
  # cat hist

  # event histogram
  #
  # trigger info: hist:keys=pid:vals=hitcount:sort=pid:size=2048 [active]
  { pid:         16 } hitcount:       2.11
  { pid:         63 } hitcount:       6.33
  { pid:         64 } hitcount:       6.33

it only shows one column with percent, no graph.

Similarly, if I do just hitcount and hitcount.graph, I only get the graph,
no straight hitcount:

  # echo 'hist:keys=pid:vals=hitcount,hitcount.graph:sort=pid'
    >> sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger

  # cat hist
  # event histogram
  #
  # trigger info: hist:keys=pid:vals=hitcount:sort=pid:size=2048 active]
  #

  { pid:         16 } hitcount: ######              
  { pid:         63 } hitcount: ##########          
  { pid:         64 } hitcount: ##########

I think it's because there's only one hitcount variable serving both
PERCENT and GRAPH flags, and never gets to GRAPH if both are set.  So
needs to iterate over both flags for hitcount to see which or if both
are set.  Also, in order to just print the straight hitcount if one of
the other flags is set probably needs another flag for that case.

Also, the trigger info string always only shows 'vals=hitcount' even if
percent or graph is set.

Finally, I'm wondering if labeling the percent column as percent would
make things clearer in cases where you have the straight value along
with the percent e.g. currently we have:

  # echo hist:keys=pid:vals=runtime,runtime.percent:sort=pid 
    >>/sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
  # cat hist
  # event histogram
  #
  # trigger info: hist:keys=pid:vals=hitcount,runtime,runtime.percent:sort=pid:size=2048 [active]
  #

  { pid:         16 } hitcount:          3  runtime:      50742  runtime:       0.36
  { pid:         63 } hitcount:          6  runtime:     123394  runtime:       0.88

which seeems a little confusing, 2 runtime fields with different values.  Maybe something like?:

  { pid:         16 } hitcount:          3  runtime:      50742  runtime (%):       0.36
  { pid:         63 } hitcount:          6  runtime:     123394  runtime (%):       0.88

Just a thought..

Tom

>            
> 
> Totals:
>     Hits: 153
>     Entries: 11
>     Dropped: 0
> 
> 
> Thank you,
> 
> ---
> 
> Masami Hiramatsu (Google) (2):
>       tracing: Add .percent suffix option to histogram values
>       tracing: Add .graph suffix option to histogram value
> 
> 
>  kernel/trace/trace.c             |    3 +
>  kernel/trace/trace_events_hist.c |  129 ++++++++++++++++++++++++++++++++++++--
>  2 files changed, 124 insertions(+), 8 deletions(-)
> 
> --
> Masami Hiramatsu (Google) <mhiramat@kernel.org>

Re: [PATCH v2 0/2] tracing/hist: Add percentage histogram suffixes

[Masami Hiramatsu]

On Thu, 18 Aug 2022 15:41:30 -0500
Tom Zanussi <zanussi@kernel.org> wrote:

> Hi Masami,
> 
> On Fri, 2022-08-05 at 10:35 +0900, Masami Hiramatsu (Google) wrote:
> > Hi,
> > 
> > Here is the 2nd version of .percent and .graph suffixes for histogram
> > trigger to show the value in percentage and in bar-graph respectively.
> > 
> > This version uses div64_*() for calculating percentages and show an
> > error if it fails to calculate it.
> > 
> 
> > This will help us to check the trend of the histogram instantly
> > without the post processing tool.
> > 
> > Here shows the example of the percentage and the bar graph of
> > the runtime of the running tasks.
> > 
> > /sys/kernel/tracing # echo hist:keys=pid:vals=runtime.percent,runtime.graph:sort
> > =pid >> events/sched/sched_stat_runtime/trigger
> > /sys/kernel/tracing # sleep 10
> > /sys/kernel/tracing # cat events/sched/sched_stat_runtime/hist
> > # event histogram
> > #
> > # trigger info: hist:keys=pid:vals=hitcount,runtime.percent,runtime.graph:sort=pid:size=2048 [active]
> > #
> > 
> > { pid:          8 } hitcount:         11  runtime:       4.11  runtime: #                   
> > { pid:          9 } hitcount:          4  runtime:       1.28  runtime:                     
> > { pid:         14 } hitcount:         10  runtime:       2.22  runtime:                     
> > { pid:         15 } hitcount:          1  runtime:       0.07  runtime:                     
> > { pid:         16 } hitcount:         21  runtime:       3.35  runtime: #                   
> > { pid:         57 } hitcount:          6  runtime:       2.41  runtime: #                   
> > { pid:         61 } hitcount:         42  runtime:       9.79  runtime: ####                
> > { pid:         66 } hitcount:          5  runtime:       0.69  runtime:                     
> > { pid:        147 } hitcount:         36  runtime:      45.33  runtime: ####################
> > { pid:       8548 } hitcount:          9  runtime:      17.25  runtime: #######             
> > { pid:       8549 } hitcount:          8  runtime:      13.43  runtime: #####    
> > 
> 
> This is a really nice new feature, thanks for adding it!

Thanks!

> 
> I did notice some anomalies when it comes to hitcount, though.  For
> instance, If I do similar to above with hitcount:
> 
>   # echo 'hist:keys=pid:vals=hitcount.percent,hitcount.graph:sort=pid'
>     >> sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
>   
>   # cat hist
> 
>   # event histogram
>   #
>   # trigger info: hist:keys=pid:vals=hitcount:sort=pid:size=2048 [active]
>   { pid:         16 } hitcount:       2.11
>   { pid:         63 } hitcount:       6.33
>   { pid:         64 } hitcount:       6.33
> 
> it only shows one column with percent, no graph.

Hmm, curious. Also, the trigger info seems odd.

> 
> Similarly, if I do just hitcount and hitcount.graph, I only get the graph,
> no straight hitcount:
> 
>   # echo 'hist:keys=pid:vals=hitcount,hitcount.graph:sort=pid'
>     >> sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
> 
>   # cat hist
>   # event histogram
>   #
>   # trigger info: hist:keys=pid:vals=hitcount:sort=pid:size=2048 active]
>   #
> 
>   { pid:         16 } hitcount: ######              
>   { pid:         63 } hitcount: ##########          
>   { pid:         64 } hitcount: ##########
> 
> I think it's because there's only one hitcount variable serving both
> PERCENT and GRAPH flags, and never gets to GRAPH if both are set.  So
> needs to iterate over both flags for hitcount to see which or if both
> are set.

Ah, I thought if I specify the hitcount twice, there would be 2 hitcount
fields, but actually it is not.

>  Also, in order to just print the straight hitcount if one of
> the other flags is set probably needs another flag for that case.

Yes, because hitcount is shown only once.

> 
> Also, the trigger info string always only shows 'vals=hitcount' even if
> percent or graph is set.

yes, the hitcount seeems to be special. Would you know why hitcount
is always shown and handled in such unique way?
(If user skips setting vals, it is natual to use hitcount by default, but
 if user specifies any vals, I would like to drop hitcount...) 

> 
> Finally, I'm wondering if labeling the percent column as percent would
> make things clearer in cases where you have the straight value along
> with the percent e.g. currently we have:
> 
>   # echo hist:keys=pid:vals=runtime,runtime.percent:sort=pid 
>     >>/sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
>   # cat hist
>   # event histogram
>   #
>   # trigger info: hist:keys=pid:vals=hitcount,runtime,runtime.percent:sort=pid:size=2048 [active]
>   #
> 
>   { pid:         16 } hitcount:          3  runtime:      50742  runtime:       0.36
>   { pid:         63 } hitcount:          6  runtime:     123394  runtime:       0.88
> 
> which seeems a little confusing, 2 runtime fields with different values.  Maybe something like?:
> 
>   { pid:         16 } hitcount:          3  runtime:      50742  runtime (%):       0.36
>   { pid:         63 } hitcount:          6  runtime:     123394  runtime (%):       0.88
> 
> Just a thought..

Ah, that's a good idea.
Let me update the series.

Thank you!

> 
> Tom
> 
> >            
> > 
> > Totals:
> >     Hits: 153
> >     Entries: 11
> >     Dropped: 0
> > 
> > 
> > Thank you,
> > 
> > ---
> > 
> > Masami Hiramatsu (Google) (2):
> >       tracing: Add .percent suffix option to histogram values
> >       tracing: Add .graph suffix option to histogram value
> > 
> > 
> >  kernel/trace/trace.c             |    3 +
> >  kernel/trace/trace_events_hist.c |  129 ++++++++++++++++++++++++++++++++++++--
> >  2 files changed, 124 insertions(+), 8 deletions(-)
> > 
> > --
> > Masami Hiramatsu (Google) <mhiramat@kernel.org>
> 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>

Re: [PATCH v2 0/2] tracing/hist: Add percentage histogram suffixes

[Tom Zanussi]

On Sat, 2022-08-20 at 11:31 +0900, Masami Hiramatsu wrote:
> On Thu, 18 Aug 2022 15:41:30 -0500
> Tom Zanussi <zanussi@kernel.org> wrote:
> 
> > Hi Masami,
> > 
> > On Fri, 2022-08-05 at 10:35 +0900, Masami Hiramatsu (Google) wrote:
> > > Hi,
> > > 
> > > Here is the 2nd version of .percent and .graph suffixes for
> > > histogram
> > > trigger to show the value in percentage and in bar-graph
> > > respectively.
> > > 
> > > This version uses div64_*() for calculating percentages and show
> > > an
> > > error if it fails to calculate it.
> > > 
> > 
> > > This will help us to check the trend of the histogram instantly
> > > without the post processing tool.
> > > 
> > > Here shows the example of the percentage and the bar graph of
> > > the runtime of the running tasks.
> > > 
> > > /sys/kernel/tracing # echo
> > > hist:keys=pid:vals=runtime.percent,runtime.graph:sort
> > > =pid >> events/sched/sched_stat_runtime/trigger
> > > /sys/kernel/tracing # sleep 10
> > > /sys/kernel/tracing # cat events/sched/sched_stat_runtime/hist
> > > # event histogram
> > > #
> > > # trigger info:
> > > hist:keys=pid:vals=hitcount,runtime.percent,runtime.graph:sort=pi
> > > d:size=2048 [active]
> > > #
> > > 
> > > { pid:          8 } hitcount:         11  runtime:       4.11 
> > > runtime: #                   
> > > { pid:          9 } hitcount:          4  runtime:       1.28 
> > > runtime:                     
> > > { pid:         14 } hitcount:         10  runtime:       2.22 
> > > runtime:                     
> > > { pid:         15 } hitcount:          1  runtime:       0.07 
> > > runtime:                     
> > > { pid:         16 } hitcount:         21  runtime:       3.35 
> > > runtime: #                   
> > > { pid:         57 } hitcount:          6  runtime:       2.41 
> > > runtime: #                   
> > > { pid:         61 } hitcount:         42  runtime:       9.79 
> > > runtime: ####                
> > > { pid:         66 } hitcount:          5  runtime:       0.69 
> > > runtime:                     
> > > { pid:        147 } hitcount:         36  runtime:      45.33 
> > > runtime: ####################
> > > { pid:       8548 } hitcount:          9  runtime:      17.25 
> > > runtime: #######             
> > > { pid:       8549 } hitcount:          8  runtime:      13.43 
> > > runtime: #####    
> > > 
> > 
> > This is a really nice new feature, thanks for adding it!
> 
> Thanks!
> 
> > 
> > I did notice some anomalies when it comes to hitcount, though.  For
> > instance, If I do similar to above with hitcount:
> > 
> >   # echo
> > 'hist:keys=pid:vals=hitcount.percent,hitcount.graph:sort=pid'
> >     >>
> > sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
> >   
> >   # cat hist
> > 
> >   # event histogram
> >   #
> >   # trigger info: hist:keys=pid:vals=hitcount:sort=pid:size=2048
> > [active]
> >   { pid:         16 } hitcount:       2.11
> >   { pid:         63 } hitcount:       6.33
> >   { pid:         64 } hitcount:       6.33
> > 
> > it only shows one column with percent, no graph.
> 
> Hmm, curious. Also, the trigger info seems odd.
> 
> > 
> > Similarly, if I do just hitcount and hitcount.graph, I only get the
> > graph,
> > no straight hitcount:
> > 
> >   # echo 'hist:keys=pid:vals=hitcount,hitcount.graph:sort=pid'
> >     >>
> > sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
> > 
> >   # cat hist
> >   # event histogram
> >   #
> >   # trigger info: hist:keys=pid:vals=hitcount:sort=pid:size=2048
> > active]
> >   #
> > 
> >   { pid:         16 } hitcount: ######              
> >   { pid:         63 } hitcount: ##########          
> >   { pid:         64 } hitcount: ##########
> > 
> > I think it's because there's only one hitcount variable serving
> > both
> > PERCENT and GRAPH flags, and never gets to GRAPH if both are set. 
> > So
> > needs to iterate over both flags for hitcount to see which or if
> > both
> > are set.
> 
> Ah, I thought if I specify the hitcount twice, there would be 2
> hitcount
> fields, but actually it is not.
> 
> >  Also, in order to just print the straight hitcount if one of
> > the other flags is set probably needs another flag for that case.
> 
> Yes, because hitcount is shown only once.
> 
> > 
> > Also, the trigger info string always only shows 'vals=hitcount'
> > even if
> > percent or graph is set.
> 
> yes, the hitcount seeems to be special. Would you know why hitcount
> is always shown and handled in such unique way?
> (If user skips setting vals, it is natual to use hitcount by default,
> but
>  if user specifies any vals, I would like to drop hitcount...) 

It was just assumed that you'd always want to see the hitcount, so it
was added unconditionally as the first value.  I don't think we can
just drop it at this point if another value is specified and the
hitcount isn't, but we could add another section that could be used to
tailor the display to get rid of it e.g.

 echo hist:keys=pid:vals=hitcount:sort=pid:size=2048:display=no_hitcount,...

The display= section could be used to add other customization
possibilities in the future.

What do you think?

As for the anomalies I pointed out with the hitcount in your patches,
I'm thinking that adding a patch that allows the user to add multiple
hitcounts as with any other value should make the problems go away -
let me create a patch to do that and then you shouldn't have to make
any changes to yours..

Tom

> 
> > 
> > Finally, I'm wondering if labeling the percent column as percent
> > would
> > make things clearer in cases where you have the straight value
> > along
> > with the percent e.g. currently we have:
> > 
> >   # echo hist:keys=pid:vals=runtime,runtime.percent:sort=pid 
> >    
> > >>/sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
> >   # cat hist
> >   # event histogram
> >   #
> >   # trigger info:
> > hist:keys=pid:vals=hitcount,runtime,runtime.percent:sort=pid:size=2
> > 048 [active]
> >   #
> > 
> >   { pid:         16 } hitcount:          3  runtime:      50742 
> > runtime:       0.36
> >   { pid:         63 } hitcount:          6  runtime:     123394 
> > runtime:       0.88
> > 
> > which seeems a little confusing, 2 runtime fields with different
> > values.  Maybe something like?:
> > 
> >   { pid:         16 } hitcount:          3  runtime:      50742 
> > runtime (%):       0.36
> >   { pid:         63 } hitcount:          6  runtime:     123394 
> > runtime (%):       0.88
> > 
> > Just a thought..
> 
> Ah, that's a good idea.
> Let me update the series.
> 
> Thank you!
> 
> > 
> > Tom
> > 
> > >            
> > > 
> > > Totals:
> > >     Hits: 153
> > >     Entries: 11
> > >     Dropped: 0
> > > 
> > > 
> > > Thank you,
> > > 
> > > ---
> > > 
> > > Masami Hiramatsu (Google) (2):
> > >       tracing: Add .percent suffix option to histogram values
> > >       tracing: Add .graph suffix option to histogram value
> > > 
> > > 
> > >  kernel/trace/trace.c             |    3 +
> > >  kernel/trace/trace_events_hist.c |  129
> > > ++++++++++++++++++++++++++++++++++++--
> > >  2 files changed, 124 insertions(+), 8 deletions(-)
> > > 
> > > --
> > > Masami Hiramatsu (Google) <mhiramat@kernel.org>
> > 
> 
> 

Re: [PATCH v2 0/2] tracing/hist: Add percentage histogram suffixes

[Masami Hiramatsu]

On Sun, 21 Aug 2022 14:35:00 -0500
Tom Zanussi <zanussi@kernel.org> wrote:

> On Sat, 2022-08-20 at 11:31 +0900, Masami Hiramatsu wrote:
> > On Thu, 18 Aug 2022 15:41:30 -0500
> > Tom Zanussi <zanussi@kernel.org> wrote:
> > 
> > > Hi Masami,
> > > 
> > > On Fri, 2022-08-05 at 10:35 +0900, Masami Hiramatsu (Google) wrote:
> > > > Hi,
> > > > 
> > > > Here is the 2nd version of .percent and .graph suffixes for
> > > > histogram
> > > > trigger to show the value in percentage and in bar-graph
> > > > respectively.
> > > > 
> > > > This version uses div64_*() for calculating percentages and show
> > > > an
> > > > error if it fails to calculate it.
> > > > 
> > > 
> > > > This will help us to check the trend of the histogram instantly
> > > > without the post processing tool.
> > > > 
> > > > Here shows the example of the percentage and the bar graph of
> > > > the runtime of the running tasks.
> > > > 
> > > > /sys/kernel/tracing # echo
> > > > hist:keys=pid:vals=runtime.percent,runtime.graph:sort
> > > > =pid >> events/sched/sched_stat_runtime/trigger
> > > > /sys/kernel/tracing # sleep 10
> > > > /sys/kernel/tracing # cat events/sched/sched_stat_runtime/hist
> > > > # event histogram
> > > > #
> > > > # trigger info:
> > > > hist:keys=pid:vals=hitcount,runtime.percent,runtime.graph:sort=pi
> > > > d:size=2048 [active]
> > > > #
> > > > 
> > > > { pid:          8 } hitcount:         11  runtime:       4.11 
> > > > runtime: #                   
> > > > { pid:          9 } hitcount:          4  runtime:       1.28 
> > > > runtime:                     
> > > > { pid:         14 } hitcount:         10  runtime:       2.22 
> > > > runtime:                     
> > > > { pid:         15 } hitcount:          1  runtime:       0.07 
> > > > runtime:                     
> > > > { pid:         16 } hitcount:         21  runtime:       3.35 
> > > > runtime: #                   
> > > > { pid:         57 } hitcount:          6  runtime:       2.41 
> > > > runtime: #                   
> > > > { pid:         61 } hitcount:         42  runtime:       9.79 
> > > > runtime: ####                
> > > > { pid:         66 } hitcount:          5  runtime:       0.69 
> > > > runtime:                     
> > > > { pid:        147 } hitcount:         36  runtime:      45.33 
> > > > runtime: ####################
> > > > { pid:       8548 } hitcount:          9  runtime:      17.25 
> > > > runtime: #######             
> > > > { pid:       8549 } hitcount:          8  runtime:      13.43 
> > > > runtime: #####    
> > > > 
> > > 
> > > This is a really nice new feature, thanks for adding it!
> > 
> > Thanks!
> > 
> > > 
> > > I did notice some anomalies when it comes to hitcount, though.  For
> > > instance, If I do similar to above with hitcount:
> > > 
> > >   # echo
> > > 'hist:keys=pid:vals=hitcount.percent,hitcount.graph:sort=pid'
> > >     >>
> > > sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
> > >   
> > >   # cat hist
> > > 
> > >   # event histogram
> > >   #
> > >   # trigger info: hist:keys=pid:vals=hitcount:sort=pid:size=2048
> > > [active]
> > >   { pid:         16 } hitcount:       2.11
> > >   { pid:         63 } hitcount:       6.33
> > >   { pid:         64 } hitcount:       6.33
> > > 
> > > it only shows one column with percent, no graph.
> > 
> > Hmm, curious. Also, the trigger info seems odd.
> > 
> > > 
> > > Similarly, if I do just hitcount and hitcount.graph, I only get the
> > > graph,
> > > no straight hitcount:
> > > 
> > >   # echo 'hist:keys=pid:vals=hitcount,hitcount.graph:sort=pid'
> > >     >>
> > > sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
> > > 
> > >   # cat hist
> > >   # event histogram
> > >   #
> > >   # trigger info: hist:keys=pid:vals=hitcount:sort=pid:size=2048
> > > active]
> > >   #
> > > 
> > >   { pid:         16 } hitcount: ######              
> > >   { pid:         63 } hitcount: ##########          
> > >   { pid:         64 } hitcount: ##########
> > > 
> > > I think it's because there's only one hitcount variable serving
> > > both
> > > PERCENT and GRAPH flags, and never gets to GRAPH if both are set. 
> > > So
> > > needs to iterate over both flags for hitcount to see which or if
> > > both
> > > are set.
> > 
> > Ah, I thought if I specify the hitcount twice, there would be 2
> > hitcount
> > fields, but actually it is not.
> > 
> > >  Also, in order to just print the straight hitcount if one of
> > > the other flags is set probably needs another flag for that case.
> > 
> > Yes, because hitcount is shown only once.
> > 
> > > 
> > > Also, the trigger info string always only shows 'vals=hitcount'
> > > even if
> > > percent or graph is set.
> > 
> > yes, the hitcount seeems to be special. Would you know why hitcount
> > is always shown and handled in such unique way?
> > (If user skips setting vals, it is natual to use hitcount by default,
> > but
> >  if user specifies any vals, I would like to drop hitcount...) 
> 
> It was just assumed that you'd always want to see the hitcount, so it
> was added unconditionally as the first value.  I don't think we can
> just drop it at this point if another value is specified and the
> hitcount isn't, but we could add another section that could be used to
> tailor the display to get rid of it e.g.
> 
>  echo hist:keys=pid:vals=hitcount:sort=pid:size=2048:display=no_hitcount,...
> 
> The display= section could be used to add other customization
> possibilities in the future.
> 
> What do you think?

Ah, that's nice. But I would like to have "option" instead of "display"
so that we can add another options in the future. :)

> 
> As for the anomalies I pointed out with the hitcount in your patches,
> I'm thinking that adding a patch that allows the user to add multiple
> hitcounts as with any other value should make the problems go away -
> let me create a patch to do that and then you shouldn't have to make
> any changes to yours..

Oops, I already updated mine, let me just share the v3. Anyway I will
wait your series and update it again. :)

Thank you,

> 
> Tom
> 
> > 
> > > 
> > > Finally, I'm wondering if labeling the percent column as percent
> > > would
> > > make things clearer in cases where you have the straight value
> > > along
> > > with the percent e.g. currently we have:
> > > 
> > >   # echo hist:keys=pid:vals=runtime,runtime.percent:sort=pid 
> > >    
> > > >>/sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
> > >   # cat hist
> > >   # event histogram
> > >   #
> > >   # trigger info:
> > > hist:keys=pid:vals=hitcount,runtime,runtime.percent:sort=pid:size=2
> > > 048 [active]
> > >   #
> > > 
> > >   { pid:         16 } hitcount:          3  runtime:      50742 
> > > runtime:       0.36
> > >   { pid:         63 } hitcount:          6  runtime:     123394 
> > > runtime:       0.88
> > > 
> > > which seeems a little confusing, 2 runtime fields with different
> > > values.  Maybe something like?:
> > > 
> > >   { pid:         16 } hitcount:          3  runtime:      50742 
> > > runtime (%):       0.36
> > >   { pid:         63 } hitcount:          6  runtime:     123394 
> > > runtime (%):       0.88
> > > 
> > > Just a thought..
> > 
> > Ah, that's a good idea.
> > Let me update the series.
> > 
> > Thank you!
> > 
> > > 
> > > Tom
> > > 
> > > >            
> > > > 
> > > > Totals:
> > > >     Hits: 153
> > > >     Entries: 11
> > > >     Dropped: 0
> > > > 
> > > > 
> > > > Thank you,
> > > > 
> > > > ---
> > > > 
> > > > Masami Hiramatsu (Google) (2):
> > > >       tracing: Add .percent suffix option to histogram values
> > > >       tracing: Add .graph suffix option to histogram value
> > > > 
> > > > 
> > > >  kernel/trace/trace.c             |    3 +
> > > >  kernel/trace/trace_events_hist.c |  129
> > > > ++++++++++++++++++++++++++++++++++++--
> > > >  2 files changed, 124 insertions(+), 8 deletions(-)
> > > > 
> > > > --
> > > > Masami Hiramatsu (Google) <mhiramat@kernel.org>
> > > 
> > 
> > 
> 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>