* [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 related [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 related [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
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 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