linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH 0/2 v3] tracing/histogram: Add buckets to group data in
@ 2021-07-07 21:36 Steven Rostedt
  2021-07-07 21:36 ` [PATCH 1/2 v3] tracing: Add linear buckets to histogram logic Steven Rostedt
                   ` (3 more replies)
  0 siblings, 4 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-07-07 21:36 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Tom Zanussi, Masami Hiramatsu,
	Namhyung Kim, Daniel Bristot de Oliveira

Add a .buckets modifier to group the data instead of having every key saved
in its own entry, and in a linear fashion instead of like the log2 modifier.

Changes since v2:

 - Rename "grouping" field in hist_field to "buckets"
 - Updated documentation to describe the new modifier


Steven Rostedt (VMware) (2):
      tracing: Add linear buckets to histogram logic
      tracing/histogram: Update the documentation for the buckets modifier

----
 Documentation/trace/histogram.rst | 92 ++++++++++++++++++++++++++++++++++++---
 kernel/trace/trace.c              |  1 +
 kernel/trace/trace_events_hist.c  | 65 ++++++++++++++++++++++++---
 3 files changed, 145 insertions(+), 13 deletions(-)

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [PATCH 1/2 v3] tracing: Add linear buckets to histogram logic
  2021-07-07 21:36 [PATCH 0/2 v3] tracing/histogram: Add buckets to group data in Steven Rostedt
