tracing/hist: Add percentage histogram suffixes

PATCH Superseded Masami Hiramatsu (Google) 2 participants 7 messages Aug 5, 2022 – Aug 23, 2022 Tracing

lore

Share & tools

lore

Masami Hiramatsu (Google)

author maintainer

2022-08-05 01:35 UTC #0 lore raw

v2 cover tracing/hist: Add percentage histogram suffixes

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) <[email protected]>

Masami Hiramatsu (Google)

author maintainer

2022-08-05 01:37 UTC #1 lore raw

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

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]>

---
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(-)

kernel/trace/trace.c +2 -1

index 7eb5bce62500..4f54f2494370 100644
@@ -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"

kernel/trace/trace_events_hist.c +72 -7

141 lines not on this page · raw message

Masami Hiramatsu (Google)

author maintainer

2022-08-05 01:37 UTC #2 lore raw

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

In reply to Masami Hiramatsu (Google)

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]>

---
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(-)

kernel/trace/trace_events_hist.c +64 ~~-14~~

index c774d2ff02a8..3d609f457e8c 100644
@@ -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);

Tom Zanussi

2022-08-18 20:41 UTC #3 lore raw

In reply to Masami Hiramatsu (Google)

Hi Masami,

Quoted 24 lines · 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]
#

Quoted 12 lines

{ 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'

Quoted 1 line

Quoted 1 line
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'

Quoted 1 line

Quoted 1 line
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

Quoted 1 line

Quoted 1 line
/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

Quoted 23 lines

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) <[email protected]>

Masami Hiramatsu (Google)

author maintainer

2022-08-20 02:31 UTC #4 lore raw

Quoted 40 lines · On Thu, 18 Aug 2022 15:41:30 -0500 Tom Zanussi <[email protected]> wrote:

Hi Masami,
Quoted 24 lines · 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]
#
Quoted 12 lines
{ 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: #####

Quoted 1 line

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

Thanks!

Quoted 9 lines

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'
Quoted 1 line
Quoted 1 line
sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
  # cat hist

Quoted 8 lines

  # 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.

Quoted 13 lines

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'
Quoted 1 line
Quoted 1 line
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]
  #

Quoted 8 lines

  { 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.

Quoted 2 lines

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.

Quoted 3 lines

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...)

Quoted 16 lines

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 
Quoted 1 line
Quoted 1 line
/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

Quoted 6 lines

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!

Quoted 27 lines

Tom
Quoted 23 lines
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) <[email protected]>

Signature · 1 line

Masami Hiramatsu (Google) <[email protected]>

Tom Zanussi

2022-08-21 19:35 UTC #5 lore raw

Quoted 129 lines · Masami Hiramatsu

Quoted 57 lines · On Thu, 18 Aug 2022 15:41:30 -0500 Tom Zanussi <[email protected]> wrote:
Hi Masami,
Quoted 44 lines · 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=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: ####
Quoted 9 lines
{ 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: #####
Quoted 1 line
This is a really nice new feature, thanks for adding it!
Thanks!
Quoted 19 lines
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
Quoted 1 line
it only shows one column with percent, no graph.
Hmm, curious. Also, the trigger info seems odd.
Quoted 20 lines
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: ##########
Quoted 7 lines
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.
Quoted 2 lines
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.
Quoted 4 lines
Also, the trigger info string always only shows 'vals=hitcount' even if
percent or graph is set.

Quoted 5 lines

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

Quoted 69 lines

Quoted 27 lines
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 
   
Quoted 1 line
Quoted 1 line
/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?:
Quoted 6 lines
{ 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!
Quoted 28 lines
Tom
Quoted 24 lines
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) <[email protected]>

Masami Hiramatsu (Google)

author maintainer

2022-08-23 02:58 UTC #6 lore raw

Quoted 142 lines · On Sun, 21 Aug 2022 14:35:00 -0500 Tom Zanussi <[email protected]> wrote:

Quoted 129 lines · Masami Hiramatsu
Quoted 57 lines · On Thu, 18 Aug 2022 15:41:30 -0500 Tom Zanussi <[email protected]> wrote:
Hi Masami,
Quoted 44 lines · 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=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: ####
Quoted 9 lines
{ 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: #####
Quoted 1 line
This is a really nice new feature, thanks for adding it!
Thanks!
Quoted 19 lines
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
Quoted 1 line
it only shows one column with percent, no graph.
Hmm, curious. Also, the trigger info seems odd.
Quoted 20 lines
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: ##########
Quoted 7 lines
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.
Quoted 2 lines
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.
Quoted 4 lines
Also, the trigger info string always only shows 'vals=hitcount' even if
percent or graph is set.
Quoted 5 lines
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.

Quoted 6 lines

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. :)

Quoted 6 lines

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,

Quoted 73 lines

Tom
Quoted 69 lines
Quoted 27 lines
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 
   
Quoted 1 line
Quoted 1 line
/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?:
Quoted 6 lines
{ 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!
Quoted 28 lines
Tom
Quoted 24 lines
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) <[email protected]>

Signature · 1 line

Masami Hiramatsu (Google) <[email protected]>