Re: [PATCH 2/2 v3] tracing/histogram: Update the documentation for the buckets modifier
From: Masami Hiramatsu
Date: Thu Jul 08 2021 - 08:23:52 EST
On Wed, 07 Jul 2021 17:36:25 -0400
Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
> From: "Steven Rostedt (VMware)" <rostedt@xxxxxxxxxxx>
>
> 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@xxxxxxxxxx>
Thanks!
> Signed-off-by: Steven Rostedt (VMware) <rostedt@xxxxxxxxxxx>
> ---
> 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@xxxxxxxxxx>