@ 2021-07-07 21:36 ` Steven Rostedt
  2021-07-07 21:36 ` [PATCH 2/2 v3] tracing/histogram: Update the documentation for the buckets modifier Steven Rostedt
                   ` (2 subsequent siblings)
  3 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-07-07 21:36 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Tom Zanussi, Masami Hiramatsu,
	Namhyung Kim, Daniel Bristot de Oliveira

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

There's been several times I wished the histogram logic had a "grouping"
feature for the buckets. Currently, each bucket has a size of one. That
is, if you trace the amount of requested allocations, each allocation is
its own bucket, even if you are interested in what allocates 100 bytes or
less, 100 to 200, 200 to 300, etc.

Also, without grouping, it fills up the allocated histogram buckets
quickly. If you are tracking latency, and don't care if something is 200
microseconds off, or 201 microseconds off, but want to track them by say
10 microseconds each. This can not currently be done.

There is a log2 but that grouping get's too big too fast for a lot of
cases.

Introduce a "buckets=SIZE" command to each field where it will record in a
rounded number. For example:

 ># echo 'hist:keys=bytes_req.buckets=100:sort=bytes_req' > events/kmem/kmalloc/trigger
 ># cat events/kmem/kmalloc/hist
 # event histogram
 #
 # trigger info:
 hist:keys=bytes_req.buckets=100:vals=hitcount:sort=bytes_req.buckets=100:size=2048
 [active]
 #

 { bytes_req: ~ 0-99 } hitcount:       3149
 { bytes_req: ~ 100-199 } hitcount:       1468
 { bytes_req: ~ 200-299 } hitcount:         39
 { bytes_req: ~ 300-399 } hitcount:        306
 { bytes_req: ~ 400-499 } hitcount:        364
 { bytes_req: ~ 500-599 } hitcount:         32
 { bytes_req: ~ 600-699 } hitcount:         69
 { bytes_req: ~ 700-799 } hitcount:         37
 { bytes_req: ~ 1200-1299 } hitcount:         16
 { bytes_req: ~ 1400-1499 } hitcount:         30
 { bytes_req: ~ 2000-2099 } hitcount:          6
 { bytes_req: ~ 4000-4099 } hitcount:       2168
 { bytes_req: ~ 5000-5099 } hitcount:          6

 Totals:
     Hits: 7690
     Entries: 13
     Dropped: 0

Reviewed-by: Tom Zanussi <zanussi@kernel.org>
Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/trace_events_hist.c | 65 ++++++++++++++++++++++++++++----
 1 file changed, 58 insertions(+), 7 deletions(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 0207aeed31e6..1d0592051f2f 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -120,6 +120,7 @@ struct hist_field {
 	unsigned int			size;
 	unsigned int			offset;
 	unsigned int                    is_signed;
+	unsigned long			buckets;
 	const char			*type;
 	struct hist_field		*operands[HIST_FIELD_OPERANDS_MAX];
 	struct hist_trigger_data	*hist_data;
@@ -218,6 +219,27 @@ static u64 hist_field_log2(struct hist_field *hist_field,
 	return (u64) ilog2(roundup_pow_of_two(val));
 }
 
+static u64 hist_field_bucket(struct hist_field *hist_field,
+			     struct tracing_map_elt *elt,
+			     struct trace_buffer *buffer,
+			     struct ring_buffer_event *rbe,
+			     void *event)
+{
+	struct hist_field *operand = hist_field->operands[0];
+	unsigned long buckets = hist_field->buckets;
+
+	u64 val = operand->fn(operand, elt, buffer, rbe, event);
+
+	if (WARN_ON_ONCE(!buckets))
+		return val;
+
+	if (val >= LONG_MAX)
+		val = div64_ul(val, buckets);
+	else
+		val = (u64)((unsigned long)val / buckets);
+	return val * buckets;
+}
+
 static u64 hist_field_plus(struct hist_field *hist_field,
 			   struct tracing_map_elt *elt,
 			   struct trace_buffer *buffer,
@@ -317,6 +339,7 @@ enum hist_field_flags {
 	HIST_FIELD_FL_VAR_REF		= 1 << 14,
 	HIST_FIELD_FL_CPU		= 1 << 15,
 	HIST_FIELD_FL_ALIAS		= 1 << 16,
+	HIST_FIELD_FL_BUCKET		= 1 << 17,
 };
 
 struct var_defs {
@@ -1108,7 +1131,8 @@ static const char *hist_field_name(struct hist_field *field,
 	if (field->field)
 		field_name = field->field->name;
 	else if (field->flags & HIST_FIELD_FL_LOG2 ||
-		 field->flags & HIST_FIELD_FL_ALIAS)
+		 field->flags & HIST_FIELD_FL_ALIAS ||
+		 field->flags & HIST_FIELD_FL_BUCKET)
 		field_name = hist_field_name(field->operands[0], ++level);
 	else if (field->flags & HIST_FIELD_FL_CPU)
 		field_name = "cpu";
@@ -1469,6 +1493,8 @@ static const char *get_hist_field_flags(struct hist_field *hist_field)
 		flags_str = "syscall";
 	else if (hist_field->flags & HIST_FIELD_FL_LOG2)
 		flags_str = "log2";
+	else if (hist_field->flags & HIST_FIELD_FL_BUCKET)
+		flags_str = "buckets";
 	else if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP_USECS)
 		flags_str = "usecs";
 
@@ -1657,9 +1683,10 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
 		goto out;
 	}
 
-	if (flags & HIST_FIELD_FL_LOG2) {
-		unsigned long fl = flags & ~HIST_FIELD_FL_LOG2;
-		hist_field->fn = hist_field_log2;
+	if (flags & (HIST_FIELD_FL_LOG2 | HIST_FIELD_FL_BUCKET)) {
+		unsigned long fl = flags & ~(HIST_FIELD_FL_LOG2 | HIST_FIELD_FL_BUCKET);
+		hist_field->fn = flags & HIST_FIELD_FL_LOG2 ? hist_field_log2 :
+			hist_field_bucket;
 		hist_field->operands[0] = create_hist_field(hist_data, field, fl, NULL);
 		hist_field->size = hist_field->operands[0]->size;
 		hist_field->type = kstrdup(hist_field->operands[0]->type, GFP_KERNEL);
@@ -1950,7 +1977,7 @@ static struct hist_field *parse_var_ref(struct hist_trigger_data *hist_data,
 
 static struct ftrace_event_field *
 parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file,
-	    char *field_str, unsigned long *flags)
+	    char *field_str, unsigned long *flags, unsigned long *buckets)
 {
 	struct ftrace_event_field *field = NULL;
 	char *field_name, *modifier, *str;
@@ -1977,7 +2004,22 @@ parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file,
 			*flags |= HIST_FIELD_FL_LOG2;
 		else if (strcmp(modifier, "usecs") == 0)
 			*flags |= HIST_FIELD_FL_TIMESTAMP_USECS;
-		else {
+		else if (strncmp(modifier, "bucket", 6) == 0) {
+			int ret;
+
+			modifier += 6;
+
+			if (*modifier == 's')
+				modifier++;
+			if (*modifier != '=')
+				goto error;
+			modifier++;
+			ret = kstrtoul(modifier, 0, buckets);
+			if (ret || !(*buckets))
+				goto error;
+			*flags |= HIST_FIELD_FL_BUCKET;
+		} else {
+ error:
 			hist_err(tr, HIST_ERR_BAD_FIELD_MODIFIER, errpos(modifier));
 			field = ERR_PTR(-EINVAL);
 			goto out;
@@ -2036,6 +2078,7 @@ static struct hist_field *parse_atom(struct hist_trigger_data *hist_data,
 	char *s, *ref_system = NULL, *ref_event = NULL, *ref_var = str;
 	struct ftrace_event_field *field = NULL;
 	struct hist_field *hist_field = NULL;
+	unsigned long buckets = 0;
 	int ret = 0;
 
 	s = strchr(str, '.');
@@ -2073,7 +2116,7 @@ static struct hist_field *parse_atom(struct hist_trigger_data *hist_data,
 	} else
 		str = s;
 
-	field = parse_field(hist_data, file, str, flags);
+	field = parse_field(hist_data, file, str, flags, &buckets);
 	if (IS_ERR(field)) {
 		ret = PTR_ERR(field);
 		goto out;
@@ -2084,6 +2127,7 @@ static struct hist_field *parse_atom(struct hist_trigger_data *hist_data,
 		ret = -ENOMEM;
 		goto out;
 	}
+	hist_field->buckets = buckets;
 
 	return hist_field;
  out:
@@ -4664,6 +4708,11 @@ static void hist_trigger_print_key(struct seq_file *m,
 		} else if (key_field->flags & HIST_FIELD_FL_LOG2) {
 			seq_printf(m, "%s: ~ 2^%-2llu", field_name,
 				   *(u64 *)(key + key_field->offset));
+		} else if (key_field->flags & HIST_FIELD_FL_BUCKET) {
+			unsigned long buckets = key_field->buckets;
+			uval = *(u64 *)(key + key_field->offset);
+			seq_printf(m, "%s: ~ %llu-%llu", field_name,
+				   uval, uval + buckets -1);
 		} else if (key_field->flags & HIST_FIELD_FL_STRING) {
 			seq_printf(m, "%s: %-50s", field_name,
 				   (char *)(key + key_field->offset));
@@ -5103,6 +5152,8 @@ static void hist_field_print(struct seq_file *m, struct hist_field *hist_field)
 				seq_printf(m, ".%s", flags);
 		}
 	}
+	if (hist_field->buckets)
+		seq_printf(m, "=%ld", hist_field->buckets);
 }
 
 static int event_hist_trigger_print(struct seq_file *m,
-- 
2.30.2

^ permalink raw reply	[flat|nested] 8+ messages in thread

* [PATCH 2/2 v3] tracing/histogram: Update the documentation for the buckets modifier
  2021-07-07 21:36 [PATCH 0/2 v3] tracing/histogram: Add buckets to group data in Steven Rostedt
  2021-07-07 21:36 ` [PATCH 1/2 v3] tracing: Add linear buckets to histogram logic Steven Rostedt
