docs: histogram.txt: convert it to ReST file format
Despite being mentioned at Documentation/trace/ftrace.rst as a rst file, this file was still a text one, with several issues. Convert it to ReST and add it to the trace index: - Mark the document title as such; - Identify and indent the literal blocks; - Use the proper markups for table. Signed-off-by: Mauro Carvalho Chehab <mchehab+samsung@kernel.org> Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org> Signed-off-by: Jonathan Corbet <corbet@lwn.net>hifive-unleashed-5.1
parent
60a8666850
commit
ea272257cc
|
@ -524,4 +524,4 @@ The following commands are supported:
|
|||
totals derived from one or more trace event format fields and/or
|
||||
event counts (hitcount).
|
||||
|
||||
See Documentation/trace/histogram.txt for details and examples.
|
||||
See Documentation/trace/histogram.rst for details and examples.
|
||||
|
|
|
@ -1,4 +1,6 @@
|
|||
================
|
||||
Event Histograms
|
||||
================
|
||||
|
||||
Documentation written by Tom Zanussi
|
||||
|
||||
|
@ -19,7 +21,7 @@
|
|||
derived from one or more trace event format fields and/or event
|
||||
counts (hitcount).
|
||||
|
||||
The format of a hist trigger is as follows:
|
||||
The format of a hist trigger is as follows::
|
||||
|
||||
hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>]
|
||||
[:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue]
|
||||
|
@ -68,6 +70,7 @@
|
|||
modified by appending any of the following modifiers to the field
|
||||
name:
|
||||
|
||||
=========== ==========================================
|
||||
.hex display a number as a hex value
|
||||
.sym display an address as a symbol
|
||||
.sym-offset display an address as a symbol and offset
|
||||
|
@ -75,6 +78,7 @@
|
|||
.execname display a common_pid as a program name
|
||||
.log2 display log2 value rather than raw number
|
||||
.usecs display a common_timestamp in microseconds
|
||||
=========== ==========================================
|
||||
|
||||
Note that in general the semantics of a given field aren't
|
||||
interpreted when applying a modifier to it, but there are some
|
||||
|
@ -92,7 +96,7 @@
|
|||
pid-specific comm fields in the event itself.
|
||||
|
||||
A typical usage scenario would be the following to enable a hist
|
||||
trigger, read its current contents, and then turn it off:
|
||||
trigger, read its current contents, and then turn it off::
|
||||
|
||||
# echo 'hist:keys=skbaddr.hex:vals=len' > \
|
||||
/sys/kernel/debug/tracing/events/net/netif_rx/trigger
|
||||
|
@ -140,7 +144,7 @@
|
|||
can be attached to a given event, allowing that event to kick off
|
||||
and stop aggregations on a host of other events.
|
||||
|
||||
The format is very similar to the enable/disable_event triggers:
|
||||
The format is very similar to the enable/disable_event triggers::
|
||||
|
||||
enable_hist:<system>:<event>[:count]
|
||||
disable_hist:<system>:<event>[:count]
|
||||
|
@ -153,7 +157,7 @@
|
|||
A typical usage scenario for the enable_hist/disable_hist triggers
|
||||
would be to first set up a paused hist trigger on some event,
|
||||
followed by an enable_hist/disable_hist pair that turns the hist
|
||||
aggregation on and off when conditions of interest are hit:
|
||||
aggregation on and off when conditions of interest are hit::
|
||||
|
||||
# echo 'hist:keys=skbaddr.hex:vals=len:pause' > \
|
||||
/sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
|
||||
|
@ -182,11 +186,13 @@
|
|||
event, and can be used anywhere an actual event field could be.
|
||||
They are:
|
||||
|
||||
common_timestamp u64 - timestamp (from ring buffer) associated
|
||||
====================== ==== =======================================
|
||||
common_timestamp u64 timestamp (from ring buffer) associated
|
||||
with the event, in nanoseconds. May be
|
||||
modified by .usecs to have timestamps
|
||||
interpreted as microseconds.
|
||||
cpu int - the cpu on which the event occurred.
|
||||
cpu int the cpu on which the event occurred.
|
||||
====================== ==== =======================================
|
||||
|
||||
Extended error information
|
||||
--------------------------
|
||||
|
@ -199,7 +205,7 @@
|
|||
be available until the next hist trigger command for that event.
|
||||
|
||||
If available for a given error condition, the extended error
|
||||
information and usage takes the following form:
|
||||
information and usage takes the following form::
|
||||
|
||||
# echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
|
||||
echo: write error: Invalid argument
|
||||
|
@ -213,7 +219,7 @@
|
|||
|
||||
The first set of examples creates aggregations using the kmalloc
|
||||
event. The fields that can be used for the hist trigger are listed
|
||||
in the kmalloc event's format file:
|
||||
in the kmalloc event's format file::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format
|
||||
name: kmalloc
|
||||
|
@ -232,7 +238,7 @@
|
|||
|
||||
We'll start by creating a hist trigger that generates a simple table
|
||||
that lists the total number of bytes requested for each function in
|
||||
the kernel that made one or more calls to kmalloc:
|
||||
the kernel that made one or more calls to kmalloc::
|
||||
|
||||
# echo 'hist:key=call_site:val=bytes_req' > \
|
||||
/sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
|
||||
|
@ -247,7 +253,7 @@
|
|||
|
||||
We'll let it run for awhile and then dump the contents of the 'hist'
|
||||
file in the kmalloc event's subdirectory (for readability, a number
|
||||
of entries have been omitted):
|
||||
of entries have been omitted)::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
|
||||
# trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
|
||||
|
@ -287,7 +293,7 @@
|
|||
specified in the trigger, followed by the value(s) also specified in
|
||||
the trigger. At the beginning of the output is a line that displays
|
||||
the trigger info, which can also be displayed by reading the
|
||||
'trigger' file:
|
||||
'trigger' file::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
|
||||
hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
|
||||
|
@ -317,7 +323,7 @@
|
|||
frequencies.
|
||||
|
||||
To turn the hist trigger off, simply call up the trigger in the
|
||||
command history and re-execute it with a '!' prepended:
|
||||
command history and re-execute it with a '!' prepended::
|
||||
|
||||
# echo '!hist:key=call_site:val=bytes_req' > \
|
||||
/sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
|
||||
|
@ -325,7 +331,7 @@
|
|||
Finally, notice that the call_site as displayed in the output above
|
||||
isn't really very useful. It's an address, but normally addresses
|
||||
are displayed in hex. To have a numeric field displayed as a hex
|
||||
value, simply append '.hex' to the field name in the trigger:
|
||||
value, simply append '.hex' to the field name in the trigger::
|
||||
|
||||
# echo 'hist:key=call_site.hex:val=bytes_req' > \
|
||||
/sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
|
||||
|
@ -370,7 +376,7 @@
|
|||
when looking at text addresses are the corresponding symbols
|
||||
instead. To have an address displayed as symbolic value instead,
|
||||
simply append '.sym' or '.sym-offset' to the field name in the
|
||||
trigger:
|
||||
trigger::
|
||||
|
||||
# echo 'hist:key=call_site.sym:val=bytes_req' > \
|
||||
/sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
|
||||
|
@ -420,7 +426,7 @@
|
|||
run. If instead we we wanted to see the top kmalloc callers in
|
||||
terms of the number of bytes requested rather than the number of
|
||||
calls, and we wanted the top caller to appear at the top, we can use
|
||||
the 'sort' parameter, along with the 'descending' modifier:
|
||||
the 'sort' parameter, along with the 'descending' modifier::
|
||||
|
||||
# echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \
|
||||
/sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
|
||||
|
@ -461,7 +467,7 @@
|
|||
Dropped: 0
|
||||
|
||||
To display the offset and size information in addition to the symbol
|
||||
name, just use 'sym-offset' instead:
|
||||
name, just use 'sym-offset' instead::
|
||||
|
||||
# echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \
|
||||
/sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
|
||||
|
@ -500,7 +506,7 @@
|
|||
We can also add multiple fields to the 'values' parameter. For
|
||||
example, we might want to see the total number of bytes allocated
|
||||
alongside bytes requested, and display the result sorted by bytes
|
||||
allocated in a descending order:
|
||||
allocated in a descending order::
|
||||
|
||||
# echo 'hist:keys=call_site.sym:values=bytes_req,bytes_alloc:sort=bytes_alloc.descending' > \
|
||||
/sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
|
||||
|
@ -543,7 +549,7 @@
|
|||
the hist trigger display symbolic call_sites, we can have the hist
|
||||
trigger additionally display the complete set of kernel stack traces
|
||||
that led to each call_site. To do that, we simply use the special
|
||||
value 'stacktrace' for the key parameter:
|
||||
value 'stacktrace' for the key parameter::
|
||||
|
||||
# echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \
|
||||
/sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
|
||||
|
@ -554,7 +560,7 @@
|
|||
event, along with a running total of any of the event fields for
|
||||
that event. Here we tally bytes requested and bytes allocated for
|
||||
every callpath in the system that led up to a kmalloc (in this case
|
||||
every callpath to a kmalloc for a kernel compile):
|
||||
every callpath to a kmalloc for a kernel compile)::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
|
||||
# trigger info: hist:keys=stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active]
|
||||
|
@ -652,7 +658,7 @@
|
|||
gather and display sorted totals for each process, you can use the
|
||||
special .execname modifier to display the executable names for the
|
||||
processes in the table rather than raw pids. The example below
|
||||
keeps a per-process sum of total bytes read:
|
||||
keeps a per-process sum of total bytes read::
|
||||
|
||||
# echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \
|
||||
/sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
|
||||
|
@ -693,7 +699,7 @@
|
|||
gather and display a list of systemwide syscall hits, you can use
|
||||
the special .syscall modifier to display the syscall names rather
|
||||
than raw ids. The example below keeps a running total of syscall
|
||||
counts for the system during the run:
|
||||
counts for the system during the run::
|
||||
|
||||
# echo 'hist:key=id.syscall:val=hitcount' > \
|
||||
/sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
|
||||
|
@ -747,7 +753,7 @@
|
|||
system call id and pid - the end result is essentially a table
|
||||
that keeps a per-pid sum of system call hits. The results are
|
||||
sorted using the system call id as the primary key, and the
|
||||
hitcount sum as the secondary key:
|
||||
hitcount sum as the secondary key::
|
||||
|
||||
# echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \
|
||||
/sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
|
||||
|
@ -797,7 +803,7 @@
|
|||
pid, but it also gives us quite a bit more than that, which we
|
||||
don't really care about at the moment. Since we know the syscall
|
||||
id for sys_ioctl (16, displayed next to the sys_ioctl name), we
|
||||
can use that to filter out all the other syscalls:
|
||||
can use that to filter out all the other syscalls::
|
||||
|
||||
# echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount if id == 16' > \
|
||||
/sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
|
||||
|
@ -840,7 +846,7 @@
|
|||
common_pid and size event fields. Sorting with pid as the primary
|
||||
key and 'size' as the secondary key allows us to display an
|
||||
ordered summary of the recvfrom sizes, with counts, received by
|
||||
each process:
|
||||
each process::
|
||||
|
||||
# echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \
|
||||
/sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/trigger
|
||||
|
@ -893,7 +899,7 @@
|
|||
demonstrates how you can manually pause and continue a hist trigger.
|
||||
In this example, we'll aggregate fork counts and don't expect a
|
||||
large number of entries in the hash table, so we'll drop it to a
|
||||
much smaller number, say 256:
|
||||
much smaller number, say 256::
|
||||
|
||||
# echo 'hist:key=child_comm:val=hitcount:size=256' > \
|
||||
/sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
|
||||
|
@ -929,7 +935,7 @@
|
|||
|
||||
If we want to pause the hist trigger, we can simply append :pause to
|
||||
the command that started the trigger. Notice that the trigger info
|
||||
displays as [paused]:
|
||||
displays as [paused]::
|
||||
|
||||
# echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \
|
||||
/sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
|
||||
|
@ -966,7 +972,7 @@
|
|||
|
||||
To manually continue having the trigger aggregate events, append
|
||||
:cont instead. Notice that the trigger info displays as [active]
|
||||
again, and the data has changed:
|
||||
again, and the data has changed::
|
||||
|
||||
# echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \
|
||||
/sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
|
||||
|
@ -1020,7 +1026,7 @@
|
|||
wget.
|
||||
|
||||
First we set up an initially paused stacktrace trigger on the
|
||||
netif_receive_skb event:
|
||||
netif_receive_skb event::
|
||||
|
||||
# echo 'hist:key=stacktrace:vals=len:pause' > \
|
||||
/sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
|
||||
|
@ -1031,7 +1037,7 @@
|
|||
set up on netif_receive_skb if and only if it sees a
|
||||
sched_process_exec event with a filename of '/usr/bin/wget'. When
|
||||
that happens, all netif_receive_skb events are aggregated into a
|
||||
hash table keyed on stacktrace:
|
||||
hash table keyed on stacktrace::
|
||||
|
||||
# echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \
|
||||
/sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
|
||||
|
@ -1039,7 +1045,7 @@
|
|||
The aggregation continues until the netif_receive_skb is paused
|
||||
again, which is what the following disable_hist event does by
|
||||
creating a similar setup on the sched_process_exit event, using the
|
||||
filter 'comm==wget':
|
||||
filter 'comm==wget'::
|
||||
|
||||
# echo 'disable_hist:net:netif_receive_skb if comm==wget' > \
|
||||
/sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
|
||||
|
@ -1051,7 +1057,7 @@
|
|||
The overall effect is that netif_receive_skb events are aggregated
|
||||
into the hash table for only the duration of the wget. Executing a
|
||||
wget command and then listing the 'hist' file will display the
|
||||
output generated by the wget command:
|
||||
output generated by the wget command::
|
||||
|
||||
$ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
|
||||
|
||||
|
@ -1136,13 +1142,13 @@
|
|||
Suppose we wanted to try another run of the previous example but
|
||||
this time also wanted to see the complete list of events that went
|
||||
into the histogram. In order to avoid having to set everything up
|
||||
again, we can just clear the histogram first:
|
||||
again, we can just clear the histogram first::
|
||||
|
||||
# echo 'hist:key=stacktrace:vals=len:clear' >> \
|
||||
/sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
|
||||
|
||||
Just to verify that it is in fact cleared, here's what we now see in
|
||||
the hist file:
|
||||
the hist file::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
|
||||
# trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused]
|
||||
|
@ -1156,7 +1162,7 @@
|
|||
event occurring during the new run, which are in fact the same
|
||||
events being aggregated into the hash table, we add some additional
|
||||
'enable_event' events to the triggering sched_process_exec and
|
||||
sched_process_exit events as such:
|
||||
sched_process_exit events as such::
|
||||
|
||||
# echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \
|
||||
/sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
|
||||
|
@ -1167,7 +1173,7 @@
|
|||
If you read the trigger files for the sched_process_exec and
|
||||
sched_process_exit triggers, you should see two triggers for each:
|
||||
one enabling/disabling the hist aggregation and the other
|
||||
enabling/disabling the logging of events:
|
||||
enabling/disabling the logging of events::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
|
||||
enable_event:net:netif_receive_skb:unlimited if filename==/usr/bin/wget
|
||||
|
@ -1181,13 +1187,13 @@
|
|||
sched_process_exit events is hit and matches 'wget', it enables or
|
||||
disables both the histogram and the event log, and what you end up
|
||||
with is a hash table and set of events just covering the specified
|
||||
duration. Run the wget command again:
|
||||
duration. Run the wget command again::
|
||||
|
||||
$ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
|
||||
|
||||
Displaying the 'hist' file should show something similar to what you
|
||||
saw in the last run, but this time you should also see the
|
||||
individual events in the trace file:
|
||||
individual events in the trace file::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/trace
|
||||
|
||||
|
@ -1220,7 +1226,7 @@
|
|||
attached to a given event. This capability can be useful for
|
||||
creating a set of different summaries derived from the same set of
|
||||
events, or for comparing the effects of different filters, among
|
||||
other things.
|
||||
other things::
|
||||
|
||||
# echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \
|
||||
/sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
|
||||
|
@ -1241,7 +1247,7 @@
|
|||
any existing hist triggers beforehand).
|
||||
|
||||
Displaying the contents of the 'hist' file for the event shows the
|
||||
contents of all five histograms:
|
||||
contents of all five histograms::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
|
||||
|
||||
|
@ -1361,7 +1367,7 @@
|
|||
output of events generated by tracepoints contained inside inline
|
||||
functions, but names can be used in a hist trigger on any event.
|
||||
For example, these two triggers when hit will update the same 'len'
|
||||
field in the shared 'foo' histogram data:
|
||||
field in the shared 'foo' histogram data::
|
||||
|
||||
# echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \
|
||||
/sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
|
||||
|
@ -1369,7 +1375,7 @@
|
|||
/sys/kernel/debug/tracing/events/net/netif_rx/trigger
|
||||
|
||||
You can see that they're updating common histogram data by reading
|
||||
each event's hist files at the same time:
|
||||
each event's hist files at the same time::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist;
|
||||
cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
|
||||
|
@ -1482,7 +1488,7 @@
|
|||
And here's an example that shows how to combine histogram data from
|
||||
any two events even if they don't share any 'compatible' fields
|
||||
other than 'hitcount' and 'stacktrace'. These commands create a
|
||||
couple of triggers named 'bar' using those fields:
|
||||
couple of triggers named 'bar' using those fields::
|
||||
|
||||
# echo 'hist:name=bar:key=stacktrace:val=hitcount' > \
|
||||
/sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
|
||||
|
@ -1490,7 +1496,7 @@
|
|||
/sys/kernel/debug/tracing/events/net/netif_rx/trigger
|
||||
|
||||
And displaying the output of either shows some interesting if
|
||||
somewhat confusing output:
|
||||
somewhat confusing output::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
|
||||
# cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
|
||||
|
@ -1705,7 +1711,7 @@ to any event field.
|
|||
|
||||
Either keys or values can be saved and retrieved in this way. This
|
||||
creates a variable named 'ts0' for a histogram entry with the key
|
||||
'next_pid':
|
||||
'next_pid'::
|
||||
|
||||
# echo 'hist:keys=next_pid:vals=$ts0:ts0=common_timestamp ... >> \
|
||||
event/trigger
|
||||
|
@ -1721,40 +1727,40 @@ Because 'vals=' is used, the common_timestamp variable value above
|
|||
will also be summed as a normal histogram value would (though for a
|
||||
timestamp it makes little sense).
|
||||
|
||||
The below shows that a key value can also be saved in the same way:
|
||||
The below shows that a key value can also be saved in the same way::
|
||||
|
||||
# echo 'hist:timer_pid=common_pid:key=timer_pid ...' >> event/trigger
|
||||
|
||||
If a variable isn't a key variable or prefixed with 'vals=', the
|
||||
associated event field will be saved in a variable but won't be summed
|
||||
as a value:
|
||||
as a value::
|
||||
|
||||
# echo 'hist:keys=next_pid:ts1=common_timestamp ...' >> event/trigger
|
||||
|
||||
Multiple variables can be assigned at the same time. The below would
|
||||
result in both ts0 and b being created as variables, with both
|
||||
common_timestamp and field1 additionally being summed as values:
|
||||
common_timestamp and field1 additionally being summed as values::
|
||||
|
||||
# echo 'hist:keys=pid:vals=$ts0,$b:ts0=common_timestamp,b=field1 ...' >> \
|
||||
event/trigger
|
||||
|
||||
Note that variable assignments can appear either preceding or
|
||||
following their use. The command below behaves identically to the
|
||||
command above:
|
||||
command above::
|
||||
|
||||
# echo 'hist:keys=pid:ts0=common_timestamp,b=field1:vals=$ts0,$b ...' >> \
|
||||
event/trigger
|
||||
|
||||
Any number of variables not bound to a 'vals=' prefix can also be
|
||||
assigned by simply separating them with colons. Below is the same
|
||||
thing but without the values being summed in the histogram:
|
||||
thing but without the values being summed in the histogram::
|
||||
|
||||
# echo 'hist:keys=pid:ts0=common_timestamp:b=field1 ...' >> event/trigger
|
||||
|
||||
Variables set as above can be referenced and used in expressions on
|
||||
another event.
|
||||
|
||||
For example, here's how a latency can be calculated:
|
||||
For example, here's how a latency can be calculated::
|
||||
|
||||
# echo 'hist:keys=pid,prio:ts0=common_timestamp ...' >> event1/trigger
|
||||
# echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ...' >> event2/trigger
|
||||
|
@ -1764,7 +1770,7 @@ variable ts0. In the next line, ts0 is subtracted from the second
|
|||
event's timestamp to produce the latency, which is then assigned into
|
||||
yet another variable, 'wakeup_lat'. The hist trigger below in turn
|
||||
makes use of the wakeup_lat variable to compute a combined latency
|
||||
using the same key and variable from yet another event:
|
||||
using the same key and variable from yet another event::
|
||||
|
||||
# echo 'hist:key=pid:wakeupswitch_lat=$wakeup_lat+$switchtime_lat ...' >> event3/trigger
|
||||
|
||||
|
@ -1784,7 +1790,7 @@ separated by semicolons, to the tracing/synthetic_events file.
|
|||
|
||||
For instance, the following creates a new event named 'wakeup_latency'
|
||||
with 3 fields: lat, pid, and prio. Each of those fields is simply a
|
||||
variable reference to a variable on another event:
|
||||
variable reference to a variable on another event::
|
||||
|
||||
# echo 'wakeup_latency \
|
||||
u64 lat; \
|
||||
|
@ -1793,13 +1799,13 @@ variable reference to a variable on another event:
|
|||
/sys/kernel/debug/tracing/synthetic_events
|
||||
|
||||
Reading the tracing/synthetic_events file lists all the currently
|
||||
defined synthetic events, in this case the event defined above:
|
||||
defined synthetic events, in this case the event defined above::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/synthetic_events
|
||||
wakeup_latency u64 lat; pid_t pid; int prio
|
||||
|
||||
An existing synthetic event definition can be removed by prepending
|
||||
the command that defined it with a '!':
|
||||
the command that defined it with a '!'::
|
||||
|
||||
# echo '!wakeup_latency u64 lat pid_t pid int prio' >> \
|
||||
/sys/kernel/debug/tracing/synthetic_events
|
||||
|
@ -1811,13 +1817,13 @@ 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:
|
||||
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:
|
||||
and looks and behaves just like any other event::
|
||||
|
||||
# ls /sys/kernel/debug/tracing/events/synthetic/wakeup_latency
|
||||
enable filter format hist id trigger
|
||||
|
@ -1872,7 +1878,7 @@ hist trigger specification.
|
|||
As an example the below defines a simple synthetic event and uses
|
||||
a variable defined on the sched_wakeup_new event as a parameter
|
||||
when invoking the synthetic event. Here we define the synthetic
|
||||
event:
|
||||
event::
|
||||
|
||||
# echo 'wakeup_new_test pid_t pid' >> \
|
||||
/sys/kernel/debug/tracing/synthetic_events
|
||||
|
@ -1884,7 +1890,7 @@ hist trigger specification.
|
|||
variable and specifies an onmatch() action that generates a
|
||||
wakeup_new_test synthetic event whenever a sched_wakeup_new event
|
||||
occurs, which because of the 'if comm == "cyclictest"' filter only
|
||||
happens when the executable is cyclictest:
|
||||
happens when the executable is cyclictest::
|
||||
|
||||
# echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\
|
||||
wakeup_new_test($testpid) if comm=="cyclictest"' >> \
|
||||
|
@ -1892,28 +1898,28 @@ hist trigger specification.
|
|||
|
||||
Creating and displaying a histogram based on those events is now
|
||||
just a matter of using the fields and new synthetic event in the
|
||||
tracing/events/synthetic directory, as usual:
|
||||
tracing/events/synthetic directory, as usual::
|
||||
|
||||
# echo 'hist:keys=pid:sort=pid' >> \
|
||||
/sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/trigger
|
||||
|
||||
Running 'cyclictest' should cause wakeup_new events to generate
|
||||
wakeup_new_test synthetic events which should result in histogram
|
||||
output in the wakeup_new_test event's hist file:
|
||||
output in the wakeup_new_test event's hist file::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/hist
|
||||
|
||||
A more typical usage would be to use two events to calculate a
|
||||
latency. The following example uses a set of hist triggers to
|
||||
produce a 'wakeup_latency' histogram:
|
||||
produce a 'wakeup_latency' histogram.
|
||||
|
||||
First, we define a 'wakeup_latency' synthetic event:
|
||||
First, we define a 'wakeup_latency' synthetic event::
|
||||
|
||||
# echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \
|
||||
/sys/kernel/debug/tracing/synthetic_events
|
||||
|
||||
Next, we specify that whenever we see a sched_waking event for a
|
||||
cyclictest thread, save the timestamp in a 'ts0' variable:
|
||||
cyclictest thread, save the timestamp in a 'ts0' variable::
|
||||
|
||||
# echo 'hist:keys=$saved_pid:saved_pid=pid:ts0=common_timestamp.usecs \
|
||||
if comm=="cyclictest"' >> \
|
||||
|
@ -1922,7 +1928,7 @@ hist trigger specification.
|
|||
Then, when the corresponding thread is actually scheduled onto the
|
||||
CPU by a sched_switch event, calculate the latency and use that
|
||||
along with another variable and an event field to generate a
|
||||
wakeup_latency synthetic event:
|
||||
wakeup_latency synthetic event::
|
||||
|
||||
# echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\
|
||||
onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,\
|
||||
|
@ -1930,14 +1936,14 @@ hist trigger specification.
|
|||
/sys/kernel/debug/tracing/events/sched/sched_switch/trigger
|
||||
|
||||
We also need to create a histogram on the wakeup_latency synthetic
|
||||
event in order to aggregate the generated synthetic event data:
|
||||
event in order to aggregate the generated synthetic event data::
|
||||
|
||||
# echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \
|
||||
/sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
|
||||
|
||||
Finally, once we've run cyclictest to actually generate some
|
||||
events, we can see the output by looking at the wakeup_latency
|
||||
synthetic event's hist file:
|
||||
synthetic event's hist file::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist
|
||||
|
||||
|
@ -1961,7 +1967,7 @@ hist trigger specification.
|
|||
back to that pid, the timestamp difference is calculated. If the
|
||||
resulting latency, stored in wakeup_lat, exceeds the current
|
||||
maximum latency, the values specified in the save() fields are
|
||||
recorded:
|
||||
recorded::
|
||||
|
||||
# echo 'hist:keys=pid:ts0=common_timestamp.usecs \
|
||||
if comm=="cyclictest"' >> \
|
||||
|
@ -1975,7 +1981,7 @@ hist trigger specification.
|
|||
|
||||
When the histogram is displayed, the max value and the saved
|
||||
values corresponding to the max are displayed following the rest
|
||||
of the fields:
|
||||
of the fields::
|
||||
|
||||
# cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
|
||||
{ next_pid: 2255 } hitcount: 239
|
||||
|
@ -2002,7 +2008,7 @@ ring buffer. This can also act like an event, by writing into the trigger
|
|||
file located in /sys/kernel/tracing/events/ftrace/print/
|
||||
|
||||
Modifying cyclictest to write into the trace_marker file before it sleeps
|
||||
and after it wakes up, something like this:
|
||||
and after it wakes up, something like this::
|
||||
|
||||
static void traceputs(char *str)
|
||||
{
|
||||
|
@ -2013,13 +2019,13 @@ static void traceputs(char *str)
|
|||
write(tracemark_fd, str, strlen(str));
|
||||
}
|
||||
|
||||
And later add something like:
|
||||
And later add something like::
|
||||
|
||||
traceputs("start");
|
||||
clock_nanosleep(...);
|
||||
traceputs("end");
|
||||
|
||||
We can make a histogram from this:
|
||||
We can make a histogram from this::
|
||||
|
||||
# cd /sys/kernel/tracing
|
||||
# echo 'latency u64 lat' > synthetic_events
|
||||
|
@ -2034,7 +2040,7 @@ it will call the "latency" synthetic event with the calculated latency as its
|
|||
parameter. Finally, a histogram is added to the latency synthetic event to
|
||||
record the calculated latency along with the pid.
|
||||
|
||||
Now running cyclictest with:
|
||||
Now running cyclictest with::
|
||||
|
||||
# ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000
|
||||
|
||||
|
@ -2049,7 +2055,7 @@ Now running cyclictest with:
|
|||
|
||||
Note, the -b 1000 is used just to make --tracemark available.
|
||||
|
||||
Then we can see the histogram created by this with:
|
||||
Then we can see the histogram created by this with::
|
||||
|
||||
# cat events/synthetic/latency/hist
|
||||
# event histogram
|
||||
|
@ -2350,7 +2356,7 @@ will be at 200 microseconds.
|
|||
|
||||
But this could easily be done in userspace. To make this even more
|
||||
interesting, we can mix the histogram between events that happened in the
|
||||
kernel with trace_marker.
|
||||
kernel with trace_marker::
|
||||
|
||||
# cd /sys/kernel/tracing
|
||||
# echo 'latency u64 lat' > synthetic_events
|
||||
|
@ -2362,7 +2368,7 @@ The difference this time is that instead of using the trace_marker to start
|
|||
the latency, the sched_waking event is used, matching the common_pid for the
|
||||
trace_marker write with the pid that is being woken by sched_waking.
|
||||
|
||||
After running cyclictest again with the same parameters, we now have:
|
||||
After running cyclictest again with the same parameters, we now have::
|
||||
|
||||
# cat events/synthetic/latency/hist
|
||||
# event histogram
|
|
@ -18,6 +18,7 @@ Linux Tracing Technologies
|
|||
events-nmi
|
||||
events-msr
|
||||
mmiotrace
|
||||
histogram
|
||||
hwlat_detector
|
||||
intel_th
|
||||
stm
|
||||
|
|
|
@ -605,7 +605,7 @@ config HIST_TRIGGERS
|
|||
Inter-event tracing of quantities such as latencies is also
|
||||
supported using hist triggers under this option.
|
||||
|
||||
See Documentation/trace/histogram.txt.
|
||||
See Documentation/trace/histogram.rst.
|
||||
If in doubt, say N.
|
||||
|
||||
config MMIOTRACE_TEST
|
||||
|
|
Loading…
Reference in New Issue