Documentation/trace/histogram.rst

24   The format of a hist trigger is as follows::
26         hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>]
50   key.  If a hist trigger is given a name using the 'name' parameter,
60   'hist' triggers add a 'hist' file to each event's subdirectory.
61   Reading the 'hist' file for the event will dump the hash table in
62   its entirety to stdout.  If there are multiple hist triggers
98   A typical usage scenario would be the following to enable a hist
101     # echo 'hist:keys=skbaddr.hex:vals=len' > \
104     # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
106     # echo '!hist:keys=skbaddr.hex:vals=len' > \
110   currently attached hist trigger.  This information is also displayed
111   at the top of the 'hist' file when read.
126   The 'pause' parameter can be used to pause an existing hist trigger
127   or to start a hist trigger but not log any events until told to do
129   hist trigger.
131   The 'clear' parameter will clear the contents of a running hist
143   hist trigger.  Any number of enable_hist and disable_hist triggers
158   would be to first set up a paused hist trigger on some event,
159   followed by an enable_hist/disable_hist pair that turns the hist
162    # echo 'hist:keys=skbaddr.hex:vals=len:pause' > \
171   The above sets up an initially paused hist trigger which is unpaused
173   which stops aggregating when the process exits and the hist trigger
183   keys or values in a hist trigger.  These look like and behave as if
200   For some error conditions encountered when invoking a hist trigger
205 6.2 'hist' trigger examples
209   event.  The fields that can be used for the hist trigger are listed
227   We'll start by creating a hist trigger that generates a simple table
231     # echo 'hist:key=call_site:val=bytes_req' > \
234   This tells the tracing system to create a 'hist' trigger using the
238   the hist trigger that for each unique entry (call_site) in the
242   We'll let it run for awhile and then dump the contents of the 'hist'
246     # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
247     # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
287     hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
313   To turn the hist trigger off, simply call up the trigger in the
316     # echo '!hist:key=call_site:val=bytes_req' > \
324     # echo 'hist:key=call_site.hex:val=bytes_req' > \
327     # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
328     # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active]
369     # echo 'hist:key=call_site.sym:val=bytes_req' > \
372     # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
373     # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active]
419     # echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \
422     # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
423 …# trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active]
460     # echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \
463     # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
464 …# trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 …
499     # echo 'hist:keys=call_site.sym:values=bytes_req,bytes_alloc:sort=bytes_alloc.descending' > \
502     # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
503 …# trigger info: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:siz…
537   the hist trigger display symbolic call_sites, we can have the hist
542     # echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \
553     # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
554 …# trigger info: hist:keys=stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active]
645   If you key a hist trigger on common_pid, in order for example to
651     # echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \
654     # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/hist
655 …  # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active]
686   Similarly, if you key a hist trigger on syscall id, for example to
692     # echo 'hist:key=id.syscall:val=hitcount' > \
695     # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist
696     # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active]
746     # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \
749     # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist
750 …# trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:si…
796     # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount if id == 16' > \
799     # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist
800 …# trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:si…
839     # echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \
842     # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/hist
843 …# trigger info: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:siz…
887   demonstrates how you can manually pause and continue a hist trigger.
892     # echo 'hist:key=child_comm:val=hitcount:size=256' > \
895     # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
896     # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active]
924   If we want to pause the hist trigger, we can simply append :pause to
928     # echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \
931     # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
932     # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [paused]
965     # echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \
968     # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
969     # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active]
998   The previous example showed how to start and stop a hist trigger by
999   appending 'pause' and 'continue' to the hist trigger command.  A
1000   hist trigger can also be started in a paused state by initially
1008   it is possible to automatically start and stop a hist trigger based
1019     # echo 'hist:key=stacktrace:vals=len:pause' > \
1024   this new trigger is that it will 'unpause' the hist trigger we just
1042   trigger filter matches 'comm==wget', the netif_receive_skb hist
1047   wget command and then listing the 'hist' file will display the
1052     # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1053     # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused]
1129   The 'clear' hist trigger param can be used to clear the hash table.
1135     # echo 'hist:key=stacktrace:vals=len:clear' >> \
1139   the hist file::
1141     # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1142     # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused]
1163   one enabling/disabling the hist aggregation and the other
1182   Displaying the 'hist' file should show something similar to what you
1213   The following example demonstrates how multiple hist triggers can be
1219     # echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \
1221     # echo 'hist:keys=skbaddr.hex:vals=len if len > 4096' >> \
1223     # echo 'hist:keys=skbaddr.hex:vals=len if len == 256' >> \
1225     # echo 'hist:keys=skbaddr.hex:vals=len' >> \
1227     # echo 'hist:keys=len:vals=common_preempt_count' >> \
1232   nonsensical trigger.  Note that in order to append multiple hist
1234   append them ('>' will also add the new hist trigger, but will remove
1235   any existing hist triggers beforehand).
1237   Displaying the contents of the 'hist' file for the event shows the
1240     # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1244 …  # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active]
1271     # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1308 …# trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [act…
1320 …# trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [act…
1344 …# trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active]
1356   functions, but names can be used in a hist trigger on any event.
1360     # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \
1362     # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \
1366   each event's hist files at the same time::
1368     # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist;
1369       cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
1373 …  # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1425 …  # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1481     # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \
1483     # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \
1489     # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
1490     # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
1494     # trigger info: hist:name=bar:keys=stacktrace:vals=hitcount:sort=hitcount:size=2048 [active]
1601 2.2 Inter-event hist triggers
1604 Inter-event hist triggers are hist triggers that combine values from
1622 Normally, a hist trigger specification consists of a (possibly
1629 The inter-event hist trigger extension allows fields from multiple
1632 features have been added to the hist trigger support:
1643     histogram on either event (so having the 'hist' file for either
1672 trace clocks instead, using the "clock=XXX" hist trigger attribute,
1704   # echo 'hist:keys=next_pid:vals=$ts0:ts0=common_timestamp ... >> \
1720   # echo 'hist:timer_pid=common_pid:key=timer_pid ...' >> event/trigger
1726   # echo 'hist:keys=next_pid:ts1=common_timestamp ...' >> event/trigger
1732   # echo 'hist:keys=pid:vals=$ts0,$b:ts0=common_timestamp,b=field1 ...' >> \
1739   # echo 'hist:keys=pid:ts0=common_timestamp,b=field1:vals=$ts0,$b ...' >> \
1746   # echo 'hist:keys=pid:ts0=common_timestamp:b=field1 ...' >> event/trigger
1753   # echo 'hist:keys=pid,prio:ts0=common_timestamp ...' >> event1/trigger
1754   # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ...' >> event2/trigger
1759 yet another variable, 'wakeup_lat'.  The hist trigger below in turn
1763   # echo 'hist:key=pid:wakeupswitch_lat=$wakeup_lat+$switchtime_lat ...' >> event3/trigger
1768 Synthetic events are user-defined events generated from hist trigger
1820 instantiated in the event subsystem - for this to happen, a 'hist
1823 how that is done using hist trigger 'onmatch' action). Once that is
1828   # echo 'hist:keys=pid,prio,lat.log2:sort=pid,lat' >> \
1835         enable  filter  format  hist  id  trigger
1838 output can be displayed by reading the event's 'hist' file.
1843 A hist trigger 'action' is a function that's executed (in most cases
1846 When a histogram entry is added or updated, a hist trigger 'handler'
1856 that handler.action pair between colons in the hist trigger
1861 if a given handler.action combination isn't supported, the hist
1891     list)' hist trigger action is invoked whenever an event matches
1944     The following hist trigger both defines the missing testpid
1950       # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\
1956     # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\
1964       # echo 'hist:keys=pid:sort=pid' >> \
1969     output in the wakeup_new_test event's hist file::
1971       # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/hist
1974     latency.  The following example uses a set of hist triggers to
1985       # echo 'hist:keys=$saved_pid:saved_pid=pid:ts0=common_timestamp.usecs \
1994       # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\
2002       # echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \
2007     synthetic event's hist file::
2009       # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist
2013     The 'onmax(var).save(field,...)' hist trigger action is invoked
2019     maximum for that hist trigger entry.  This allows context from the
2024     As an example the below defines a couple of hist triggers, one for
2033       # echo 'hist:keys=pid:ts0=common_timestamp.usecs \
2037       # echo 'hist:keys=next_pid:\
2047       # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
2066     The 'onmax(var).snapshot()' hist trigger action is invoked
2072     maximum for any hist trigger entry.
2083     As an example the below defines a couple of hist triggers, one for
2095     # echo 'hist:keys=pid:ts0=common_timestamp.usecs \
2099     # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \
2112     # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
2175     The 'onchange(var).save(field,...)' hist trigger action is invoked
2181     hist trigger entry.  This allows context from the event that
2188     The 'onchange(var).snapshot()' hist trigger action is invoked
2194     hist trigger entry.
2204     As an example the below defines a hist trigger on the tcp_probe
2215     # echo 'hist:keys=dport:cwnd=snd_cwnd: \
2227       # cat /sys/kernel/debug/tracing/events/tcp/tcp_probe/hist
2301 …# echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/t…
2302 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) i…
2303  # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
2329  # cat events/synthetic/latency/hist
2332  # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
2632  # echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
2633 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($…
2634  # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
2642  # cat events/synthetic/latency/hist
2645  # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]