@ 2021-07-07 21:36 ` Steven Rostedt
  2021-07-08 12:23   ` Masami Hiramatsu
  2021-07-08 20:05   ` Tom Zanussi
  2021-07-07 22:14 ` [PATCH 0/2 v3] tracing/histogram: Add buckets to group data in Namhyung Kim
  2021-08-04 14:17 ` Daniel Bristot de Oliveira
  3 siblings, 2 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-07-07 21:36 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Tom Zanussi, Masami Hiramatsu,
	Namhyung Kim, Daniel Bristot de Oliveira

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Update both the tracefs README file as well as the histogram.rst to
include an explanation of what the buckets modifier is and how to use it.
Include an example with the wakeup_latency example for both log2 and the
buckets modifiers as there was no existing log2 example.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 Documentation/trace/histogram.rst | 92 +++++++++++++++++++++++++++++--
 kernel/trace/trace.c              |  1 +
 2 files changed, 87 insertions(+), 6 deletions(-)

diff --git a/Documentation/trace/histogram.rst b/Documentation/trace/histogram.rst
index b71e09f745c3..11094ec6e52e 100644
--- a/Documentation/trace/histogram.rst
+++ b/Documentation/trace/histogram.rst
@@ -77,6 +77,7 @@ Documentation written by Tom Zanussi
 	.syscall    display a syscall id as a system call name
 	.execname   display a common_pid as a program name
 	.log2       display log2 value rather than raw number
+	.buckets=size  display grouping of values rather than raw number
 	.usecs      display a common_timestamp in microseconds
 	=========== ==========================================
 
@@ -228,7 +229,7 @@ Extended error information
   that lists the total number of bytes requested for each function in
   the kernel that made one or more calls to kmalloc::
 
-    # echo 'hist:key=call_site:val=bytes_req' > \
+    # echo 'hist:key=call_site:val=bytes_req.buckets=32' > \
             /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
 
   This tells the tracing system to create a 'hist' trigger using the
@@ -1823,20 +1824,99 @@ and variables defined on other events (see Section 2.2.3 below on
 how that is done using hist trigger 'onmatch' action). Once that is
 done, the 'wakeup_latency' synthetic event instance is created.
 
-A histogram can now be defined for the new synthetic event::
-
-  # echo 'hist:keys=pid,prio,lat.log2:sort=pid,lat' >> \
-        /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
-
 The new event is created under the tracing/events/synthetic/ directory
 and looks and behaves just like any other event::
 
   # ls /sys/kernel/debug/tracing/events/synthetic/wakeup_latency
         enable  filter  format  hist  id  trigger
 
+A histogram can now be defined for the new synthetic event::
+
+  # echo 'hist:keys=pid,prio,lat.log2:sort=lat' >> \
+        /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
+
+The above shows the latency "lat" in a power of 2 grouping.
+
 Like any other event, once a histogram is enabled for the event, the
 output can be displayed by reading the event's 'hist' file.
 
+  # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist
+
+  # event histogram
+  #
+  # trigger info: hist:keys=pid,prio,lat.log2:vals=hitcount:sort=lat.log2:size=2048 [active]
+  #
+
+  { pid:       2035, prio:          9, lat: ~ 2^2  } hitcount:         43
+  { pid:       2034, prio:          9, lat: ~ 2^2  } hitcount:         60
+  { pid:       2029, prio:          9, lat: ~ 2^2  } hitcount:        965
+  { pid:       2034, prio:        120, lat: ~ 2^2  } hitcount:          9
+  { pid:       2033, prio:        120, lat: ~ 2^2  } hitcount:          5
+  { pid:       2030, prio:          9, lat: ~ 2^2  } hitcount:        335
+  { pid:       2030, prio:        120, lat: ~ 2^2  } hitcount:         10
+  { pid:       2032, prio:        120, lat: ~ 2^2  } hitcount:          1
+  { pid:       2035, prio:        120, lat: ~ 2^2  } hitcount:          2
+  { pid:       2031, prio:          9, lat: ~ 2^2  } hitcount:        176
+  { pid:       2028, prio:        120, lat: ~ 2^2  } hitcount:         15
+  { pid:       2033, prio:          9, lat: ~ 2^2  } hitcount:         91
+  { pid:       2032, prio:          9, lat: ~ 2^2  } hitcount:        125
+  { pid:       2029, prio:        120, lat: ~ 2^2  } hitcount:          4
+  { pid:       2031, prio:        120, lat: ~ 2^2  } hitcount:          3
+  { pid:       2029, prio:        120, lat: ~ 2^3  } hitcount:          2
+  { pid:       2035, prio:          9, lat: ~ 2^3  } hitcount:         41
+  { pid:       2030, prio:        120, lat: ~ 2^3  } hitcount:          1
+  { pid:       2032, prio:          9, lat: ~ 2^3  } hitcount:         32
+  { pid:       2031, prio:          9, lat: ~ 2^3  } hitcount:         44
+  { pid:       2034, prio:          9, lat: ~ 2^3  } hitcount:         40
+  { pid:       2030, prio:          9, lat: ~ 2^3  } hitcount:         29
+  { pid:       2033, prio:          9, lat: ~ 2^3  } hitcount:         31
+  { pid:       2029, prio:          9, lat: ~ 2^3  } hitcount:         31
+  { pid:       2028, prio:        120, lat: ~ 2^3  } hitcount:         18
+  { pid:       2031, prio:        120, lat: ~ 2^3  } hitcount:          2
+  { pid:       2028, prio:        120, lat: ~ 2^4  } hitcount:          1
+  { pid:       2029, prio:          9, lat: ~ 2^4  } hitcount:          4
+  { pid:       2031, prio:        120, lat: ~ 2^7  } hitcount:          1
+  { pid:       2032, prio:        120, lat: ~ 2^7  } hitcount:          1
+
+  Totals:
+      Hits: 2122
+      Entries: 30
+      Dropped: 0
+
+
+The latency values can also be grouped linearly by a given size with
+the ".buckets" modifier and specify a size (in this case groups of 10).
+
+  # echo 'hist:keys=pid,prio,lat.buckets=10:sort=lat' >> \
+        /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
+
+  # event histogram
+  #
+  # trigger info: hist:keys=pid,prio,lat.buckets=10:vals=hitcount:sort=lat.buckets=10:size=2048 [active]
+  #
+
+  { pid:       2067, prio:          9, lat: ~ 0-9 } hitcount:        220
+  { pid:       2068, prio:          9, lat: ~ 0-9 } hitcount:        157
+  { pid:       2070, prio:          9, lat: ~ 0-9 } hitcount:        100
+  { pid:       2067, prio:        120, lat: ~ 0-9 } hitcount:          6
+  { pid:       2065, prio:        120, lat: ~ 0-9 } hitcount:          2
+  { pid:       2066, prio:        120, lat: ~ 0-9 } hitcount:          2
+  { pid:       2069, prio:          9, lat: ~ 0-9 } hitcount:        122
+  { pid:       2069, prio:        120, lat: ~ 0-9 } hitcount:          8
+  { pid:       2070, prio:        120, lat: ~ 0-9 } hitcount:          1
+  { pid:       2068, prio:        120, lat: ~ 0-9 } hitcount:          7
+  { pid:       2066, prio:          9, lat: ~ 0-9 } hitcount:        365
+  { pid:       2064, prio:        120, lat: ~ 0-9 } hitcount:         35
+  { pid:       2065, prio:          9, lat: ~ 0-9 } hitcount:        998
+  { pid:       2071, prio:          9, lat: ~ 0-9 } hitcount:         85
+  { pid:       2065, prio:          9, lat: ~ 10-19 } hitcount:          2
+  { pid:       2064, prio:        120, lat: ~ 10-19 } hitcount:          2
+
+  Totals:
+      Hits: 2112
+      Entries: 16
+      Dropped: 0
+
 2.2.3 Hist trigger 'handlers' and 'actions'
 -------------------------------------------
 
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 14f56e9fa001..8097d5aa8627 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -5648,6 +5648,7 @@ static const char readme_msg[] =
 	"\t            .execname   display a common_pid as a program name\n"
 	"\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    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"
-- 
2.30.2

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH 0/2 v3] tracing/histogram: Add buckets to group data in
  2021-07-07 21:36 [PATCH 0/2 v3] tracing/histogram: Add buckets to group data in Steven Rostedt
  2021-07-07 21:36 ` [PATCH 1/2 v3] tracing: Add linear buckets to histogram logic Steven Rostedt
  2021-07-07 21:36 ` [PATCH 2/2 v3] tracing/histogram: Update the documentation for the buckets modifier Steven Rostedt
@ 2021-07-07 22:14 ` Namhyung Kim
  2021-08-04 14:17 ` Daniel Bristot de Oliveira
  3 siblings, 0 replies; 8+ messages in thread
From: Namhyung Kim @ 2021-07-07 22:14 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Tom Zanussi,
	Masami Hiramatsu, Daniel Bristot de Oliveira

On Wed, Jul 7, 2021 at 2:39 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> Add a .buckets modifier to group the data instead of having every key saved
> in its own entry, and in a linear fashion instead of like the log2 modifier.
>
> Changes since v2:
>
>  - Rename "grouping" field in hist_field to "buckets"
>  - Updated documentation to describe the new modifier
>
>
> Steven Rostedt (VMware) (2):
>       tracing: Add linear buckets to histogram logic
>       tracing/histogram: Update the documentation for the buckets modifier

Acked-by: Namhyung Kim <namhyung@kernel.org>

Thanks,
Namhyung


>
> ----
>  Documentation/trace/histogram.rst | 92 ++++++++++++++++++++++++++++++++++++---
>  kernel/trace/trace.c              |  1 +
>  kernel/trace/trace_events_hist.c  | 65 ++++++++++++++++++++++++---
>  3 files changed, 145 insertions(+), 13 deletions(-)

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH 2/2 v3] tracing/histogram: Update the documentation for the buckets modifier
  2021-07-07 21:36 ` [PATCH 2/2 v3] tracing/histogram: Update the documentation for the buckets modifier Steven Rostedt
@ 2021-07-08 12:23   ` Masami Hiramatsu
  2021-07-08 20:05   ` Tom Zanussi
  1 sibling, 0 replies; 8+ messages in thread
From: Masami Hiramatsu @ 2021-07-08 12:23 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Tom Zanussi,
	Masami Hiramatsu, Namhyung Kim, Daniel Bristot de Oliveira

On Wed, 07 Jul 2021 17:36:25 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
> 
> Update both the tracefs README file as well as the histogram.rst to
> include an explanation of what the buckets modifier is and how to use it.
> Include an example with the wakeup_latency example for both log2 and the
> buckets modifiers as there was no existing log2 example.
> 

Looks good to me.

Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org>

Thanks!

> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>  Documentation/trace/histogram.rst | 92 +++++++++++++++++++++++++++++--
>  kernel/trace/trace.c              |  1 +
>  2 files changed, 87 insertions(+), 6 deletions(-)
> 
> diff --git a/Documentation/trace/histogram.rst b/Documentation/trace/histogram.rst
> index b71e09f745c3..11094ec6e52e 100644
> --- a/Documentation/trace/histogram.rst
> +++ b/Documentation/trace/histogram.rst
> @@ -77,6 +77,7 @@ Documentation written by Tom Zanussi
>  	.syscall    display a syscall id as a system call name
>  	.execname   display a common_pid as a program name
>  	.log2       display log2 value rather than raw number
> +	.buckets=size  display grouping of values rather than raw number
>  	.usecs      display a common_timestamp in microseconds
>  	=========== ==========================================
>  
> @@ -228,7 +229,7 @@ Extended error information
>    that lists the total number of bytes requested for each function in
>    the kernel that made one or more calls to kmalloc::
>  
> -    # echo 'hist:key=call_site:val=bytes_req' > \
> +    # echo 'hist:key=call_site:val=bytes_req.buckets=32' > \
>              /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
>  
>    This tells the tracing system to create a 'hist' trigger using the
> @@ -1823,20 +1824,99 @@ and variables defined on other events (see Section 2.2.3 below on
>  how that is done using hist trigger 'onmatch' action). Once that is
>  done, the 'wakeup_latency' synthetic event instance is created.
>  
> -A histogram can now be defined for the new synthetic event::
> -
> -  # echo 'hist:keys=pid,prio,lat.log2:sort=pid,lat' >> \
> -        /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
> -
>  The new event is created under the tracing/events/synthetic/ directory
>  and looks and behaves just like any other event::
>  
>    # ls /sys/kernel/debug/tracing/events/synthetic/wakeup_latency
>          enable  filter  format  hist  id  trigger
>  
> +A histogram can now be defined for the new synthetic event::
> +
> +  # echo 'hist:keys=pid,prio,lat.log2:sort=lat' >> \
> +        /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
> +
> +The above shows the latency "lat" in a power of 2 grouping.
> +
>  Like any other event, once a histogram is enabled for the event, the
>  output can be displayed by reading the event's 'hist' file.
>  
> +  # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist
> +
> +  # event histogram
> +  #
> +  # trigger info: hist:keys=pid,prio,lat.log2:vals=hitcount:sort=lat.log2:size=2048 [active]
> +  #
> +
> +  { pid:       2035, prio:          9, lat: ~ 2^2  } hitcount:         43
> +  { pid:       2034, prio:          9, lat: ~ 2^2  } hitcount:         60
> +  { pid:       2029, prio:          9, lat: ~ 2^2  } hitcount:        965
> +  { pid:       2034, prio:        120, lat: ~ 2^2  } hitcount:          9
> +  { pid:       2033, prio:        120, lat: ~ 2^2  } hitcount:          5
> +  { pid:       2030, prio:          9, lat: ~ 2^2  } hitcount:        335
> +  { pid:       2030, prio:        120, lat: ~ 2^2  } hitcount:         10
> +  { pid:       2032, prio:        120, lat: ~ 2^2  } hitcount:          1
> +  { pid:       2035, prio:        120, lat: ~ 2^2  } hitcount:          2
> +  { pid:       2031, prio:          9, lat: ~ 2^2  } hitcount:        176
> +  { pid:       2028, prio:        120, lat: ~ 2^2  } hitcount:         15
> +  { pid:       2033, prio:          9, lat: ~ 2^2  } hitcount:         91
> +  { pid:       2032, prio:          9, lat: ~ 2^2  } hitcount:        125
> +  { pid:       2029, prio:        120, lat: ~ 2^2  } hitcount:          4
> +  { pid:       2031, prio:        120, lat: ~ 2^2  } hitcount:          3
> +  { pid:       2029, prio:        120, lat: ~ 2^3  } hitcount:          2
> +  { pid:       2035, prio:          9, lat: ~ 2^3  } hitcount:         41
> +  { pid:       2030, prio:        120, lat: ~ 2^3  } hitcount:          1
> +  { pid:       2032, prio:          9, lat: ~ 2^3  } hitcount:         32
> +  { pid:       2031, prio:          9, lat: ~ 2^3  } hitcount:         44
> +  { pid:       2034, prio:          9, lat: ~ 2^3  } hitcount:         40
> +  { pid:       2030, prio:          9, lat: ~ 2^3  } hitcount:         29
> +  { pid:       2033, prio:          9, lat: ~ 2^3  } hitcount:         31
> +  { pid:       2029, prio:          9, lat: ~ 2^3  } hitcount:         31
> +  { pid:       2028, prio:        120, lat: ~ 2^3  } hitcount:         18
> +  { pid:       2031, prio:        120, lat: ~ 2^3  } hitcount:          2
> +  { pid:       2028, prio:        120, lat: ~ 2^4  } hitcount:          1
> +  { pid:       2029, prio:          9, lat: ~ 2^4  } hitcount:          4
> +  { pid:       2031, prio:        120, lat: ~ 2^7  } hitcount:          1
> +  { pid:       2032, prio:        120, lat: ~ 2^7  } hitcount:          1
> +
> +  Totals:
> +      Hits: 2122
> +      Entries: 30
> +      Dropped: 0
> +
> +
> +The latency values can also be grouped linearly by a given size with
> +the ".buckets" modifier and specify a size (in this case groups of 10).
> +
> +  # echo 'hist:keys=pid,prio,lat.buckets=10:sort=lat' >> \
> +        /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
> +
> +  # event histogram
> +  #
> +  # trigger info: hist:keys=pid,prio,lat.buckets=10:vals=hitcount:sort=lat.buckets=10:size=2048 [active]
> +  #
> +
> +  { pid:       2067, prio:          9, lat: ~ 0-9 } hitcount:        220
> +  { pid:       2068, prio:          9, lat: ~ 0-9 } hitcount:        157
> +  { pid:       2070, prio:          9, lat: ~ 0-9 } hitcount:        100
> +  { pid:       2067, prio:        120, lat: ~ 0-9 } hitcount:          6
> +  { pid:       2065, prio:        120, lat: ~ 0-9 } hitcount:          2
> +  { pid:       2066, prio:        120, lat: ~ 0-9 } hitcount:          2
> +  { pid:       2069, prio:          9, lat: ~ 0-9 } hitcount:        122
> +  { pid:       2069, prio:        120, lat: ~ 0-9 } hitcount:          8
> +  { pid:       2070, prio:        120, lat: ~ 0-9 } hitcount:          1
> +  { pid:       2068, prio:        120, lat: ~ 0-9 } hitcount:          7
> +  { pid:       2066, prio:          9, lat: ~ 0-9 } hitcount:        365
> +  { pid:       2064, prio:        120, lat: ~ 0-9 } hitcount:         35
> +  { pid:       2065, prio:          9, lat: ~ 0-9 } hitcount:        998
> +  { pid:       2071, prio:          9, lat: ~ 0-9 } hitcount:         85
> +  { pid:       2065, prio:          9, lat: ~ 10-19 } hitcount:          2
> +  { pid:       2064, prio:        120, lat: ~ 10-19 } hitcount:          2
> +
> +  Totals:
> +      Hits: 2112
> +      Entries: 16
> +      Dropped: 0
> +
>  2.2.3 Hist trigger 'handlers' and 'actions'
>  -------------------------------------------
>  
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 14f56e9fa001..8097d5aa8627 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -5648,6 +5648,7 @@ static const char readme_msg[] =
>  	"\t            .execname   display a common_pid as a program name\n"
>  	"\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    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"
> -- 
> 2.30.2


-- 
Masami Hiramatsu <mhiramat@kernel.org>

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH 2/2 v3] tracing/histogram: Update the documentation for the buckets modifier
  2021-07-07 21:36 ` [PATCH 2/2 v3] tracing/histogram: Update the documentation for the buckets modifier Steven Rostedt
  2021-07-08 12:23   ` Masami Hiramatsu
@ 2021-07-08 20:05   ` Tom Zanussi
  2021-07-08 20:11     ` Steven Rostedt
  1 sibling, 1 reply; 8+ messages in thread
From: Tom Zanussi @ 2021-07-08 20:05 UTC (permalink / raw)
  To: Steven Rostedt, linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Masami Hiramatsu, Namhyung Kim,
	Daniel Bristot de Oliveira

Hi Steve,

On Wed, 2021-07-07 at 17:36 -0400, Steven Rostedt wrote:
> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
> 
> Update both the tracefs README file as well as the histogram.rst to
> include an explanation of what the buckets modifier is and how to use
> it.
> Include an example with the wakeup_latency example for both log2 and
> the
> buckets modifiers as there was no existing log2 example.
> 
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>  Documentation/trace/histogram.rst | 92
> +++++++++++++++++++++++++++++--
>  kernel/trace/trace.c              |  1 +
>  2 files changed, 87 insertions(+), 6 deletions(-)
> 
> diff --git a/Documentation/trace/histogram.rst
> b/Documentation/trace/histogram.rst
> index b71e09f745c3..11094ec6e52e 100644
> --- a/Documentation/trace/histogram.rst
> +++ b/Documentation/trace/histogram.rst
> @@ -77,6 +77,7 @@ Documentation written by Tom Zanussi
>  	.syscall    display a syscall id as a system call name
>  	.execname   display a common_pid as a program name
>  	.log2       display log2 value rather than raw number
> +	.buckets=size  display grouping of values rather than raw
> number
>  	.usecs      display a common_timestamp in microseconds
>  	=========== ==========================================
>  
> @@ -228,7 +229,7 @@ Extended error information
>    that lists the total number of bytes requested for each function
> in
>    the kernel that made one or more calls to kmalloc::
>  
> -    # echo 'hist:key=call_site:val=bytes_req' > \
> +    # echo 'hist:key=call_site:val=bytes_req.buckets=32' > \
>              /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger

This just seems random, not sure why you changed it, and it doesn't
make sense on a val anyway..

The rest looks good, though, thanks for doing this!

Reviewed-by: Tom Zanussi <zanussi@kernel.org>




^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH 2/2 v3] tracing/histogram: Update the documentation for the buckets modifier
  2021-07-08 20:05   ` Tom Zanussi
@ 2021-07-08 20:11     ` Steven Rostedt
  0 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2021-07-08 20:11 UTC (permalink / raw)
  To: Tom Zanussi
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Masami Hiramatsu,
	Namhyung Kim, Daniel Bristot de Oliveira

On Thu, 08 Jul 2021 15:05:16 -0500
Tom Zanussi <zanussi@kernel.org> wrote:

> > -    # echo 'hist:key=call_site:val=bytes_req' > \
> > +    # echo 'hist:key=call_site:val=bytes_req.buckets=32' > \
> >              /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger  
> 
> This just seems random, not sure why you changed it, and it doesn't
> make sense on a val anyway..

Good catch! I originally wrote this to explain the buckets in this
location, and then realized it did not match the flow, and moved my text
down. It appears that I missed putting back the original trigger. Will fix
and send a v4.

> 
> The rest looks good, though, thanks for doing this!
> 
> Reviewed-by: Tom Zanussi <zanussi@kernel.org>

Thanks!

-- Steve

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: [PATCH 0/2 v3] tracing/histogram: Add buckets to group data in
  2021-07-07 21:36 [PATCH 0/2 v3] tracing/histogram: Add buckets to group data in Steven Rostedt
                   ` (2 preceding siblings ...)
  2021-07-07 22:14 ` [PATCH 0/2 v3] tracing/histogram: Add buckets to group data in Namhyung Kim
@ 2021-08-04 14:17 ` Daniel Bristot de Oliveira
  3 siblings, 0 replies; 8+ messages in thread
From: Daniel Bristot de Oliveira @ 2021-08-04 14:17 UTC (permalink / raw)
  To: Steven Rostedt, linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Tom Zanussi, Masami Hiramatsu,
	Namhyung Kim, Daniel Bristot de Oliveira

On 7/7/21 11:36 PM, Steven Rostedt wrote:
> Add a .buckets modifier to group the data instead of having every key saved
> in its own entry, and in a linear fashion instead of like the log2 modifier.
> 
> Changes since v2:
> 
>  - Rename "grouping" field in hist_field to "buckets"
>  - Updated documentation to describe the new modifier
> 
> 
> Steven Rostedt (VMware) (2):
>       tracing: Add linear buckets to histogram logic
>       tracing/histogram: Update the documentation for the buckets modifier

ok, I need this!

Tested on regular and preempt rt kernel.

Tested-by: Daniel Bristot de Oliveira <bristot@kernel.org>

[root@alien bristot]# cd /sys/kernel/tracing/
[root@alien tracing]# echo 'hist:keys=duration.buckets=1000:sort=duration' >> events/osnoise/sample_threshold/trigger
[root@alien tracing]# echo osnoise > current_tracer 
[root@alien tracing]# cat events/osnoise/sample_threshold/hist 
# event histogram
#
# trigger info: hist:keys=duration.buckets=1000:vals=hitcount:sort=duration.buckets=1000:size=2048 [active]
#

{ duration: ~ 5000-5999 } hitcount:        384
{ duration: ~ 6000-6999 } hitcount:        175
{ duration: ~ 7000-7999 } hitcount:         55
{ duration: ~ 8000-8999 } hitcount:        230
{ duration: ~ 9000-9999 } hitcount:         60
{ duration: ~ 10000-10999 } hitcount:        123
{ duration: ~ 11000-11999 } hitcount:         20
{ duration: ~ 12000-12999 } hitcount:         40
{ duration: ~ 13000-13999 } hitcount:        954
{ duration: ~ 14000-14999 } hitcount:         43
{ duration: ~ 15000-15999 } hitcount:         41
{ duration: ~ 16000-16999 } hitcount:         12
{ duration: ~ 17000-17999 } hitcount:         44
{ duration: ~ 18000-18999 } hitcount:          6
{ duration: ~ 19000-19999 } hitcount:          7
{ duration: ~ 20000-20999 } hitcount:          4
{ duration: ~ 21000-21999 } hitcount:          5
{ duration: ~ 22000-22999 } hitcount:          1
{ duration: ~ 23000-23999 } hitcount:          2
{ duration: ~ 24000-24999 } hitcount:         13
{ duration: ~ 25000-25999 } hitcount:         14
{ duration: ~ 26000-26999 } hitcount:         10
{ duration: ~ 27000-27999 } hitcount:          1
{ duration: ~ 28000-28999 } hitcount:          5
{ duration: ~ 29000-29999 } hitcount:          5
{ duration: ~ 30000-30999 } hitcount:          4
{ duration: ~ 31000-31999 } hitcount:          2
{ duration: ~ 32000-32999 } hitcount:          2
{ duration: ~ 33000-33999 } hitcount:          3
{ duration: ~ 34000-34999 } hitcount:          1
{ duration: ~ 35000-35999 } hitcount:          1
{ duration: ~ 36000-36999 } hitcount:          4
{ duration: ~ 37000-37999 } hitcount:          2
{ duration: ~ 42000-42999 } hitcount:          1
{ duration: ~ 47000-47999 } hitcount:          1
{ duration: ~ 51000-51999 } hitcount:          5
{ duration: ~ 52000-52999 } hitcount:          2
{ duration: ~ 53000-53999 } hitcount:          6
{ duration: ~ 54000-54999 } hitcount:          3
{ duration: ~ 55000-55999 } hitcount:          9
{ duration: ~ 56000-56999 } hitcount:          7
{ duration: ~ 57000-57999 } hitcount:          5
{ duration: ~ 58000-58999 } hitcount:          2
{ duration: ~ 59000-59999 } hitcount:          4
{ duration: ~ 60000-60999 } hitcount:          1
{ duration: ~ 61000-61999 } hitcount:          4
{ duration: ~ 62000-62999 } hitcount:          2
{ duration: ~ 64000-64999 } hitcount:          4
{ duration: ~ 65000-65999 } hitcount:          3
{ duration: ~ 66000-66999 } hitcount:         17
{ duration: ~ 67000-67999 } hitcount:         12
{ duration: ~ 68000-68999 } hitcount:          1
{ duration: ~ 69000-69999 } hitcount:          9
{ duration: ~ 70000-70999 } hitcount:          8
{ duration: ~ 71000-71999 } hitcount:         10
{ duration: ~ 72000-72999 } hitcount:          3
{ duration: ~ 73000-73999 } hitcount:          1
{ duration: ~ 74000-74999 } hitcount:          2
{ duration: ~ 75000-75999 } hitcount:          3
{ duration: ~ 77000-77999 } hitcount:          3
{ duration: ~ 78000-78999 } hitcount:          2
{ duration: ~ 79000-79999 } hitcount:          2
{ duration: ~ 83000-83999 } hitcount:          3
{ duration: ~ 84000-84999 } hitcount:          1
{ duration: ~ 85000-85999 } hitcount:          1
{ duration: ~ 86000-86999 } hitcount:          6
{ duration: ~ 87000-87999 } hitcount:          3
{ duration: ~ 88000-88999 } hitcount:          2
{ duration: ~ 90000-90999 } hitcount:          1
{ duration: ~ 91000-91999 } hitcount:          1
{ duration: ~ 92000-92999 } hitcount:          1
{ duration: ~ 97000-97999 } hitcount:          1
{ duration: ~ 99000-99999 } hitcount:          4
{ duration: ~ 100000-100999 } hitcount:          2
{ duration: ~ 101000-101999 } hitcount:          1
{ duration: ~ 104000-104999 } hitcount:          1
{ duration: ~ 106000-106999 } hitcount:          1
{ duration: ~ 107000-107999 } hitcount:          1
{ duration: ~ 109000-109999 } hitcount:          1
{ duration: ~ 130000-130999 } hitcount:          1
{ duration: ~ 155000-155999 } hitcount:          1
{ duration: ~ 160000-160999 } hitcount:          1
{ duration: ~ 194000-194999 } hitcount:          1
{ duration: ~ 335000-335999 } hitcount:          1
{ duration: ~ 437000-437999 } hitcount:          1
{ duration: ~ 452000-452999 } hitcount:          1
{ duration: ~ 457000-457999 } hitcount:          1
{ duration: ~ 524000-524999 } hitcount:          1
{ duration: ~ 623000-623999 } hitcount:          1
{ duration: ~ 627000-627999 } hitcount:          1
{ duration: ~ 629000-629999 } hitcount:          1
{ duration: ~ 634000-634999 } hitcount:          1
{ duration: ~ 695000-695999 } hitcount:          1
{ duration: ~ 706000-706999 } hitcount:          1
{ duration: ~ 720000-720999 } hitcount:          1
{ duration: ~ 768000-768999 } hitcount:          1
{ duration: ~ 1296000-1296999 } hitcount:          1
{ duration: ~ 1301000-1301999 } hitcount:          1
{ duration: ~ 1303000-1303999 } hitcount:          1
{ duration: ~ 1306000-1306999 } hitcount:          1
{ duration: ~ 1308000-1308999 } hitcount:          1
{ duration: ~ 1310000-1310999 } hitcount:          1
{ duration: ~ 1314000-1314999 } hitcount:          1
{ duration: ~ 1315000-1315999 } hitcount:          1
{ duration: ~ 1318000-1318999 } hitcount:          1
{ duration: ~ 1321000-1321999 } hitcount:          1
{ duration: ~ 1322000-1322999 } hitcount:          1
{ duration: ~ 1325000-1325999 } hitcount:          1
{ duration: ~ 1330000-1330999 } hitcount:          1
{ duration: ~ 1367000-1367999 } hitcount:          1
{ duration: ~ 1415000-1415999 } hitcount:          1
{ duration: ~ 1420000-1420999 } hitcount:          1
{ duration: ~ 1462000-1462999 } hitcount:          1
{ duration: ~ 1466000-1466999 } hitcount:          1
{ duration: ~ 1489000-1489999 } hitcount:          1
{ duration: ~ 1537000-1537999 } hitcount:          1
{ duration: ~ 1559000-1559999 } hitcount:          1
{ duration: ~ 3176000-3176999 } hitcount:          1
{ duration: ~ 3353000-3353999 } hitcount:          1
{ duration: ~ 3719000-3719999 } hitcount:          1
{ duration: ~ 5824000-5824999 } hitcount:          1

Totals:
    Hits: 2478
    Entries: 121
    Dropped: 0



> ----
>  Documentation/trace/histogram.rst | 92 ++++++++++++++++++++++++++++++++++++---
>  kernel/trace/trace.c              |  1 +
>  kernel/trace/trace_events_hist.c  | 65 ++++++++++++++++++++++++---
>  3 files changed, 145 insertions(+), 13 deletions(-)
> 


^ permalink raw reply	[flat|nested] 8+ messages in thread

end of thread, other threads:[~2021-08-04 14:41 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-07-07 21:36 [PATCH 0/2 v3] tracing/histogram: Add buckets to group data in Steven Rostedt
2021-07-07 21:36 ` [PATCH 1/2 v3] tracing: Add linear buckets to histogram logic Steven Rostedt
2021-07-07 21:36 ` [PATCH 2/2 v3] tracing/histogram: Update the documentation for the buckets modifier Steven Rostedt
2021-07-08 12:23   ` Masami Hiramatsu
2021-07-08 20:05   ` Tom Zanussi
2021-07-08 20:11     ` Steven Rostedt
2021-07-07 22:14 ` [PATCH 0/2 v3] tracing/histogram: Add buckets to group data in Namhyung Kim
2021-08-04 14:17 ` Daniel Bristot de Oliveira

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).