tracing: Add features for event-fork and histograms
Subsystems (4)
Steven Rostedt
maintainercover tracing: Add features for event-fork and histograms
git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
for-next
Head SHA1: d50c744ecde7ee3ba4d7ffb0e1c55e7a2f6bbc8e
Masami Hiramatsu (3):
kselftests/ftrace : Add event trigger testcases kselftests/ftrace: Add hist trigger testcases kselftests/ftrace: Add a test for log2 modifier of hist trigger
Namhyung Kim (2):
tracing: Support string type key properly
tracing: Add hist trigger 'log2' modifier
Steven Rostedt (3):
tracing: Rename check_ignore_pid() to ignore_this_task()
tracing: Use pid bitmap instead of a pid array for set_event_pid
tracing: Add infrastructure to allow set_event_pid to follow children
Steven Rostedt (Red Hat) (3):
tracing: Update the documentation to describe "event-fork" option
tracing: Fix TRACING_MAP Kconfig
tracing: Fix unsigned comparison to zero in hist trigger code
Tom Zanussi (19):
tracing: Add lock-free tracing_map
tracing: Update some tracing_map constants and comments
tracing: Add 'hist' event trigger command
tracing: Add hist trigger support for multiple values ('vals=' param)
tracing: Add hist trigger support for compound keys
tracing: Add hist trigger support for user-defined sorting ('sort=' param)
tracing: Add hist trigger support for pausing and continuing a trace
tracing: Add hist trigger support for clearing a trace
tracing: Add hist trigger 'hex' modifier for displaying numeric fields
tracing: Add hist trigger 'sym' and 'sym-offset' modifiers
tracing: Add hist trigger 'execname' modifier
tracing: Add hist trigger 'syscall' modifier
tracing: Add hist trigger support for stacktraces as keys
tracing: Remove restriction on string position in hist trigger keys
tracing: Add enable_hist/disable_hist triggers
tracing: Add 'hist' trigger Documentation
tracing: Add support for multiple hist triggers per event
tracing: Add support for named triggers
tracing: Add support for named hist triggers
----
Documentation/trace/events.txt | 1555 +++++++++++++++++ Documentation/trace/ftrace.txt | 34 +- include/linux/trace_events.h | 2 + kernel/trace/Kconfig | 26 + kernel/trace/Makefile | 2 + kernel/trace/trace.c | 60 + kernel/trace/trace.h | 59 +- kernel/trace/trace_events.c | 301 ++-- kernel/trace/trace_events_hist.c | 1752 ++++++++++++++++++++ kernel/trace/trace_events_trigger.c | 215 ++- kernel/trace/tracing_map.c | 1058 ++++++++++++ kernel/trace/tracing_map.h | 283 ++++ tools/testing/selftests/ftrace/test.d/functions | 9 + .../ftrace/test.d/trigger/trigger-eventonoff.tc | 64 + .../ftrace/test.d/trigger/trigger-filter.tc | 59 + .../ftrace/test.d/trigger/trigger-hist-mod.tc | 75 + .../ftrace/test.d/trigger/trigger-hist.tc | 83 + .../ftrace/test.d/trigger/trigger-multihist.tc | 73 + .../ftrace/test.d/trigger/trigger-snapshot.tc | 56 + .../ftrace/test.d/trigger/trigger-stacktrace.tc | 53 + .../ftrace/test.d/trigger/trigger-traceonoff.tc | 58 + 21 files changed, 5706 insertions(+), 171 deletions(-) create mode 100644 kernel/trace/trace_events_hist.c create mode 100644 kernel/trace/tracing_map.c create mode 100644 kernel/trace/tracing_map.h create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-eventonoff.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-filter.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-mod.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-multihist.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-snapshot.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-stacktrace.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-traceonoff.tc
Steven Rostedt
maintainerPATCH 1/30 tracing: Rename check_ignore_pid() to ignore_this_task()
From: Steven Rostedt <[email protected]>
The name "check_ignore_pid" is confusing in trying to figure out if the pid should be ignored or not. Rename it to "ignore_this_task" which is pretty straight forward, as a task (not a pid) is passed in, and should if true should be ignored.
--- kernel/trace/trace_events.c | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-)
kernel/trace/trace_events.c +7 -7
@@ -484,7 +484,7 @@ static int cmp_pid(const void *key, const void *elt) }static bool -check_ignore_pid (struct trace_pid_list *filtered_pids,struct task_struct *task) +ignore_this_task (struct trace_pid_list *filtered_pids,struct task_struct *task) {pid_t search_pid;pid_t *pid;
@@ -517,8 +517,8 @@ event_filter_pid_sched_switch_probe_pre(void *data, bool preempt, pid_list =rcu_dereference_sched (tr->filtered_pids);this_cpu_write (tr->trace_buffer.data->ignore_pid, -check_ignore_pid (pid_list, prev) && -check_ignore_pid (pid_list, next)); +ignore_this_task (pid_list, prev) && +ignore_this_task (pid_list, next)); } static void
@@ -531,7 +531,7 @@ event_filter_pid_sched_switch_probe_post(void *data, bool preempt, pid_list =rcu_dereference_sched (tr->filtered_pids);this_cpu_write (tr->trace_buffer.data->ignore_pid, -check_ignore_pid (pid_list, next)); +ignore_this_task (pid_list, next)); } static void
@@ -547,7 +547,7 @@ event_filter_pid_sched_wakeup_probe_pre(void *data, struct task_struct *task) pid_list =rcu_dereference_sched (tr->filtered_pids);this_cpu_write (tr->trace_buffer.data->ignore_pid, -check_ignore_pid (pid_list, task)); +ignore_this_task (pid_list, task)); } static void
@@ -564,7 +564,7 @@ event_filter_pid_sched_wakeup_probe_post(void *data, struct task_struct *task)/* Set tracing if current is enabled */ this_cpu_write (tr->trace_buffer.data->ignore_pid, -check_ignore_pid (pid_list, current)); +ignore_this_task (pid_list, current)); }static void __ftrace_clear_event_pids (struct trace_array *tr)
@@ -1561,7 +1561,7 @@ static void ignore_task_cpu(void *data) mutex_is_locked(&event_mutex));this_cpu_write (tr->trace_buffer.data->ignore_pid, -check_ignore_pid (pid_list, current)); +ignore_this_task (pid_list, current)); } static ssize_t
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 2/30 tracing: Use pid bitmap instead of a pid array for set_event_pid
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
In order to add the ability to let tasks that are filtered by the events have their children also be traced on fork (and then not traced on exit), convert the array into a pid bitmask. Most of the time the number of pids is only 32768 pids or a 4k bitmask, which is the same size as the default list currently is, and that list could grow if more pids are listed.
This also greatly simplifies the code.
--- kernel/trace/trace.h | 5 +- kernel/trace/trace_events.c | 221 ++++++++++++++++++++------------------------ 2 files changed, 102 insertions(+), 124 deletions(-)
kernel/trace/trace.h +2 -3
@@ -177,9 +177,8 @@ struct trace_options { };struct trace_pid_list { -unsigned int nr_pids; -int order; -pid_t *pids; +int pid_max; +unsigned long *pids; };/*
kernel/trace/trace_events.c +100 -121
342 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 3/30 tracing: Add infrastructure to allow set_event_pid to follow children
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
Add the infrastructure needed to have the PIDs in set_event_pid to automatically add PIDs of the children of the tasks that have their PIDs in set_event_pid. This will also remove PIDs from set_event_pid when a task exits
This is implemented by adding hooks into the fork and exit tracepoints. On fork, the PIDs are added to the list, and on exit, they are removed.
Add a new option called event_fork that when set, PIDs in set_event_pid will automatically get their children PIDs added when they fork, as well as any task that exits will have its PID removed from set_event_pid.
This works for instances as well.
--- kernel/trace/trace.c | 3 ++ kernel/trace/trace.h | 2 ++ kernel/trace/trace_events.c | 84 +++++++++++++++++++++++++++++++++++++++------ 3 files changed, 79 insertions(+), 10 deletions(-)
kernel/trace/trace.c +3 -0
@@ -3571,6 +3571,9 @@ int set_tracer_flag(struct trace_array *tr, unsigned int mask, int enabled)if (mask ==TRACE_ITER_RECORD_CMD )trace_event_enable_cmd_record (enabled); +if (mask ==TRACE_ITER_EVENT_FORK ) +trace_event_follow_fork (tr, enabled); +if (mask ==TRACE_ITER_OVERWRITE ) {ring_buffer_change_overwrite (tr->trace_buffer.buffer, enabled);#ifdef CONFIG_TRACER_MAX_TRACE
kernel/trace/trace.h +2 -0
@@ -655,6 +655,7 @@ static inline void __trace_stack(struct trace_array *tr, unsigned long flags,extern cycle_t ftrace_now (int cpu);extern void trace_find_cmdline (int pid,char comm[]); +extern void trace_event_follow_fork (struct trace_array *tr,bool enable);#ifdef CONFIG_DYNAMIC_FTRACE extern unsigned long ftrace_update_tot_cnt;
@@ -966,6 +967,7 @@ extern int trace_get_user(struct trace_parser *parser, const char __user *ubuf,C (STOP_ON_FREE ,"disable_on_free" ), \C (IRQ_INFO ,"irq-info" ), \C (MARKERS ,"markers" ), \ +C (EVENT_FORK ,"event-fork" ), \ FUNCTION_FLAGS \FGRAPH_FLAGS \STACK_FLAGS \
kernel/trace/trace_events.c +74 -10
101 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 4/30 tracing: Update the documentation to describe "event-fork" option
In reply to Steven RostedtFrom: "Steven Rostedt (Red Hat)" <[email protected]>
Add documentation to the ftrace.txt file in Documentation to describe the event-fork option. Also add the missing "display-graph" option now that it shows up in the trace_options file (from a previous commit).
--- Documentation/trace/ftrace.txt | 34 ++++++++++++++++++++++++---------- 1 file changed, 24 insertions(+), 10 deletions(-)
Documentation/trace/ftrace.txt +24 -10
@@ -210,6 +210,11 @@ of ftrace. Here is a list of some of the key files: Note, sched_switch and sched_wake_up will also trace events listed in this file. + To have the PIDs of children of tasks with their PID in this file + added on fork, enable the "event-fork" option. That option will also + cause the PIDs of tasks to be removed from this file when the task + exits. + set_graph_function: Set a "trigger" function where tracing should start
@@ -725,16 +730,14 @@ noraw nohex nobin noblock -nostacktrace trace_printk -noftrace_preempt nobranch annotate nouserstacktrace nosym-userobj noprintk-msg-only context-info -latency-format +nolatency-format sleep-time graph-time record-cmd
@@ -742,7 +745,10 @@ overwrite nodisable_on_free irq-info markers +noevent-fork function-trace +nodisplay-graph +nostacktrace To disable one of the options, echo in the option prepended with "no".
@@ -796,11 +802,6 @@ Here are the available options: block - When set, reading trace_pipe will not block when polled. - stacktrace - This is one of the options that changes the trace - itself. When a trace is recorded, so is the stack - of functions. This allows for back traces of - trace sites. - trace_printk - Can disable trace_printk() from writing into the buffer. branch - Enable branch tracing with the tracer.
@@ -897,6 +898,10 @@ x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] When disabled, the trace_marker will error with EINVAL on write. + event-fork - When set, tasks with PIDs listed in set_event_pid will have + the PIDs of their children added to set_event_pid when those + tasks fork. Also, when tasks with PIDs in set_event_pid exit, + their PIDs will be removed from the file. function-trace - The latency tracers will enable function tracing if this option is enabled (default it is). When
@@ -904,8 +909,17 @@ x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6] functions. This keeps the overhead of the tracer down when performing latency tests. - Note: Some tracers have their own options. They only appear - when the tracer is active. + display-graph - When set, the latency tracers (irqsoff, wakeup, etc) will + use function graph tracing instead of function tracing. + + stacktrace - This is one of the options that changes the trace + itself. When a trace is recorded, so is the stack + of functions. This allows for back traces of + trace sites. + + Note: Some tracers have their own options. They only appear in this + file when the tracer is active. They always appear in the + options directory.
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 5/30 tracing: Add lock-free tracing_map
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Add tracing_map, a special-purpose lock-free map for tracing.
tracing_map is designed to aggregate or 'sum' one or more values associated with a specific object of type tracing_map_elt, which is associated by the map to a given key.
It provides various hooks allowing per-tracer customization and is separated out into a separate file in order to allow it to be shared between multiple tracers, but isn't meant to be generally used outside of that context.
The tracing_map implementation was inspired by lock-free map algorithms originated by Dr. Cliff Click:
http://www.azulsystems.com/blog/cliff/2007-03-26-non-blocking-hashtable
http://www.azulsystems.com/events/javaone_2007/2007_LockFreeHash.pdf
--- kernel/trace/Kconfig | 13 + kernel/trace/Makefile | 1 + kernel/trace/tracing_map.c | 1058 ++++++++++++++++++++++++++++++++++++++++++++ kernel/trace/tracing_map.h | 282 ++++++++++++ 4 files changed, 1354 insertions(+) create mode 100644 kernel/trace/tracing_map.c create mode 100644 kernel/trace/tracing_map.h
kernel/trace/Kconfig +13 -0
@@ -528,6 +528,19 @@ config MMIOTRACE See Documentation/trace/mmiotrace.txt. If you are not helping to develop drivers, say N. +config TRACING_MAP + bool + depends on ARCH_HAVE_NMI_SAFE_CMPXCHG + default n + help + tracing_map is a special-purpose lock-free map for tracing, + separated out as a stand-alone facility in order to allow it + to be shared between multiple tracers. It isn't meant to be + generally used outside of that context, and is normally + selected by tracers that use it. + + If in doubt, say N. + config MMIOTRACE_TEST tristate "Test module for mmiotrace" depends on MMIOTRACE && m
kernel/trace/Makefile +1 -0
@@ -31,6 +31,7 @@ obj-$(CONFIG_TRACING) += trace_output.o obj-$(CONFIG_TRACING) += trace_seq.o obj-$(CONFIG_TRACING) += trace_stat.o obj-$(CONFIG_TRACING) += trace_printk.o +obj-$(CONFIG_TRACING_MAP) += tracing_map.o obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o obj-$(CONFIG_FUNCTION_TRACER) += trace_functions.o obj-$(CONFIG_IRQSOFF_TRACER) += trace_irqsoff.o
kernel/trace/tracing_map.c new file +1058 -0
1,058 lines not on this page · raw message
kernel/trace/tracing_map.h new file +282 -0
282 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 6/30 tracing: Fix TRACING_MAP Kconfig
In reply to Steven RostedtFrom: "Steven Rostedt (Red Hat)" <[email protected]>
The config option for TRACING_MAP has "default n", which is not needed because the default of configs is 'n'.
Also, since the TRACING_MAP has no config prompt, there's no reason to include "If in doubt, say N" in the help text.
Fixed a typo in the comments of tracing_map.h.
--- kernel/trace/Kconfig | 3 --- kernel/trace/tracing_map.h | 2 +- 2 files changed, 1 insertion(+), 4 deletions(-)
kernel/trace/Kconfig +0 -3
@@ -531,7 +531,6 @@ config MMIOTRACE config TRACING_MAP bool depends on ARCH_HAVE_NMI_SAFE_CMPXCHG - default n help tracing_map is a special-purpose lock-free map for tracing, separated out as a stand-alone facility in order to allow it
@@ -539,8 +538,6 @@ config TRACING_MAP generally used outside of that context, and is normally selected by tracers that use it. - If in doubt, say N. - config MMIOTRACE_TEST tristate "Test module for mmiotrace" depends on MMIOTRACE && m
kernel/trace/tracing_map.h +1 -1
@@ -46,7 +46,7 @@ typedef int (*tracing_map_cmp_fn_t) (void *val_a, void *val_b);* That unique element now in the tracing_map_entry's 'val' field is * an instance of tracing_map_elt, where 'elt' in the latter part of * that variable name is short for 'element'. The purpose of a -* tracing_map_elt is to hold values specific to the the particular +* tracing_map_elt is to hold values specific to the particular * 32-bit hashed key it's assocated with. Things such as the unique * set of aggregated sums associated with the 32-bit hashed key, along * with a copy of the full key associated with the entry, and which
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 7/30 tracing: Update some tracing_map constants and comments
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Make it clear exactly how many keys and values are supported through better defines, and add 1 to the vals count, since normally clients want support for at least a hitcount and two other values.
Also, note the error return value for tracing_map_add_key/val_field() in the comments.
--- kernel/trace/tracing_map.c | 4 ++-- kernel/trace/tracing_map.h | 5 +++-- 2 files changed, 5 insertions(+), 4 deletions(-)
kernel/trace/tracing_map.c +2 -2
@@ -163,7 +163,7 @@ static int tracing_map_add_field(struct tracing_map *map,* tracing_map_update_sum() or reading it via tracing_map_read_sum(). * * Return: The index identifying the field in the map and associated -* tracing_map_elts. +* tracing_map_elts, or -EINVAL on error. */ int tracing_map_add_sum_field (struct tracing_map *map) {
@@ -184,7 +184,7 @@ int tracing_map_add_sum_field(struct tracing_map *map)* the key referenced by this key field resides. * * Return: The index identifying the field in the map and associated -* tracing_map_elts. +* tracing_map_elts, or -EINVAL on error. */ int tracing_map_add_key_field(struct tracing_map *map, unsigned int offset,
kernel/trace/tracing_map.h +3 -2
@@ -5,9 +5,10 @@#define TRACING_MAP_BITS_MAX 17#define TRACING_MAP_BITS_MIN 7 -#define TRACING_MAP_FIELDS_MAX 4#define TRACING_MAP_KEYS_MAX 2 - +#define TRACING_MAP_VALS_MAX 3 +#define TRACING_MAP_FIELDS_MAX (TRACING_MAP_KEYS_MAX + \ + TRACING_MAP_VALS_MAX)#define TRACING_MAP_SORT_KEYS_MAX 2typedef int (*tracing_map_cmp_fn_t ) (void *val_a,void *val_b);
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 8/30 tracing: Add hist event trigger command
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
'hist' triggers allow users to continually aggregate trace events, which can then be viewed afterwards by simply reading a 'hist' file containing the aggregation in a human-readable format.
The basic idea is very simple and boils down to a mechanism whereby trace events, rather than being exhaustively dumped in raw form and viewed directly, are automatically 'compressed' into meaningful tables completely defined by the user.
This is done strictly via single-line command-line commands and without the aid of any kind of programming language or interpreter.
A surprising number of typical use cases can be accomplished by users via this simple mechanism. In fact, a large number of the tasks that users typically do using the more complicated script-based tracing tools, at least during the initial stages of an investigation, can be accomplished by simply specifying a set of keys and values to be used in the creation of a hash table.
The Linux kernel trace event subsystem happens to provide an extensive list of keys and values ready-made for such a purpose in the form of the event format files associated with each trace event. By simply consulting the format file for field names of interest and by plugging them into the hist trigger command, users can create an endless number of useful aggregations to help with investigating various properties of the system. See Documentation/trace/events.txt for examples.
hist triggers are implemented on top of the existing event trigger infrastructure, and as such are consistent with the existing triggers from a user's perspective as well.
The basic syntax follows the existing trigger syntax. Users start an aggregation by writing a 'hist' trigger to the event of interest's trigger file:
# echo hist:keys=xxx [ if filter] > event/trigger
Once a hist trigger has been set up, by default it continually aggregates every matching event into a hash table using the event key and a value field named 'hitcount'.
To view the aggregation at any point in time, simply read the 'hist' file in the same directory as the 'trigger' file:
# cat event/hist
The detailed syntax provides additional options for user control, and is described exhaustively in Documentation/trace/events.txt and in the virtual tracing/README file in the tracing subsystem.
--- include/linux/trace_events.h | 1 + kernel/trace/Kconfig | 16 + kernel/trace/Makefile | 1 + kernel/trace/trace.c | 17 + kernel/trace/trace.h | 7 + kernel/trace/trace_events.c | 4 + kernel/trace/trace_events_hist.c | 849 ++++++++++++++++++++++++++++++++++++ kernel/trace/trace_events_trigger.c | 1 + 8 files changed, 896 insertions(+) create mode 100644 kernel/trace/trace_events_hist.c
include/linux/trace_events.h +1 -0
@@ -407,6 +407,7 @@ enum event_trigger_type {ETT_SNAPSHOT = (1 <<1 ),ETT_STACKTRACE = (1 <<2 ),ETT_EVENT_ENABLE = (1 <<3 ), + ETT_EVENT_HIST = (1 << 4), };extern int filter_match_preds (struct event_filter *filter,void *rec);
kernel/trace/Kconfig +16 -0
@@ -538,6 +538,22 @@ config TRACING_MAP generally used outside of that context, and is normally selected by tracers that use it. +config HIST_TRIGGERS + bool "Histogram triggers" + depends on ARCH_HAVE_NMI_SAFE_CMPXCHG + select TRACING_MAP + default n + help + Hist triggers allow one or more arbitrary trace event fields + to be aggregated into hash tables and dumped to stdout by + reading a debugfs/tracefs file. They're useful for + gathering quick and dirty (though precise) summaries of + event activity as an initial guide for further investigation + using more advanced tools. + + See Documentation/trace/events.txt. + If in doubt, say N. + config MMIOTRACE_TEST tristate "Test module for mmiotrace" depends on MMIOTRACE && m
kernel/trace/Makefile +1 -0
@@ -54,6 +54,7 @@ obj-$(CONFIG_EVENT_TRACING) += trace_event_perf.o endif obj-$(CONFIG_EVENT_TRACING) += trace_events_filter.o obj-$(CONFIG_EVENT_TRACING) += trace_events_trigger.o +obj-$(CONFIG_HIST_TRIGGERS) += trace_events_hist.o obj-$(CONFIG_BPF_EVENTS) += bpf_trace.o obj-$(CONFIG_KPROBE_EVENT) += trace_kprobe.o obj-$(CONFIG_TRACEPOINTS) += power-traces.o
kernel/trace/trace.c +17 -0
@@ -3813,6 +3813,9 @@ static const char readme_msg[] =#ifdef CONFIG_TRACER_SNAPSHOT "\t\t snapshot\n"#endif +#ifdef CONFIG_HIST_TRIGGERS + "\t\t hist (see below)\n" +#endif "\t example: echo traceoff > events/block/block_unplug/trigger\n" "\t echo traceoff:3 > events/block/block_unplug/trigger\n" "\t echo 'enable_event:kmem:kmalloc:3 if nr_rq > 1' > \\\n"
@@ -3828,6 +3831,20 @@ static const char readme_msg[] ="\t To remove a trigger with a count:\n" "\t echo '!<trigger>:0 > <system>/<event>/trigger\n" "\t Filters can be ignored when removing a trigger.\n" +#ifdef CONFIG_HIST_TRIGGERS +" hist trigger\t- If set, event hits are aggregated into a hash table\n" +"\t Format: hist:keys=<field1>\n" +"\t [:size=#entries]\n" +"\t [if <filter>]\n\n" +"\t When a matching event is hit, an entry is added to a hash\n" +"\t table using the key named, and the value of a sum called\n" +"\t 'hitcount' is incremented. Keys correspond to fields in the\n" +"\t event's format description. Keys can be any field. The\n" +"\t 'size' parameter can be used to specify more or fewer than\n" +"\t the default 2048 entries for the hashtable size.\n\n" +"\t Reading the 'hist' file for the event will dump the hash\n" +"\t table in its entirety to stdout." +#endif ; static ssize_t
kernel/trace/trace.h +7 -0
@@ -1162,6 +1162,13 @@ extern struct mutex event_mutex;extern struct list_head ftrace_events;extern const struct file_operations event_trigger_fops; +extern const struct file_operations event_hist_fops; + +#ifdef CONFIG_HIST_TRIGGERS +extern int register_trigger_hist_cmd (void ); +#else +static inline int register_trigger_hist_cmd (void ) {return 0 ; } +#endif extern int register_trigger_cmds (void );extern void clear_event_triggers (struct trace_array *tr);
kernel/trace/trace_events.c +4 -0
@@ -2141,6 +2141,10 @@ event_create_dir(struct dentry *parent, struct trace_event_file *file)trace_create_file ("trigger" ,0644 , file->dir, file, &event_trigger_fops); +#ifdef CONFIG_HIST_TRIGGERS +trace_create_file ("hist" ,0444 , file->dir, file, + &event_hist_fops); +#endif trace_create_file ("format" ,0444 , file->dir, call, &ftrace_event_format_fops);
kernel/trace/trace_events_hist.c new file +849 -0
849 lines not on this page · raw message
kernel/trace/trace_events_trigger.c +1 -0
@@ -1447,6 +1447,7 @@ __init int register_trigger_cmds(void)register_trigger_snapshot_cmd ();register_trigger_stacktrace_cmd ();register_trigger_enable_disable_cmds (); +register_trigger_hist_cmd ();return 0 ; }
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 9/30 tracing: Add hist trigger support for multiple values (vals= param)
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Allow users to specify trace event fields to use in aggregated sums via a new 'vals=' keyword. Before this addition, the only aggregated sum supported was the implied value 'hitcount'. With this addition, 'hitcount' is also supported as an explicit value field, as is any numeric trace event field.
This expands the hist trigger syntax from this:
# echo hist:keys=xxx [ if filter] > event/trigger
to this:
# echo hist:keys=xxx:vals=yyy [ if filter] > event/trigger
--- kernel/trace/trace.c | 12 +++--- kernel/trace/trace_events_hist.c | 79 +++++++++++++++++++++++++++++++++++++++- 2 files changed, 85 insertions(+), 6 deletions(-)
kernel/trace/trace.c +7 -5
@@ -3834,14 +3834,16 @@ static const char readme_msg[] =#ifdef CONFIG_HIST_TRIGGERS " hist trigger\t- If set, event hits are aggregated into a hash table\n" "\t Format: hist:keys=<field1>\n" +"\t [:values=<field1[,field2,...]>]\n" "\t [:size=#entries]\n" "\t [if <filter>]\n\n" "\t When a matching event is hit, an entry is added to a hash\n" -"\t table using the key named, and the value of a sum called\n" -"\t 'hitcount' is incremented. Keys correspond to fields in the\n" -"\t event's format description. Keys can be any field. The\n" -"\t 'size' parameter can be used to specify more or fewer than\n" -"\t the default 2048 entries for the hashtable size.\n\n" +"\t table using the key(s) and value(s) named, and the value of a\n" +"\t sum called 'hitcount' is incremented. Keys and values\n" +"\t correspond to fields in the event's format description. Keys\n" +"\t can be any field. Values must correspond to numeric fields.\n" +"\t The 'size' parameter can be used to specify more or fewer\n" +"\t than the default 2048 entries for the hashtable size.\n\n" "\t Reading the 'hist' file for the event will dump the hash\n" "\t table in its entirety to stdout."#endif
kernel/trace/trace_events_hist.c +78 -1
122 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 10/30 tracing: Add hist trigger support for compound keys
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Allow users to specify multiple trace event fields to use in keys by allowing multiple fields in the 'keys=' keyword. With this addition, any unique combination of any of the fields named in the 'keys' keyword will result in a new entry being added to the hash table.
--- kernel/trace/trace.c | 10 ++++++---- kernel/trace/trace_events_hist.c | 41 +++++++++++++++++++++++++++++----------- 2 files changed, 36 insertions(+), 15 deletions(-)
kernel/trace/trace.c +6 -4
@@ -3833,7 +3833,7 @@ static const char readme_msg[] ="\t Filters can be ignored when removing a trigger.\n" #ifdef CONFIG_HIST_TRIGGERS" hist trigger\t- If set, event hits are aggregated into a hash table\n" -"\t Format: hist:keys=<field1>\n" +"\t Format: hist:keys=<field1[,field2,...]>\n" "\t [:values=<field1[,field2,...]>]\n" "\t [:size=#entries]\n" "\t [if <filter>]\n\n"
@@ -3841,9 +3841,11 @@ static const char readme_msg[] ="\t table using the key(s) and value(s) named, and the value of a\n" "\t sum called 'hitcount' is incremented. Keys and values\n" "\t correspond to fields in the event's format description. Keys\n" -"\t can be any field. Values must correspond to numeric fields.\n" -"\t The 'size' parameter can be used to specify more or fewer\n" -"\t than the default 2048 entries for the hashtable size.\n\n" +"\t can be any field. Compound keys consisting of up to two\n" +"\t fields can be specified by the 'keys' keyword. Values must\n" +"\t correspond to numeric fields. The 'size' parameter can be\n" +"\t used to specify more or fewer than the default 2048 entries\n" +"\t for the hashtable size.\n\n" "\t Reading the 'hist' file for the event will dump the hash\n" "\t table in its entirety to stdout."#endif
kernel/trace/trace_events_hist.c +30 -11
115 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 11/30 tracing: Add hist trigger support for user-defined sorting (sort= param)
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Allow users to specify keys and/or values to sort on. With this addition, keys and values specified using the 'keys=' and 'vals=' keywords can be used to sort the hist trigger output via a new 'sort=' keyword. If multiple sort keys are specified, the output will be sorted using the second key as a secondary sort key, etc. The default sort order is ascending; if the user wants a different sort order, '.descending' can be appended to the specific sort key. Before this addition, output was always sorted by 'hitcount' in ascending order.
This expands the hist trigger syntax from this:
# echo hist:keys=xxx:vals=yyy \
[ if filter] > event/triggerto this:
# echo hist:keys=xxx:vals=yyy:sort=zzz.descending \
[ if filter] > event/trigger--- kernel/trace/trace.c | 6 ++- kernel/trace/trace_events_hist.c | 112 +++++++++++++++++++++++++++++++++++++-- 2 files changed, 114 insertions(+), 4 deletions(-)
kernel/trace/trace.c +5 -1
@@ -3835,6 +3835,7 @@ static const char readme_msg[] =" hist trigger\t- If set, event hits are aggregated into a hash table\n" "\t Format: hist:keys=<field1[,field2,...]>\n" "\t [:values=<field1[,field2,...]>]\n" +"\t [:sort=<field1[,field2,...]>]\n" "\t [:size=#entries]\n" "\t [if <filter>]\n\n" "\t When a matching event is hit, an entry is added to a hash\n"
@@ -3843,7 +3844,10 @@ static const char readme_msg[] ="\t correspond to fields in the event's format description. Keys\n" "\t can be any field. Compound keys consisting of up to two\n" "\t fields can be specified by the 'keys' keyword. Values must\n" -"\t correspond to numeric fields. The 'size' parameter can be\n" +"\t correspond to numeric fields. Sort keys consisting of up to\n" +"\t two fields can be specified using the 'sort' keyword. The\n" +"\t sort direction can be modified by appending '.descending' or\n" +"\t '.ascending' to a sort field. The 'size' parameter can be\n" "\t used to specify more or fewer than the default 2048 entries\n" "\t for the hashtable size.\n\n" "\t Reading the 'hist' file for the event will dump the hash\n"
kernel/trace/trace_events_hist.c +109 -3
146 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 12/30 tracing: Add hist trigger support for pausing and continuing a trace
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Allow users to append 'pause' or 'continue' to an existing trigger in order to have it paused or to have a paused trace continue.
This expands the hist trigger syntax from this:
# echo hist:keys=xxx:vals=yyy:sort=zzz.descending \
[ if filter] >> event/triggerto this:
# echo hist:keys=xxx:vals=yyy:sort=zzz.descending:pause or cont \
[ if filter] >> event/trigger--- kernel/trace/trace.c | 7 ++++++- kernel/trace/trace_events_hist.c | 31 ++++++++++++++++++++++++++++--- 2 files changed, 34 insertions(+), 4 deletions(-)
kernel/trace/trace.c +6 -1
@@ -3837,6 +3837,7 @@ static const char readme_msg[] ="\t [:values=<field1[,field2,...]>]\n" "\t [:sort=<field1[,field2,...]>]\n" "\t [:size=#entries]\n" +"\t [:pause][:continue]\n" "\t [if <filter>]\n\n" "\t When a matching event is hit, an entry is added to a hash\n" "\t table using the key(s) and value(s) named, and the value of a\n"
@@ -3851,7 +3852,11 @@ static const char readme_msg[] ="\t used to specify more or fewer than the default 2048 entries\n" "\t for the hashtable size.\n\n" "\t Reading the 'hist' file for the event will dump the hash\n" - "\t table in its entirety to stdout." +"\t table in its entirety to stdout.\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" +"\t until told to do so. 'continue' can be used to start or\n" + "\t restart a paused hist trigger.\n\n"#endif ;
kernel/trace/trace_events_hist.c +28 -3
@@ -86,6 +86,8 @@ struct hist_trigger_attrs {char *keys_str;char *vals_str;char *sort_key_str; +bool pause; +bool cont;unsigned int map_bits; };
@@ -193,6 +195,11 @@ static struct hist_trigger_attrs *parse_hist_trigger_attrs(char *trigger_str) attrs->vals_str =kstrdup (str,GFP_KERNEL ); else if (strncmp(str, "sort=", strlen("sort=")) == 0) attrs->sort_key_str = kstrdup(str, GFP_KERNEL); + else if (strcmp(str, "pause") == 0) + attrs->pause = true; + else if ((strcmp(str, "cont") == 0) || + (strcmp(str, "continue") == 0)) + attrs->cont = true; else if (strncmp(str, "size=", strlen("size=")) == 0) { int map_bits = parse_map_size(str);
@@ -871,7 +878,10 @@ static int event_hist_trigger_print(struct seq_file *m,if (data->filter_str)seq_printf (m," if %s" , data->filter_str); -seq_puts (m," [active]" ); +if (data->paused) +seq_puts (m," [paused]" ); +else +seq_puts (m," [active]" );seq_putc (m,'\n' );
@@ -910,16 +920,30 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,struct event_trigger_data *data, struct trace_event_file *file) { + struct hist_trigger_data *hist_data = data->private_data;struct event_trigger_data *test;int ret =0 ;list_for_each_entry_rcu (test, &file->triggers, list) {if (test->cmd_ops->trigger_type ==ETT_EVENT_HIST ) { - ret = -EEXIST ; +if (hist_data->attrs->pause) + test->paused = true; +else if (hist_data->attrs->cont) + test->paused = false; +else + ret = -EEXIST ; goto out; } } +if (hist_data->attrs->cont) { + ret = -ENOENT ; + goto out; + } + +if (hist_data->attrs->pause) + data->paused = true; +if (data->ops->init) { ret = data->ops->init (data->ops, data);if (ret <0 )
@@ -1011,7 +1035,8 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,* triggers registered a failure too. */ if (!ret) { - ret = -ENOENT ; +if (!(attrs->pause || attrs->cont)) + ret = -ENOENT ; goto out_free; }else if (ret <0 ) goto out_free;
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 13/30 tracing: Add hist trigger support for clearing a trace
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Allow users to append 'clear' to an existing trigger in order to have the hash table cleared.
This expands the hist trigger syntax from this:
# echo hist:keys=xxx:vals=yyy:sort=zzz.descending:pause/cont \
[ if filter] >> event/triggerto this:
# echo hist:keys=xxx:vals=yyy:sort=zzz.descending:pause/cont/clear \
[ if filter] >> event/trigger--- kernel/trace/trace.c | 5 ++++- kernel/trace/trace_events_hist.c | 24 ++++++++++++++++++++++-- 2 files changed, 26 insertions(+), 3 deletions(-)
kernel/trace/trace.c +4 -1
@@ -3837,7 +3837,7 @@ static const char readme_msg[] ="\t [:values=<field1[,field2,...]>]\n" "\t [:sort=<field1[,field2,...]>]\n" "\t [:size=#entries]\n" -"\t [:pause][:continue]\n" +"\t [:pause][:continue][:clear]\n" "\t [if <filter>]\n\n" "\t When a matching event is hit, an entry is added to a hash\n" "\t table using the key(s) and value(s) named, and the value of a\n"
@@ -3857,6 +3857,9 @@ static const char readme_msg[] ="\t trigger or to start a hist trigger but not log any events\n" "\t until told to do so. 'continue' can be used to start or\n" "\t restart a paused hist trigger.\n\n" +"\t The 'clear' parameter will clear the contents of a running\n" +"\t hist trigger and leave its current paused/active state\n" + "\t unchanged.\n\n"#endif ;
kernel/trace/trace_events_hist.c +22 -2
@@ -88,6 +88,7 @@ struct hist_trigger_attrs {char *sort_key_str;bool pause;bool cont; +bool clear;unsigned int map_bits; };
@@ -200,6 +201,8 @@ static struct hist_trigger_attrs *parse_hist_trigger_attrs(char *trigger_str)else if ((strcmp (str,"cont" ) ==0 ) || (strcmp (str,"continue" ) ==0 )) attrs->cont = true; +else if (strcmp (str,"clear" ) ==0 ) + attrs->clear = true;else if (strncmp (str,"size=" ,strlen ("size=" )) ==0 ) {int map_bits =parse_map_size (str);
@@ -916,6 +919,21 @@ static struct event_trigger_ops *event_hist_get_trigger_ops(char *cmd,return &event_hist_trigger_ops; } +static void hist_clear (struct event_trigger_data *data) +{ +struct hist_trigger_data *hist_data = data->private_data; +bool paused; + + paused = data->paused; + data->paused = true; + +synchronize_sched (); + +tracing_map_clear (hist_data->map); + + data->paused = paused; +} +static int hist_register_trigger (char *glob,struct event_trigger_ops *ops,struct event_trigger_data *data,struct trace_event_file *file)
@@ -930,13 +948,15 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops, test->paused = true; else if (hist_data->attrs->cont) test->paused = false; + else if (hist_data->attrs->clear) + hist_clear(test); else ret = -EEXIST ; goto out; } } -if (hist_data->attrs->cont) { +if (hist_data->attrs->cont || hist_data->attrs->clear) { ret = -ENOENT ; goto out; }
@@ -1035,7 +1055,7 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,* triggers registered a failure too. */ if (!ret) { -if (!(attrs->pause || attrs->cont)) +if (!(attrs->pause || attrs->cont || attrs->clear)) ret = -ENOENT ; goto out_free; }else if (ret <0 )
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 14/30 tracing: Add hist trigger hex modifier for displaying numeric fields
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Allow users to have numeric fields displayed as hex values in the output by appending '.hex' to field names:
# echo hist:keys=aaa,bbb.hex:vals=ccc.hex ... \
[ if filter] > event/trigger--- kernel/trace/trace.c | 5 +++- kernel/trace/trace_events_hist.c | 62 ++++++++++++++++++++++++++++++++++++---- 2 files changed, 60 insertions(+), 7 deletions(-)
kernel/trace/trace.c +4 -1
@@ -3852,7 +3852,10 @@ static const char readme_msg[] ="\t used to specify more or fewer than the default 2048 entries\n" "\t for the hashtable size.\n\n" "\t Reading the 'hist' file for the event will dump the hash\n" -"\t table in its entirety to stdout.\n\n" +"\t table in its entirety to stdout. The default format used to\n" +"\t display a given field can be modified by appending any of the\n" +"\t following modifiers to the field name, as applicable:\n\n" +"\t .hex display a number as a hex value\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" "\t until told to do so. 'continue' can be used to start or\n"
kernel/trace/trace_events_hist.c +56 -6
111 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 15/30 tracing: Add hist trigger sym and sym-offset modifiers
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Allow users to have address fields displayed as symbols in the output by appending '.sym' or 'sym-offset' to field names:
# echo hist:keys=aaa.sym,bbb.sym-offset ... \
[ if filter] > event/trigger--- kernel/trace/trace.c | 4 +++- kernel/trace/trace_events_hist.c | 29 +++++++++++++++++++++++++---- 2 files changed, 28 insertions(+), 5 deletions(-)
kernel/trace/trace.c +3 -1
@@ -3855,7 +3855,9 @@ static const char readme_msg[] ="\t table in its entirety to stdout. The default format used to\n" "\t display a given field can be modified by appending any of the\n" "\t following modifiers to the field name, as applicable:\n\n" -"\t .hex display a number as a hex value\n\n" +"\t .hex display a number as a hex value\n" +"\t .sym display an address as a symbol\n" +"\t .sym-offset display an address as a symbol and offset\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" "\t until told to do so. 'continue' can be used to start or\n"
kernel/trace/trace_events_hist.c +25 -4
@@ -77,10 +77,12 @@ DEFINE_HIST_FIELD_FN(u8);#define HIST_KEY_SIZE_MAX (MAX_FILTER_STR_VAL + sizeof(u64))enum hist_field_flags { -HIST_FIELD_FL_HITCOUNT =1 , -HIST_FIELD_FL_KEY =2 , -HIST_FIELD_FL_STRING =4 , -HIST_FIELD_FL_HEX =8 , +HIST_FIELD_FL_HITCOUNT =1 , +HIST_FIELD_FL_KEY =2 , +HIST_FIELD_FL_STRING =4 , +HIST_FIELD_FL_HEX =8 , +HIST_FIELD_FL_SYM =16 , +HIST_FIELD_FL_SYM_OFFSET =32 , };struct hist_trigger_attrs {
@@ -397,6 +399,10 @@ static int create_key_field(struct hist_trigger_data *hist_data,if (field_str) {if (strcmp (field_str,"hex" ) ==0 ) flags |=HIST_FIELD_FL_HEX ; +else if (strcmp (field_str,"sym" ) ==0 ) + flags |=HIST_FIELD_FL_SYM ; +else if (strcmp (field_str,"sym-offset" ) ==0 ) + flags |=HIST_FIELD_FL_SYM_OFFSET ;else { ret = -EINVAL ; goto out;
@@ -726,6 +732,7 @@ hist_trigger_entry_print(struct seq_file *m, struct tracing_map_elt *elt) {struct hist_field *key_field; +char str[KSYM_SYMBOL_LEN ];unsigned int i;u64 uval;
@@ -741,6 +748,16 @@ hist_trigger_entry_print(struct seq_file *m, uval = *(u64 *)(key + key_field->offset);seq_printf (m,"%s: %llx" , key_field->field->name, uval); + }else if (key_field->flags &HIST_FIELD_FL_SYM ) { + uval = *(u64 *)(key + key_field->offset); +sprint_symbol_no_offset (str, uval); +seq_printf (m,"%s: [%llx] %-45s" , + key_field->field->name, uval, str); + }else if (key_field->flags &HIST_FIELD_FL_SYM_OFFSET ) { + uval = *(u64 *)(key + key_field->offset); +sprint_symbol (str, uval); +seq_printf (m,"%s: [%llx] %-55s" , + key_field->field->name, uval, str); }else if (key_field->flags &HIST_FIELD_FL_STRING ) {seq_printf (m,"%s: %-50s" , key_field->field->name, (char *)(key + key_field->offset));
@@ -856,6 +873,10 @@ static const char *get_hist_field_flags(struct hist_field *hist_field)if (hist_field->flags &HIST_FIELD_FL_HEX ) flags_str ="hex" ; +else if (hist_field->flags &HIST_FIELD_FL_SYM ) + flags_str ="sym" ; +else if (hist_field->flags &HIST_FIELD_FL_SYM_OFFSET ) + flags_str ="sym-offset" ;return flags_str; }
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 16/30 tracing: Add hist trigger execname modifier
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Allow users to have common_pid field values displayed as program names in the output by appending '.execname' to a common_pid field name:
# echo hist:keys=common_pid.execname ... \
[ if filter] > event/trigger--- kernel/trace/trace.c | 3 +- kernel/trace/trace_events_hist.c | 100 ++++++++++++++++++++++++++++++++++++++- 2 files changed, 101 insertions(+), 2 deletions(-)
kernel/trace/trace.c +2 -1
@@ -3857,7 +3857,8 @@ static const char readme_msg[] ="\t following modifiers to the field name, as applicable:\n\n" "\t .hex display a number as a hex value\n" "\t .sym display an address as a symbol\n" -"\t .sym-offset display an address as a symbol and offset\n\n" +"\t .sym-offset display an address as a symbol and offset\n" +"\t .execname display a common_pid as a program name\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" "\t until told to do so. 'continue' can be used to start or\n"
kernel/trace/trace_events_hist.c +99 -1
148 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 17/30 tracing: Add hist trigger syscall modifier
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Allow users to have syscall id fields displayed as syscall names in the output by appending '.syscall' to field names:
# echo hist:keys=aaa.syscall ... \
[ if filter] > event/trigger--- kernel/trace/trace.c | 3 ++- kernel/trace/trace_events_hist.c | 15 +++++++++++++++ 2 files changed, 17 insertions(+), 1 deletion(-)
kernel/trace/trace.c +2 -1
@@ -3858,7 +3858,8 @@ static const char readme_msg[] ="\t .hex display a number as a hex value\n" "\t .sym display an address as a symbol\n" "\t .sym-offset display an address as a symbol and offset\n" -"\t .execname display a common_pid as a program name\n\n" +"\t .execname display a common_pid as a program name\n" +"\t .syscall display a syscall id as a syscall name\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" "\t until told to do so. 'continue' can be used to start or\n"
kernel/trace/trace_events_hist.c +15 -0
@@ -84,6 +84,7 @@ enum hist_field_flags {HIST_FIELD_FL_SYM =16 ,HIST_FIELD_FL_SYM_OFFSET =32 ,HIST_FIELD_FL_EXECNAME =64 , + HIST_FIELD_FL_SYSCALL = 128, }; struct hist_trigger_attrs {
@@ -474,6 +475,8 @@ static int create_key_field(struct hist_trigger_data *hist_data,else if ((strcmp (field_str,"execname" ) ==0 ) && (strcmp (field_name,"common_pid" ) ==0 )) flags |=HIST_FIELD_FL_EXECNAME ; +else if (strcmp (field_str,"syscall" ) ==0 ) + flags |=HIST_FIELD_FL_SYSCALL ;else { ret = -EINVAL ; goto out;
@@ -854,6 +857,16 @@ hist_trigger_entry_print(struct seq_file *m, uval = *(u64 *)(key + key_field->offset);seq_printf (m,"%s: %-16s[%10llu]" , key_field->field->name, comm, uval); + }else if (key_field->flags &HIST_FIELD_FL_SYSCALL ) { +const char *syscall_name; + + uval = *(u64 *)(key + key_field->offset); + syscall_name =get_syscall_name (uval); +if (!syscall_name) + syscall_name ="unknown_syscall" ; + +seq_printf (m,"%s: %-30s[%3llu]" , + key_field->field->name, syscall_name, uval); }else if (key_field->flags &HIST_FIELD_FL_STRING ) {seq_printf (m,"%s: %-50s" , key_field->field->name, (char *)(key + key_field->offset));
@@ -975,6 +988,8 @@ static const char *get_hist_field_flags(struct hist_field *hist_field) flags_str ="sym-offset" ; else if (hist_field->flags & HIST_FIELD_FL_EXECNAME) flags_str ="execname" ; + else if (hist_field->flags & HIST_FIELD_FL_SYSCALL) + flags_str ="syscall" ;return flags_str; }
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 18/30 tracing: Add hist trigger support for stacktraces as keys
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
It's often useful to be able to use a stacktrace as a hash key, for keeping a count of the number of times a particular call path resulted in a trace event, for instance. Add a special key named 'stacktrace' which can be used as key in a 'keys=' param for this purpose:
# echo hist:keys=stacktrace ... \
[ if filter] > event/trigger--- kernel/trace/trace.c | 16 ++--- kernel/trace/trace_events_hist.c | 135 +++++++++++++++++++++++++++++---------- 2 files changed, 109 insertions(+), 42 deletions(-)
kernel/trace/trace.c +8 -8
@@ -3843,14 +3843,14 @@ static const char readme_msg[] ="\t table using the key(s) and value(s) named, and the value of a\n" "\t sum called 'hitcount' is incremented. Keys and values\n" "\t correspond to fields in the event's format description. Keys\n" -"\t can be any field. Compound keys consisting of up to two\n" -"\t fields can be specified by the 'keys' keyword. Values must\n" -"\t correspond to numeric fields. Sort keys consisting of up to\n" -"\t two fields can be specified using the 'sort' keyword. The\n" -"\t sort direction can be modified by appending '.descending' or\n" -"\t '.ascending' to a sort field. The 'size' parameter can be\n" -"\t used to specify more or fewer than the default 2048 entries\n" -"\t for the hashtable size.\n\n" +"\t can be any field, or the special string 'stacktrace'.\n" +"\t Compound keys consisting of up to two fields can be specified\n" +"\t by the 'keys' keyword. Values must correspond to numeric\n" +"\t fields. Sort keys consisting of up to two fields can be\n" +"\t specified using the 'sort' keyword. The sort direction can\n" +"\t be modified by appending '.descending' or '.ascending' to a\n" +"\t sort field. The 'size' parameter can be used to specify more\n" +"\t or fewer than the default 2048 entries for the hashtable size.\n\n" "\t Reading the 'hist' file for the event will dump the hash\n" "\t table in its entirety to stdout. The default format used to\n" "\t display a given field can be modified by appending any of the\n"
kernel/trace/trace_events_hist.c +101 -34
228 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 19/30 tracing: Support string type key properly
In reply to Steven RostedtFrom: Namhyung Kim <[email protected]>
The string in a trace event is usually recorded as dynamic array which is variable length. But current hist code only support fixed length array so it cannot support most strings.
This patch fixes it by checking filter_type of the field and get proper pointer with it. With this, it can get a histogram of exec() based on filenames like below:
# cd /sys/kernel/tracing/events/sched/sched_process_exec
# cat 'hist:key=filename' > trigger
# ps
PID TTY TIME CMD
1 ? 00:00:00 init
29 ? 00:00:00 sh
38 ? 00:00:00 ps
# ls
enable filter format hist id trigger
# cat hist
# trigger info: hist:keys=filename:vals=hitcount:sort=hitcount:size=2048 [active] { filename: /usr/bin/ps } hitcount: 1
{ filename: /usr/bin/ls } hitcount: 1
{ filename: /usr/bin/cat } hitcount: 1Totals:
Hits: 3
Entries: 3
Dropped: 0--- kernel/trace/trace_events_hist.c | 49 ++++++++++++++++++++++++++++++++++++---- 1 file changed, 45 insertions(+), 4 deletions(-)
kernel/trace/trace_events_hist.c +45 -4
@@ -52,12 +52,28 @@ static u64 hist_field_string(struct hist_field *hist_field, void *event)return (u64 )(unsigned long )addr; } +static u64 hist_field_dynstring (struct hist_field *hist_field,void *event) +{ +u32 str_item = *(u32 *)(event + hist_field->field->offset); +int str_loc = str_item &0xffff ; +char *addr = (char *)(event + str_loc); + +return (u64 )(unsigned long )addr; +} + +static u64 hist_field_pstring (struct hist_field *hist_field,void *event) +{ +char **addr = (char **)(event + hist_field->field->offset); + +return (u64 )(unsigned long )*addr; +} +#define DEFINE_HIST_FIELD_FN (type) \ static u64 hist_field_##type(struct hist_field *hist_field, void *event)\ { \ type *addr = (type *)(event + hist_field->field->offset); \ \ - return (u64)*addr; \ + return (u64)(unsigned long)*addr; \ }DEFINE_HIST_FIELD_FN (s64);
@@ -340,7 +356,13 @@ static struct hist_field *create_hist_field(struct ftrace_event_field *field,if (is_string_field (field)) { flags |=HIST_FIELD_FL_STRING ; - hist_field->fn = hist_field_string; + +if (field->filter_type ==FILTER_STATIC_STRING ) + hist_field->fn = hist_field_string; +else if (field->filter_type ==FILTER_DYN_STRING ) + hist_field->fn = hist_field_dynstring; +else + hist_field->fn = hist_field_pstring; }else { hist_field->fn =select_value_fn (field->size, field->is_signed);
@@ -508,7 +530,10 @@ static int create_key_field(struct hist_trigger_data *hist_data, goto out; } - key_size = field->size; +if (is_string_field (field))/* should be last key field */ + key_size =HIST_KEY_SIZE_MAX - key_offset; +else + key_size = field->size; } hist_data->fields[key_idx] =create_hist_field (field, flags);
@@ -841,8 +866,24 @@ static void event_hist_trigger(struct event_trigger_data *data, void *rec) key = (void *)&field_contents;if (hist_data->n_keys >1 ) { +/* ensure NULL-termination */ +size_t size = key_field->size -1 ; + +if (key_field->flags &HIST_FIELD_FL_STRING ) { +struct ftrace_event_field *field; + + field = key_field->field; +if (field->filter_type ==FILTER_DYN_STRING ) + size = *(u32 *)(rec + field->offset) >>16 ; +else if (field->filter_type ==FILTER_PTR_STRING ) + size =strlen (key); + +if (size > key_field->size -1 ) + size = key_field->size -1 ; + } +memcpy (compound_key + key_field->offset, key, - key_field->size); + size); } } }
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 20/30 tracing: Remove restriction on string position in hist trigger keys
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
If we assume the maximum size for a string field, we don't have to worry about its position. Since we only allow two keys in a compound key and having more than one string key in a given compound key doesn't make much sense anyway, trading a bit of extra space instead of introducing an arbitrary restriction makes more sense.
We also need to use the event field size for static strings when copying the contents, otherwise we get random garbage in the key.
Also, cast string return values to avoid warnings on 32-bit compiles.
Finally, rearrange the code without changing any functionality by moving the compound key updating code into a separate function.
--- kernel/trace/trace_events_hist.c | 63 ++++++++++++++++++++++------------------ 1 file changed, 35 insertions(+), 28 deletions(-)
kernel/trace/trace_events_hist.c +35 -28
@@ -530,8 +530,8 @@ static int create_key_field(struct hist_trigger_data *hist_data, goto out; } -if (is_string_field (field))/* should be last key field */ - key_size =HIST_KEY_SIZE_MAX - key_offset; +if (is_string_field (field)) + key_size =MAX_FILTER_STR_VAL ;else key_size = field->size; }
@@ -830,9 +830,34 @@ static void hist_trigger_elt_update(struct hist_trigger_data *hist_data, } } +static inline void add_to_key (char *compound_key,void *key, +struct hist_field *key_field,void *rec) +{ +size_t size = key_field->size; + +if (key_field->flags &HIST_FIELD_FL_STRING ) { +struct ftrace_event_field *field; + + field = key_field->field; +if (field->filter_type ==FILTER_DYN_STRING ) + size = *(u32 *)(rec + field->offset) >>16 ; +else if (field->filter_type ==FILTER_PTR_STRING ) + size =strlen (key); +else if (field->filter_type ==FILTER_STATIC_STRING ) + size = field->size; + +/* ensure NULL-termination */ +if (size > key_field->size -1 ) + size = key_field->size -1 ; + } + +memcpy (compound_key + key_field->offset, key, size); +} +static void event_hist_trigger (struct event_trigger_data *data,void *rec) {struct hist_trigger_data *hist_data = data->private_data; +bool use_compound_key = (hist_data->n_keys >1 );unsigned long entries[HIST_STACKTRACE_DEPTH ];char compound_key[HIST_KEY_SIZE_MAX ];struct stack_trace stacktrace;
@@ -842,8 +867,7 @@ static void event_hist_trigger(struct event_trigger_data *data, void *rec)void *key =NULL ;unsigned int i; -if (hist_data->n_keys >1 ) -memset (compound_key,0 , hist_data->key_size); +memset (compound_key,0 , hist_data->key_size);for_each_hist_key_field (i, hist_data) { key_field = hist_data->fields[i];
@@ -860,35 +884,18 @@ static void event_hist_trigger(struct event_trigger_data *data, void *rec) key = entries; }else { field_contents = key_field->fn (key_field, rec); -if (key_field->flags &HIST_FIELD_FL_STRING ) +if (key_field->flags &HIST_FIELD_FL_STRING ) { key = (void *)(unsigned long )field_contents; -else + use_compound_key = true; + }else key = (void *)&field_contents; - -if (hist_data->n_keys >1 ) { -/* ensure NULL-termination */ -size_t size = key_field->size -1 ; - -if (key_field->flags &HIST_FIELD_FL_STRING ) { -struct ftrace_event_field *field; - - field = key_field->field; -if (field->filter_type ==FILTER_DYN_STRING ) - size = *(u32 *)(rec + field->offset) >>16 ; -else if (field->filter_type ==FILTER_PTR_STRING ) - size =strlen (key); - -if (size > key_field->size -1 ) - size = key_field->size -1 ; - } - -memcpy (compound_key + key_field->offset, key, - size); - } } + +if (use_compound_key) +add_to_key (compound_key, key, key_field, rec); } -if (hist_data->n_keys >1 ) +if (use_compound_key) key = compound_key; elt =tracing_map_insert (hist_data->map, key);
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 21/30 tracing: Add enable_hist/disable_hist triggers
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Similar to enable_event/disable_event triggers, these triggers enable and disable the aggregation of events into maps rather than enabling and disabling their writing into the trace buffer.
They can be used to automatically start and stop hist triggers based on a matching filter condition.
If there's a paused hist trigger on system:event, the following would start it when the filter condition was hit:
# echo enable_hist:system:event [ if filter] > event/trigger
And the following would disable a running system:event hist trigger:
# echo disable_hist:system:event [ if filter] > event/trigger
See Documentation/trace/events.txt for real examples.
--- include/linux/trace_events.h | 1 + kernel/trace/trace.c | 8 +++ kernel/trace/trace.h | 32 ++++++++++ kernel/trace/trace_events_hist.c | 115 ++++++++++++++++++++++++++++++++++++ kernel/trace/trace_events_trigger.c | 71 ++++++++++++---------- 5 files changed, 196 insertions(+), 31 deletions(-)
include/linux/trace_events.h +1 -0
@@ -408,6 +408,7 @@ enum event_trigger_type {ETT_STACKTRACE = (1 <<2 ),ETT_EVENT_ENABLE = (1 <<3 ),ETT_EVENT_HIST = (1 <<4 ), + ETT_HIST_ENABLE = (1 << 5), };extern int filter_match_preds (struct event_filter *filter,void *rec);
kernel/trace/trace.c +8 -0
@@ -3807,6 +3807,10 @@ static const char readme_msg[] = "\t trigger: traceon, traceoff\n" "\t enable_event:<system>:<event>\n" "\t disable_event:<system>:<event>\n" +#ifdef CONFIG_HIST_TRIGGERS + "\t enable_hist:<system>:<event>\n" + "\t disable_hist:<system>:<event>\n" +#endif#ifdef CONFIG_STACKTRACE "\t\t stacktrace\n"#endif
@@ -3867,6 +3871,10 @@ static const char readme_msg[] ="\t The 'clear' parameter will clear the contents of a running\n" "\t hist trigger and leave its current paused/active state\n" "\t unchanged.\n\n" +"\t The enable_hist and disable_hist triggers can be used to\n" +"\t have one event conditionally start and stop another event's\n" +"\t already-attached hist trigger. The syntax is analagous to\n" + "\t the enable_event and disable_event triggers.\n"#endif ;
kernel/trace/trace.h +32 -0
@@ -1166,8 +1166,10 @@ extern const struct file_operations event_hist_fops;#ifdef CONFIG_HIST_TRIGGERS extern int register_trigger_hist_cmd (void ); +extern int register_trigger_hist_enable_disable_cmds (void );#else static inline int register_trigger_hist_cmd (void ) {return 0 ; } +static inline int register_trigger_hist_enable_disable_cmds (void ) {return 0 ; }#endif extern int register_trigger_cmds (void );
@@ -1185,6 +1187,34 @@ struct event_trigger_data {struct list_head list; }; +/* Avoid typos */ +#define ENABLE_EVENT_STR "enable_event" +#define DISABLE_EVENT_STR "disable_event" +#define ENABLE_HIST_STR "enable_hist" +#define DISABLE_HIST_STR "disable_hist" + +struct enable_trigger_data { +struct trace_event_file *file; +bool enable; +bool hist; +}; + +extern int event_enable_trigger_print (struct seq_file *m, +struct event_trigger_ops *ops, +struct event_trigger_data *data); +extern void event_enable_trigger_free (struct event_trigger_ops *ops, +struct event_trigger_data *data); +extern int event_enable_trigger_func (struct event_command *cmd_ops, +struct trace_event_file *file, +char *glob,char *cmd,char *param); +extern int event_enable_register_trigger (char *glob, +struct event_trigger_ops *ops, +struct event_trigger_data *data, +struct trace_event_file *file); +extern void event_enable_unregister_trigger (char *glob, +struct event_trigger_ops *ops, +struct event_trigger_data *test, +struct trace_event_file *file);extern void trigger_data_free (struct event_trigger_data *data);extern int event_trigger_init (struct event_trigger_ops *ops,struct event_trigger_data *data);
@@ -1198,6 +1228,8 @@ extern int set_trigger_filter(char *filter_str,struct event_trigger_data *trigger_data, struct trace_event_file *file);extern int register_event_command (struct event_command *cmd); +extern int unregister_event_command (struct event_command *cmd); +extern int register_trigger_hist_enable_disable_cmds (void );/** * struct event_trigger_ops - callbacks for trace event triggers
kernel/trace/trace_events_hist.c +115 -0
118 lines not on this page · raw message
kernel/trace/trace_events_trigger.c +40 -31
161 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 22/30 tracing: Add hist trigger Documentation
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Add documentation and usage examples for 'hist' triggers.
--- Documentation/trace/events.txt | 1155 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 1155 insertions(+)
Documentation/trace/events.txt +1155 -0
@@ -512,3 +512,1158 @@ The following commands are supported: Note that there can be only one traceon or traceoff trigger per triggering event. + +- hist + + This command aggregates event hits into a hash table keyed on one or + more trace event format fields (or stacktrace) and a set of running + totals derived from one or more trace event format fields and/or + event counts (hitcount). + + The format of a hist trigger is as follows: + + hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>] + [:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue] + [:clear] [if <filter>] + + When a matching event is hit, an entry is added to a hash table + using the key(s) and value(s) named. Keys and values correspond to + fields in the event's format description. Values must correspond to + numeric fields - on an event hit, the value(s) will be added to a + sum kept for that field. The special string 'hitcount' can be used + in place of an explicit value field - this is simply a count of + event hits. If 'values' isn't specified, an implicit 'hitcount' + value will be automatically created and used as the only value. + Keys can be any field, or the special string 'stacktrace', which + will use the event's kernel stacktrace as the key. The keywords + 'keys' or 'key' can be used to specify keys, and the keywords + 'values', 'vals', or 'val' can be used to specify values. Compound + keys consisting of up to two fields can be specified by the 'keys' + keyword. Hashing a compound key produces a unique entry in the + table for each unique combination of component keys, and can be + useful for providing more fine-grained summaries of event data. + Additionally, sort keys consisting of up to two fields can be + specified by the 'sort' keyword. If more than one field is + specified, the result will be a 'sort within a sort': the first key + is taken to be the primary sort key and the second the secondary + key. + + 'hist' triggers add a 'hist' file to each event's subdirectory. + Reading the 'hist' file for the event will dump the hash table in + its entirety to stdout. Each printed hash table entry is a simple + list of the keys and values comprising the entry; keys are printed + first and are delineated by curly braces, and are followed by the + set of value fields for the entry. By default, numeric fields are + displayed as base-10 integers. This can be 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 + .syscall display a syscall id as a system call name + .execname display a common_pid as a program name + + Note that in general the semantics of a given field aren't + interpreted when applying a modifier to it, but there are some + restrictions to be aware of in this regard: + + - only the 'hex' modifier can be used for values (because values + are essentially sums, and the other modifiers don't make sense + in that context). + - the 'execname' modifier can only be used on a 'common_pid'. The + reason for this is that the execname is simply the 'comm' value + saved for the 'current' process when an event was triggered, + which is the same as the common_pid value saved by the event + tracing code. Trying to apply that comm value to other pid + values wouldn't be correct, and typically events that care save + 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: + + # echo 'hist:keys=skbaddr.hex:vals=len' > \ + /sys/kernel/debug/tracing/events/net/netif_rx/trigger + + # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist + + # echo '!hist:keys=skbaddr.hex:vals=len' > \ + /sys/kernel/debug/tracing/events/net/netif_rx/trigger + + The trigger file itself can be read to show the details of the + currently attached hist trigger. This information is also displayed + at the top of the 'hist' file when read. + + By default, the size of the hash table is 2048 entries. The 'size' + parameter can be used to specify more or fewer than that. The units + are in terms of hashtable entries - if a run uses more entries than + specified, the results will show the number of 'drops', the number + of hits that were ignored. The size should be a power of 2 between + 128 and 131072 (any non- power-of-2 number specified will be rounded + up). + + The 'sort' parameter can be used to specify a value field to sort + on. The default if unspecified is 'hitcount' and the default sort + order is 'ascending'. To sort in the opposite direction, append + .descending' to the sort key. + + The 'pause' parameter can be used to pause an existing hist trigger + or to start a hist trigger but not log any events until told to do + so. 'continue' or 'cont' can be used to start or restart a paused + hist trigger. + + The 'clear' parameter will clear the contents of a running hist + trigger and leave its current paused/active state. + + Note that the 'pause', 'cont', and 'clear' parameters should be + applied using 'append' shell operator ('>>') if applied to an + existing trigger, rather than via the '>' operator, which will cause + the trigger to be removed through truncation. + +- enable_hist/disable_hist + + The enable_hist and disable_hist triggers can be used to have one + event conditionally start and stop another event's already-attached + hist trigger. Any number of enable_hist and disable_hist triggers + 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: + + enable_hist:<system>:<event>[:count] + disable_hist:<system>:<event>[:count] + + Instead of enabling or disabling the tracing of the target event + into the trace buffer as the enable/disable_event triggers do, the + enable/disable_hist triggers enable or disable the aggregation of + the target event into a hash table. + + 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: + + # echo 'hist:keys=skbaddr.hex:vals=len:pause' > \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + + # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger + + # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger + + The above sets up an initially paused hist trigger which is unpaused + and starts aggregating events when a given program is executed, and + which stops aggregating when the process exits and the hist trigger + is paused again. + + The examples below provide a more concrete illustration of the + concepts and typical usage patterns discussed above. + + +6.2 'hist' trigger examples +--------------------------- + + 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: + + # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format + name: kmalloc + ID: 374 + format: + field:unsigned short common_type; offset:0; size:2; signed:0; + field:unsigned char common_flags; offset:2; size:1; signed:0; + field:unsigned char common_preempt_count; offset:3; size:1; signed:0; + field:int common_pid; offset:4; size:4; signed:1; + + field:unsigned long call_site; offset:8; size:8; signed:0; + field:const void * ptr; offset:16; size:8; signed:0; + field:size_t bytes_req; offset:24; size:8; signed:0; + field:size_t bytes_alloc; offset:32; size:8; signed:0; + field:gfp_t gfp_flags; offset:40; size:4; signed:0; + + 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: + + # echo 'hist:key=call_site:val=bytes_req' > \ + /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger + + This tells the tracing system to create a 'hist' trigger using the + call_site field of the kmalloc event as the key for the table, which + just means that each unique call_site address will have an entry + created for it in the table. The 'val=bytes_req' parameter tells + the hist trigger that for each unique entry (call_site) in the + table, it should keep a running total of the number of bytes + requested by that call_site. + + 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): + + # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist + # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active] + + { call_site: 18446744072106379007 } hitcount: 1 bytes_req: 176 + { call_site: 18446744071579557049 } hitcount: 1 bytes_req: 1024 + { call_site: 18446744071580608289 } hitcount: 1 bytes_req: 16384 + { call_site: 18446744071581827654 } hitcount: 1 bytes_req: 24 + { call_site: 18446744071580700980 } hitcount: 1 bytes_req: 8 + { call_site: 18446744071579359876 } hitcount: 1 bytes_req: 152 + { call_site: 18446744071580795365 } hitcount: 3 bytes_req: 144 + { call_site: 18446744071581303129 } hitcount: 3 bytes_req: 144 + { call_site: 18446744071580713234 } hitcount: 4 bytes_req: 2560 + { call_site: 18446744071580933750 } hitcount: 4 bytes_req: 736 + . + . + . + { call_site: 18446744072106047046 } hitcount: 69 bytes_req: 5576 + { call_site: 18446744071582116407 } hitcount: 73 bytes_req: 2336 + { call_site: 18446744072106054684 } hitcount: 136 bytes_req: 140504 + { call_site: 18446744072106224230 } hitcount: 136 bytes_req: 19584 + { call_site: 18446744072106078074 } hitcount: 153 bytes_req: 2448 + { call_site: 18446744072106062406 } hitcount: 153 bytes_req: 36720 + { call_site: 18446744071582507929 } hitcount: 153 bytes_req: 37088 + { call_site: 18446744072102520590 } hitcount: 273 bytes_req: 10920 + { call_site: 18446744071582143559 } hitcount: 358 bytes_req: 716 + { call_site: 18446744072106465852 } hitcount: 417 bytes_req: 56712 + { call_site: 18446744072102523378 } hitcount: 485 bytes_req: 27160 + { call_site: 18446744072099568646 } hitcount: 1676 bytes_req: 33520 + + Totals: + Hits: 4610 + Entries: 45 + Dropped: 0 + + The output displays a line for each entry, beginning with the key + 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: + + # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger + hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active] + + At the end of the output are a few lines that display the overall + totals for the run. The 'Hits' field shows the total number of + times the event trigger was hit, the 'Entries' field shows the total + number of used entries in the hash table, and the 'Dropped' field + shows the number of hits that were dropped because the number of + used entries for the run exceeded the maximum number of entries + allowed for the table (normally 0, but if not a hint that you may + want to increase the size of the table using the 'size' parameter). + + Notice in the above output that there's an extra field, 'hitcount', + which wasn't specified in the trigger. Also notice that in the + trigger info output, there's a parameter, 'sort=hitcount', which + wasn't specified in the trigger either. The reason for that is that + every trigger implicitly keeps a count of the total number of hits + attributed to a given entry, called the 'hitcount'. That hitcount + information is explicitly displayed in the output, and in the + absence of a user-specified sort parameter, is used as the default + sort field. + + The value 'hitcount' can be used in place of an explicit value in + the 'values' parameter if you don't really need to have any + particular field summed and are mainly interested in hit + frequencies. + + To turn the hist trigger off, simply call up the trigger in the + 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 + + 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: + + # echo 'hist:key=call_site.hex:val=bytes_req' > \ + /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger + + # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist + # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active] + + { call_site: ffffffffa026b291 } hitcount: 1 bytes_req: 433 + { call_site: ffffffffa07186ff } hitcount: 1 bytes_req: 176 + { call_site: ffffffff811ae721 } hitcount: 1 bytes_req: 16384 + { call_site: ffffffff811c5134 } hitcount: 1 bytes_req: 8 + { call_site: ffffffffa04a9ebb } hitcount: 1 bytes_req: 511 + { call_site: ffffffff8122e0a6 } hitcount: 1 bytes_req: 12 + { call_site: ffffffff8107da84 } hitcount: 1 bytes_req: 152 + { call_site: ffffffff812d8246 } hitcount: 1 bytes_req: 24 + { call_site: ffffffff811dc1e5 } hitcount: 3 bytes_req: 144 + { call_site: ffffffffa02515e8 } hitcount: 3 bytes_req: 648 + { call_site: ffffffff81258159 } hitcount: 3 bytes_req: 144 + { call_site: ffffffff811c80f4 } hitcount: 4 bytes_req: 544 + . + . + . + { call_site: ffffffffa06c7646 } hitcount: 106 bytes_req: 8024 + { call_site: ffffffffa06cb246 } hitcount: 132 bytes_req: 31680 + { call_site: ffffffffa06cef7a } hitcount: 132 bytes_req: 2112 + { call_site: ffffffff8137e399 } hitcount: 132 bytes_req: 23232 + { call_site: ffffffffa06c941c } hitcount: 185 bytes_req: 171360 + { call_site: ffffffffa06f2a66 } hitcount: 185 bytes_req: 26640 + { call_site: ffffffffa036a70e } hitcount: 265 bytes_req: 10600 + { call_site: ffffffff81325447 } hitcount: 292 bytes_req: 584 + { call_site: ffffffffa072da3c } hitcount: 446 bytes_req: 60656 + { call_site: ffffffffa036b1f2 } hitcount: 526 bytes_req: 29456 + { call_site: ffffffffa0099c06 } hitcount: 1780 bytes_req: 35600 + + Totals: + Hits: 4775 + Entries: 46 + Dropped: 0 + + Even that's only marginally more useful - while hex values do look + more like addresses, what users are typically more interested in + 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: + + # echo 'hist:key=call_site.sym:val=bytes_req' > \ + /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger + + # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist + # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active] + + { call_site: [ffffffff810adcb9] syslog_print_all } hitcount: 1 bytes_req: 1024 + { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 + { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 + { call_site: [ffffffff8154acbe] usb_alloc_urb } hitcount: 1 bytes_req: 192 + { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 + { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40 + { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 + { call_site: [ffffffff811febd5] fsnotify_alloc_group } hitcount: 2 bytes_req: 528 + { call_site: [ffffffff81440f58] __tty_buffer_request_room } hitcount: 2 bytes_req: 2624 + { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 2 bytes_req: 96 + { call_site: [ffffffffa05e19af] ieee80211_start_tx_ba_session [mac80211] } hitcount: 2 bytes_req: 464 + { call_site: [ffffffff81672406] tcp_get_metrics } hitcount: 2 bytes_req: 304 + { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 + { call_site: [ffffffff81089b05] sched_create_group } hitcount: 2 bytes_req: 1424 + . + . + . + { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1185 bytes_req: 123240 + { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 1185 bytes_req: 104280 + { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 1402 bytes_req: 190672 + { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 1518 bytes_req: 146208 + { call_site: [ffffffffa029070e] drm_vma_node_allow [drm] } hitcount: 1746 bytes_req: 69840 + { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 2021 bytes_req: 792312 + { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 2592 bytes_req: 145152 + { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2629 bytes_req: 378576 + { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2629 bytes_req: 3783248 + { call_site: [ffffffff81325607] apparmor_file_alloc_security } hitcount: 5192 bytes_req: 10384 + { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 5529 bytes_req: 110584 + { call_site: [ffffffff8131ebf7] aa_alloc_task_context } hitcount: 21943 bytes_req: 702176 + { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 55759 bytes_req: 5074265 + + Totals: + Hits: 109928 + Entries: 71 + Dropped: 0 + + Because the default sort key above is 'hitcount', the above shows a + the list of call_sites by increasing hitcount, so that at the bottom + we see the functions that made the most kmalloc calls during the + 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: + + # echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \ + /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger + + # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist + # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] + + { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2186 bytes_req: 3397464 + { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1790 bytes_req: 712176 + { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 8132 bytes_req: 513135 + { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 106 bytes_req: 440128 + { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2186 bytes_req: 314784 + { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 2174 bytes_req: 208992 + { call_site: [ffffffff811ae8e1] __kmalloc } hitcount: 8 bytes_req: 131072 + { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 859 bytes_req: 116824 + { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 1834 bytes_req: 102704 + { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 972 bytes_req: 101088 + { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 972 bytes_req: 85536 + { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 3333 bytes_req: 66664 + { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 209 bytes_req: 61632 + . + . + . + { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 + { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 + { call_site: [ffffffff812d8406] copy_semundo } hitcount: 2 bytes_req: 48 + { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 1 bytes_req: 48 + { call_site: [ffffffffa027121a] drm_getmagic [drm] } hitcount: 1 bytes_req: 48 + { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40 + { call_site: [ffffffff811c52f4] bprm_change_interp } hitcount: 2 bytes_req: 16 + { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 + { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 + { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 + + Totals: + Hits: 32133 + Entries: 81 + Dropped: 0 + + To display the offset and size information in addition to the symbol + 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 + + # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist + # trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] + + { call_site: [ffffffffa046041c] i915_gem_execbuffer2+0x6c/0x2c0 [i915] } hitcount: 4569 bytes_req: 3163720 + { call_site: [ffffffffa0489a66] intel_ring_begin+0xc6/0x1f0 [i915] } hitcount: 4569 bytes_req: 657936 + { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23+0x694/0x1020 [i915] } hitcount: 1519 bytes_req: 472936 + { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23+0x516/0x1020 [i915] } hitcount: 3050 bytes_req: 211832 + { call_site: [ffffffff811e2a1b] seq_buf_alloc+0x1b/0x50 } hitcount: 34 bytes_req: 148384 + { call_site: [ffffffffa04a580c] intel_crtc_page_flip+0xbc/0x870 [i915] } hitcount: 1385 bytes_req: 144040 + { call_site: [ffffffff811ae8e1] __kmalloc+0x191/0x1b0 } hitcount: 8 bytes_req: 131072 + { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl+0x282/0x360 [drm] } hitcount: 1385 bytes_req: 121880 + { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc+0x32/0x100 [drm] } hitcount: 1848 bytes_req: 103488 + { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state+0x2c/0xa0 [i915] } hitcount: 461 bytes_req: 62696 + { call_site: [ffffffffa029070e] drm_vma_node_allow+0x2e/0xd0 [drm] } hitcount: 1541 bytes_req: 61640 + { call_site: [ffffffff815f8d7b] sk_prot_alloc+0xcb/0x1b0 } hitcount: 57 bytes_req: 57456 + . + . + . + { call_site: [ffffffff8109524a] alloc_fair_sched_group+0x5a/0x1a0 } hitcount: 2 bytes_req: 128 + { call_site: [ffffffffa027b921] drm_vm_open_locked+0x31/0xa0 [drm] } hitcount: 3 bytes_req: 96 + { call_site: [ffffffff8122e266] proc_self_follow_link+0x76/0xb0 } hitcount: 8 bytes_req: 96 + { call_site: [ffffffff81213e80] load_elf_binary+0x240/0x1650 } hitcount: 3 bytes_req: 84 + { call_site: [ffffffff8154bc62] usb_control_msg+0x42/0x110 } hitcount: 1 bytes_req: 8 + { call_site: [ffffffffa00bf6fe] hidraw_send_report+0x7e/0x1a0 [hid] } hitcount: 1 bytes_req: 7 + { call_site: [ffffffffa00bf1ca] hidraw_report_event+0x8a/0x120 [hid] } hitcount: 1 bytes_req: 7 + + Totals: + Hits: 26098 + Entries: 64 + Dropped: 0 + + 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: + + # echo 'hist:keys=call_site.sym:values=bytes_req,bytes_alloc:sort=bytes_alloc.descending' > \ + /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger + + # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist + # trigger info: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:size=2048 [active] + + { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 7403 bytes_req: 4084360 bytes_alloc: 5958016 + { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 541 bytes_req: 2213968 bytes_alloc: 2228224 + { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 7404 bytes_req: 1066176 bytes_alloc: 1421568 + { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1565 bytes_req: 557368 bytes_alloc: 1037760 + { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 9557 bytes_req: 595778 bytes_alloc: 695744 + { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 5839 bytes_req: 430680 bytes_alloc: 470400 + { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 2388 bytes_req: 324768 bytes_alloc: 458496 + { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 3911 bytes_req: 219016 bytes_alloc: 250304 + { call_site: [ffffffff815f8d7b] sk_prot_alloc } hitcount: 235 bytes_req: 236880 bytes_alloc: 240640 + { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 557 bytes_req: 169024 bytes_alloc: 221760 + { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 9378 bytes_req: 187548 bytes_alloc: 206312 + { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1519 bytes_req: 157976 bytes_alloc: 194432 + . + . + . + { call_site: [ffffffff8109bd3b] sched_autogroup_create_attach } hitcount: 2 bytes_req: 144 bytes_alloc: 192 + { call_site: [ffffffff81097ee8] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 + { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 + { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 + { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 + { call_site: [ffffffff81213e80] load_elf_binary } hitcount: 3 bytes_req: 84 bytes_alloc: 96 + { call_site: [ffffffff81079a2e] kthread_create_on_node } hitcount: 1 bytes_req: 56 bytes_alloc: 64 + { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8 + { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 bytes_alloc: 8 + { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8 + + Totals: + Hits: 66598 + Entries: 65 + Dropped: 0 + + Finally, to finish off our kmalloc example, instead of simply having + 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: + + # echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \ + /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger + + The above trigger will use the kernel stack trace in effect when an + event is triggered as the key for the hash table. This allows the + enumeration of every kernel callpath that led up to a particular + 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): + + # 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] + + { stacktrace: + __kmalloc_track_caller+0x10b/0x1a0 + kmemdup+0x20/0x50 + hidraw_report_event+0x8a/0x120 [hid] + hid_report_raw_event+0x3ea/0x440 [hid] + hid_input_report+0x112/0x190 [hid] + hid_irq_in+0xc2/0x260 [usbhid] + __usb_hcd_giveback_urb+0x72/0x120 + usb_giveback_urb_bh+0x9e/0xe0 + tasklet_hi_action+0xf8/0x100 + __do_softirq+0x114/0x2c0 + irq_exit+0xa5/0xb0 + do_IRQ+0x5a/0xf0 + ret_from_intr+0x0/0x30 + cpuidle_enter+0x17/0x20 + cpu_startup_entry+0x315/0x3e0 + rest_init+0x7c/0x80 + } hitcount: 3 bytes_req: 21 bytes_alloc: 24 + { stacktrace: + __kmalloc_track_caller+0x10b/0x1a0 + kmemdup+0x20/0x50 + hidraw_report_event+0x8a/0x120 [hid] + hid_report_raw_event+0x3ea/0x440 [hid] + hid_input_report+0x112/0x190 [hid] + hid_irq_in+0xc2/0x260 [usbhid] + __usb_hcd_giveback_urb+0x72/0x120 + usb_giveback_urb_bh+0x9e/0xe0 + tasklet_hi_action+0xf8/0x100 + __do_softirq+0x114/0x2c0 + irq_exit+0xa5/0xb0 + do_IRQ+0x5a/0xf0 + ret_from_intr+0x0/0x30 + } hitcount: 3 bytes_req: 21 bytes_alloc: 24 + { stacktrace: + kmem_cache_alloc_trace+0xeb/0x150 + aa_alloc_task_context+0x27/0x40 + apparmor_cred_prepare+0x1f/0x50 + security_prepare_creds+0x16/0x20 + prepare_creds+0xdf/0x1a0 + SyS_capset+0xb5/0x200 + system_call_fastpath+0x12/0x6a + } hitcount: 1 bytes_req: 32 bytes_alloc: 32 + . + . + . + { stacktrace: + __kmalloc+0x11b/0x1b0 + i915_gem_execbuffer2+0x6c/0x2c0 [i915] + drm_ioctl+0x349/0x670 [drm] + do_vfs_ioctl+0x2f0/0x4f0 + SyS_ioctl+0x81/0xa0 + system_call_fastpath+0x12/0x6a + } hitcount: 17726 bytes_req: 13944120 bytes_alloc: 19593808 + { stacktrace: + __kmalloc+0x11b/0x1b0 + load_elf_phdrs+0x76/0xa0 + load_elf_binary+0x102/0x1650 + search_binary_handler+0x97/0x1d0 + do_execveat_common.isra.34+0x551/0x6e0 + SyS_execve+0x3a/0x50 + return_from_execve+0x0/0x23 + } hitcount: 33348 bytes_req: 17152128 bytes_alloc: 20226048 + { stacktrace: + kmem_cache_alloc_trace+0xeb/0x150 + apparmor_file_alloc_security+0x27/0x40 + security_file_alloc+0x16/0x20 + get_empty_filp+0x93/0x1c0 + path_openat+0x31/0x5f0 + do_filp_open+0x3a/0x90 + do_sys_open+0x128/0x220 + SyS_open+0x1e/0x20 + system_call_fastpath+0x12/0x6a + } hitcount: 4766422 bytes_req: 9532844 bytes_alloc: 38131376 + { stacktrace: + __kmalloc+0x11b/0x1b0 + seq_buf_alloc+0x1b/0x50 + seq_read+0x2cc/0x370 + proc_reg_read+0x3d/0x80 + __vfs_read+0x28/0xe0 + vfs_read+0x86/0x140 + SyS_read+0x46/0xb0 + system_call_fastpath+0x12/0x6a + } hitcount: 19133 bytes_req: 78368768 bytes_alloc: 78368768 + + Totals: + Hits: 6085872 + Entries: 253 + Dropped: 0 + + If you key a hist trigger on common_pid, in order for example to + 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: + + # echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \ + /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger + + # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/hist + # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active] + + { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512 + { common_pid: Xorg [ 1309] } hitcount: 525 count: 256640 + { common_pid: compiz [ 2889] } hitcount: 59 count: 254400 + { common_pid: bash [ 8710] } hitcount: 3 count: 66369 + { common_pid: dbus-daemon-lau [ 8703] } hitcount: 49 count: 47739 + { common_pid: irqbalance [ 1252] } hitcount: 27 count: 27648 + { common_pid: 01ifupdown [ 8705] } hitcount: 3 count: 17216 + { common_pid: dbus-daemon [ 772] } hitcount: 10 count: 12396 + { common_pid: Socket Thread [ 8342] } hitcount: 11 count: 11264 + { common_pid: nm-dhcp-client. [ 8701] } hitcount: 6 count: 7424 + { common_pid: gmain [ 1315] } hitcount: 18 count: 6336 + . + . + . + { common_pid: postgres [ 1892] } hitcount: 2 count: 32 + { common_pid: postgres [ 1891] } hitcount: 2 count: 32 + { common_pid: gmain [ 8704] } hitcount: 2 count: 32 + { common_pid: upstart-dbus-br [ 2740] } hitcount: 21 count: 21 + { common_pid: nm-dispatcher.a [ 8696] } hitcount: 1 count: 16 + { common_pid: indicator-datet [ 2904] } hitcount: 1 count: 16 + { common_pid: gdbus [ 2998] } hitcount: 1 count: 16 + { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8 + { common_pid: init [ 1] } hitcount: 2 count: 2 + + Totals: + Hits: 2116 + Entries: 51 + Dropped: 0 + + Similarly, if you key a hist trigger on syscall id, for example to + 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: + + # echo 'hist:key=id.syscall:val=hitcount' > \ + /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger + + # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist + # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active] + + { id: sys_fsync [ 74] } hitcount: 1 + { id: sys_newuname [ 63] } hitcount: 1 + { id: sys_prctl [157] } hitcount: 1 + { id: sys_statfs [137] } hitcount: 1 + { id: sys_symlink [ 88] } hitcount: 1 + { id: sys_sendmmsg [307] } hitcount: 1 + { id: sys_semctl [ 66] } hitcount: 1 + { id: sys_readlink [ 89] } hitcount: 3 + { id: sys_bind [ 49] } hitcount: 3 + { id: sys_getsockname [ 51] } hitcount: 3 + { id: sys_unlink [ 87] } hitcount: 3 + { id: sys_rename [ 82] } hitcount: 4 + { id: unknown_syscall [ 58] } hitcount: 4 + { id: sys_connect [ 42] } hitcount: 4 + { id: sys_getpid [ 39] } hitcount: 4 + . + . + . + { id: sys_rt_sigprocmask [ 14] } hitcount: 952 + { id: sys_futex [202] } hitcount: 1534 + { id: sys_write [ 1] } hitcount: 2689 + { id: sys_setitimer [ 38] } hitcount: 2797 + { id: sys_read [ 0] } hitcount: 3202 + { id: sys_select [ 23] } hitcount: 3773 + { id: sys_writev [ 20] } hitcount: 4531 + { id: sys_poll [ 7] } hitcount: 8314 + { id: sys_recvmsg [ 47] } hitcount: 13738 + { id: sys_ioctl [ 16] } hitcount: 21843 + + Totals: + Hits: 67612 + Entries: 72 + Dropped: 0 + + The syscall counts above provide a rough overall picture of system + call activity on the system; we can see for example that the most + popular system call on this system was the 'sys_ioctl' system call. + + We can use 'compound' keys to refine that number and provide some + further insight as to which processes exactly contribute to the + overall ioctl count. + + The command below keeps a hitcount for every unique combination of + 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: + + # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \ + /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger + + # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist + # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active] + + { id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1 + { id: sys_read [ 0], common_pid: gdbus [ 2976] } hitcount: 1 + { id: sys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: 1 + { id: sys_read [ 0], common_pid: postgres [ 1865] } hitcount: 1 + { id: sys_read [ 0], common_pid: deja-dup-monito [ 3543] } hitcount: 2 + { id: sys_read [ 0], common_pid: NetworkManager [ 890] } hitcount: 2 + { id: sys_read [ 0], common_pid: evolution-calen [ 3048] } hitcount: 2 + { id: sys_read [ 0], common_pid: postgres [ 1864] } hitcount: 2 + { id: sys_read [ 0], common_pid: nm-applet [ 3022] } hitcount: 2 + { id: sys_read [ 0], common_pid: whoopsie [ 1212] } hitcount: 2 + . + . + . + { id: sys_ioctl [ 16], common_pid: bash [ 8479] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: bash [ 3472] } hitcount: 12 + { id: sys_ioctl [ 16], common_pid: gnome-terminal [ 3199] } hitcount: 16 + { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 1808 + { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 5580 + . + . + . + { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2690] } hitcount: 3 + { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2688] } hitcount: 16 + { id: sys_inotify_add_watch [254], common_pid: gmain [ 975] } hitcount: 2 + { id: sys_inotify_add_watch [254], common_pid: gmain [ 3204] } hitcount: 4 + { id: sys_inotify_add_watch [254], common_pid: gmain [ 2888] } hitcount: 4 + { id: sys_inotify_add_watch [254], common_pid: gmain [ 3003] } hitcount: 4 + { id: sys_inotify_add_watch [254], common_pid: gmain [ 2873] } hitcount: 4 + { id: sys_inotify_add_watch [254], common_pid: gmain [ 3196] } hitcount: 6 + { id: sys_openat [257], common_pid: java [ 2623] } hitcount: 2 + { id: sys_eventfd2 [290], common_pid: ibus-ui-gtk3 [ 2760] } hitcount: 4 + { id: sys_eventfd2 [290], common_pid: compiz [ 2994] } hitcount: 6 + + Totals: + Hits: 31536 + Entries: 323 + Dropped: 0 + + The above list does give us a breakdown of the ioctl syscall by + 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: + + # 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 + + # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist + # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active] + + { id: sys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: gmain [ 3003] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: gmain [ 2781] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: gmain [ 2829] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: bash [ 8726] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: bash [ 8508] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: gmain [ 2970] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: gmain [ 2768] } hitcount: 1 + . + . + . + { id: sys_ioctl [ 16], common_pid: pool [ 8559] } hitcount: 45 + { id: sys_ioctl [ 16], common_pid: pool [ 8555] } hitcount: 48 + { id: sys_ioctl [ 16], common_pid: pool [ 8551] } hitcount: 48 + { id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: 66 + { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 26674 + { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 73443 + + Totals: + Hits: 101162 + Entries: 103 + Dropped: 0 + + The above output shows that 'compiz' and 'Xorg' are far and away + the heaviest ioctl callers (which might lead to questions about + whether they really need to be making all those calls and to + possible avenues for further investigation.) + + The compound key examples used a key and a sum value (hitcount) to + sort the output, but we can just as easily use two keys instead. + Here's an example where we use a compound key composed of the the + 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: + + # echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \ + /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/trigger + + # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/hist + # trigger info: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active] + + { common_pid: smbd [ 784], size: 4 } hitcount: 1 + { common_pid: dnsmasq [ 1412], size: 4096 } hitcount: 672 + { common_pid: postgres [ 1796], size: 1000 } hitcount: 6 + { common_pid: postgres [ 1867], size: 1000 } hitcount: 10 + { common_pid: bamfdaemon [ 2787], size: 28 } hitcount: 2 + { common_pid: bamfdaemon [ 2787], size: 14360 } hitcount: 1 + { common_pid: compiz [ 2994], size: 8 } hitcount: 1 + { common_pid: compiz [ 2994], size: 20 } hitcount: 11 + { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2 + { common_pid: firefox [ 8817], size: 4 } hitcount: 1 + { common_pid: firefox [ 8817], size: 8 } hitcount: 5 + { common_pid: firefox [ 8817], size: 588 } hitcount: 2 + { common_pid: firefox [ 8817], size: 628 } hitcount: 1 + { common_pid: firefox [ 8817], size: 6944 } hitcount: 1 + { common_pid: firefox [ 8817], size: 408880 } hitcount: 2 + { common_pid: firefox [ 8822], size: 8 } hitcount: 2 + { common_pid: firefox [ 8822], size: 160 } hitcount: 2 + { common_pid: firefox [ 8822], size: 320 } hitcount: 2 + { common_pid: firefox [ 8822], size: 352 } hitcount: 1 + . + . + . + { common_pid: pool [ 8923], size: 1960 } hitcount: 10 + { common_pid: pool [ 8923], size: 2048 } hitcount: 10 + { common_pid: pool [ 8924], size: 1960 } hitcount: 10 + { common_pid: pool [ 8924], size: 2048 } hitcount: 10 + { common_pid: pool [ 8928], size: 1964 } hitcount: 4 + { common_pid: pool [ 8928], size: 1965 } hitcount: 2 + { common_pid: pool [ 8928], size: 2048 } hitcount: 6 + { common_pid: pool [ 8929], size: 1982 } hitcount: 1 + { common_pid: pool [ 8929], size: 2048 } hitcount: 1 + + Totals: + Hits: 2016 + Entries: 224 + Dropped: 0 + + The above example also illustrates the fact that although a compound + key is treated as a single entity for hashing purposes, the sub-keys + it's composed of can be accessed independently. + + The next example uses a string field as the hash key and + 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: + + # echo 'hist:key=child_comm:val=hitcount:size=256' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger + + # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist + # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] + + { child_comm: dconf worker } hitcount: 1 + { child_comm: ibus-daemon } hitcount: 1 + { child_comm: whoopsie } hitcount: 1 + { child_comm: smbd } hitcount: 1 + { child_comm: gdbus } hitcount: 1 + { child_comm: kthreadd } hitcount: 1 + { child_comm: dconf worker } hitcount: 1 + { child_comm: evolution-alarm } hitcount: 2 + { child_comm: Socket Thread } hitcount: 2 + { child_comm: postgres } hitcount: 2 + { child_comm: bash } hitcount: 3 + { child_comm: compiz } hitcount: 3 + { child_comm: evolution-sourc } hitcount: 4 + { child_comm: dhclient } hitcount: 4 + { child_comm: pool } hitcount: 5 + { child_comm: nm-dispatcher.a } hitcount: 8 + { child_comm: firefox } hitcount: 8 + { child_comm: dbus-daemon } hitcount: 8 + { child_comm: glib-pacrunner } hitcount: 10 + { child_comm: evolution } hitcount: 23 + + Totals: + Hits: 89 + Entries: 20 + Dropped: 0 + + 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]: + + # echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \ + /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger + + # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist + # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [paused] + + { child_comm: dconf worker } hitcount: 1 + { child_comm: kthreadd } hitcount: 1 + { child_comm: dconf worker } hitcount: 1 + { child_comm: gdbus } hitcount: 1 + { child_comm: ibus-daemon } hitcount: 1 + { child_comm: Socket Thread } hitcount: 2 + { child_comm: evolution-alarm } hitcount: 2 + { child_comm: smbd } hitcount: 2 + { child_comm: bash } hitcount: 3 + { child_comm: whoopsie } hitcount: 3 + { child_comm: compiz } hitcount: 3 + { child_comm: evolution-sourc } hitcount: 4 + { child_comm: pool } hitcount: 5 + { child_comm: postgres } hitcount: 6 + { child_comm: firefox } hitcount: 8 + { child_comm: dhclient } hitcount: 10 + { child_comm: emacs } hitcount: 12 + { child_comm: dbus-daemon } hitcount: 20 + { child_comm: nm-dispatcher.a } hitcount: 20 + { child_comm: evolution } hitcount: 35 + { child_comm: glib-pacrunner } hitcount: 59 + + Totals: + Hits: 199 + Entries: 21 + Dropped: 0 + + 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: + + # echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \ + /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger + + # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist + # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] + + { child_comm: dconf worker } hitcount: 1 + { child_comm: dconf worker } hitcount: 1 + { child_comm: kthreadd } hitcount: 1 + { child_comm: gdbus } hitcount: 1 + { child_comm: ibus-daemon } hitcount: 1 + { child_comm: Socket Thread } hitcount: 2 + { child_comm: evolution-alarm } hitcount: 2 + { child_comm: smbd } hitcount: 2 + { child_comm: whoopsie } hitcount: 3 + { child_comm: compiz } hitcount: 3 + { child_comm: evolution-sourc } hitcount: 4 + { child_comm: bash } hitcount: 5 + { child_comm: pool } hitcount: 5 + { child_comm: postgres } hitcount: 6 + { child_comm: firefox } hitcount: 8 + { child_comm: dhclient } hitcount: 11 + { child_comm: emacs } hitcount: 12 + { child_comm: dbus-daemon } hitcount: 22 + { child_comm: nm-dispatcher.a } hitcount: 22 + { child_comm: evolution } hitcount: 35 + { child_comm: glib-pacrunner } hitcount: 59 + + Totals: + Hits: 206 + Entries: 21 + Dropped: 0 + + The previous example showed how to start and stop a hist trigger by + appending 'pause' and 'continue' to the hist trigger command. A + hist trigger can also be started in a paused state by initially + starting the trigger with ':pause' appended. This allows you to + start the trigger only when you're ready to start collecting data + and not before. For example, you could start the trigger in a + paused state, then unpause it and do something you want to measure, + then pause the trigger again when done. + + Of course, doing this manually can be difficult and error-prone, but + it is possible to automatically start and stop a hist trigger based + on some condition, via the enable_hist and disable_hist triggers. + + For example, suppose we wanted to take a look at the relative + weights in terms of skb length for each callpath that leads to a + netif_receieve_skb event when downloading a decent-sized file using + wget. + + First we set up an initially paused stacktrace trigger on the + netif_receive_skb event: + + # echo 'hist:key=stacktrace:vals=len:pause' > \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + + Next, we set up an 'enable_hist' trigger on the sched_process_exec + event, with an 'if filename==/usr/bin/wget' filter. The effect of + this new trigger is that it will 'unpause' the hist trigger we just + 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: + + # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger + + 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': + + # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger + + Whenever a process exits and the comm field of the disable_hist + trigger filter matches 'comm==wget', the netif_receive_skb hist + trigger is disabled. + + 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: + + $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz + + # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist + # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused] + + { stacktrace: + __netif_receive_skb_core+0x46d/0x990 + __netif_receive_skb+0x18/0x60 + netif_receive_skb_internal+0x23/0x90 + napi_gro_receive+0xc8/0x100 + ieee80211_deliver_skb+0xd6/0x270 [mac80211] + ieee80211_rx_handlers+0xccf/0x22f0 [mac80211] + ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211] + ieee80211_rx+0x31d/0x900 [mac80211] + iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm] + iwl_rx_dispatch+0x8e/0xf0 [iwldvm] + iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi] + irq_thread_fn+0x20/0x50 + irq_thread+0x11f/0x150 + kthread+0xd2/0xf0 + ret_from_fork+0x42/0x70 + } hitcount: 85 len: 28884 + { stacktrace: + __netif_receive_skb_core+0x46d/0x990 + __netif_receive_skb+0x18/0x60 + netif_receive_skb_internal+0x23/0x90 + napi_gro_complete+0xa4/0xe0 + dev_gro_receive+0x23a/0x360 + napi_gro_receive+0x30/0x100 + ieee80211_deliver_skb+0xd6/0x270 [mac80211] + ieee80211_rx_handlers+0xccf/0x22f0 [mac80211] + ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211] + ieee80211_rx+0x31d/0x900 [mac80211] + iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm] + iwl_rx_dispatch+0x8e/0xf0 [iwldvm] + iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi] + irq_thread_fn+0x20/0x50 + irq_thread+0x11f/0x150 + kthread+0xd2/0xf0 + } hitcount: 98 len: 664329 + { stacktrace: + __netif_receive_skb_core+0x46d/0x990 + __netif_receive_skb+0x18/0x60 + process_backlog+0xa8/0x150 + net_rx_action+0x15d/0x340 + __do_softirq+0x114/0x2c0 + do_softirq_own_stack+0x1c/0x30 + do_softirq+0x65/0x70 + __local_bh_enable_ip+0xb5/0xc0 + ip_finish_output+0x1f4/0x840 + ip_output+0x6b/0xc0 + ip_local_out_sk+0x31/0x40 + ip_send_skb+0x1a/0x50 + udp_send_skb+0x173/0x2a0 + udp_sendmsg+0x2bf/0x9f0 + inet_sendmsg+0x64/0xa0 + sock_sendmsg+0x3d/0x50 + } hitcount: 115 len: 13030 + { stacktrace: + __netif_receive_skb_core+0x46d/0x990 + __netif_receive_skb+0x18/0x60 + netif_receive_skb_internal+0x23/0x90 + napi_gro_complete+0xa4/0xe0 + napi_gro_flush+0x6d/0x90 + iwl_pcie_irq_handler+0x92a/0x12f0 [iwlwifi] + irq_thread_fn+0x20/0x50 + irq_thread+0x11f/0x150 + kthread+0xd2/0xf0 + ret_from_fork+0x42/0x70 + } hitcount: 934 len: 5512212 + + Totals: + Hits: 1232 + Entries: 4 + Dropped: 0 + + The above shows all the netif_receive_skb callpaths and their total + lengths for the duration of the wget command. + + The 'clear' hist trigger param can be used to clear the hash table. + 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: + + # 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: + + # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist + # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused] + + Totals: + Hits: 0 + Entries: 0 + Dropped: 0 + + Since we want to see the detailed list of every netif_receive_skb + 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: + + # echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger + + # echo 'disable_event:net:netif_receive_skb if comm==wget' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger + + 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: + + # cat /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger + enable_event:net:netif_receive_skb:unlimited if filename==/usr/bin/wget + enable_hist:net:netif_receive_skb:unlimited if filename==/usr/bin/wget + + # cat /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger + enable_event:net:netif_receive_skb:unlimited if comm==wget + disable_hist:net:netif_receive_skb:unlimited if comm==wget + + In other words, whenever either of the sched_process_exec or + 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: + + $ 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: + + # cat /sys/kernel/debug/tracing/trace + + # tracer: nop + # + # entries-in-buffer/entries-written: 183/1426 #P:4 + # + # _-----=> irqs-off + # / _----=> need-resched + # | / _---=> hardirq/softirq + # || / _--=> preempt-depth + # ||| / delay + # TASK-PID CPU# |||| TIMESTAMP FUNCTION + # | | | |||| | | + wget-15108 [000] ..s1 31769.606929: netif_receive_skb: dev=lo skbaddr=ffff88009c353100 len=60 + wget-15108 [000] ..s1 31769.606999: netif_receive_skb: dev=lo skbaddr=ffff88009c353200 len=60 + dnsmasq-1382 [000] ..s1 31769.677652: netif_receive_skb: dev=lo skbaddr=ffff88009c352b00 len=130 + dnsmasq-1382 [000] ..s1 31769.685917: netif_receive_skb: dev=lo skbaddr=ffff88009c352200 len=138 + ##### CPU 2 buffer started #### + irq/29-iwlwifi-559 [002] ..s. 31772.031529: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433d00 len=2948 + irq/29-iwlwifi-559 [002] ..s. 31772.031572: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432200 len=1500 + irq/29-iwlwifi-559 [002] ..s. 31772.032196: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433100 len=2948 + irq/29-iwlwifi-559 [002] ..s. 31772.032761: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433000 len=2948 + irq/29-iwlwifi-559 [002] ..s. 31772.033220: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432e00 len=1500 + . + . + .
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 23/30 tracing: Add support for multiple hist triggers per event
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Allow users to define any number of hist triggers per trace event. Any number of hist triggers may be added for a given event, which may differ by key, value, or filter.
Reading the event's 'hist' file will display the output of all the hist triggers defined on an event concatenated in the order they were defined.
--- Documentation/trace/events.txt | 154 +++++++++++++++++++++++++++++++++-- kernel/trace/trace.c | 8 +- kernel/trace/trace_events_hist.c | 172 +++++++++++++++++++++++++++++++-------- 3 files changed, 293 insertions(+), 41 deletions(-)
Documentation/trace/events.txt +148 -6
@@ -550,12 +550,14 @@ The following commands are supported: 'hist' triggers add a 'hist' file to each event's subdirectory. Reading the 'hist' file for the event will dump the hash table in - its entirety to stdout. Each printed hash table entry is a simple - list of the keys and values comprising the entry; keys are printed - first and are delineated by curly braces, and are followed by the - set of value fields for the entry. By default, numeric fields are - displayed as base-10 integers. This can be modified by appending - any of the following modifiers to the field name: + its entirety to stdout. If there are multiple hist triggers + attached to an event, there will be a table for each trigger in the + output. Each printed hash table entry is a simple list of the keys + and values comprising the entry; keys are printed first and are + delineated by curly braces, and are followed by the set of value + fields for the entry. By default, numeric fields are displayed as + base-10 integers. This can be 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
@@ -1667,3 +1669,143 @@ The following commands are supported: . . . + + The following example demonstrates how multiple hist triggers can be + 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. + + # echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + # echo 'hist:keys=skbaddr.hex:vals=len if len > 4096' >> \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + # echo 'hist:keys=skbaddr.hex:vals=len if len == 256' >> \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + # echo 'hist:keys=skbaddr.hex:vals=len' >> \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + # echo 'hist:keys=len:vals=common_preempt_count' >> \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + + The above set of commands create four triggers differing only in + their filters, along with a completely different though fairly + nonsensical trigger. Note that in order to append multiple hist + triggers to the same file, you should use the '>>' operator to + append them ('>' will also add the new hist trigger, but will remove + any existing hist triggers beforehand). + + Displaying the contents of the 'hist' file for the event shows the + contents of all five histograms: + + # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist + + # event histogram + # + # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active] + # + + { len: 176 } hitcount: 1 common_preempt_count: 0 + { len: 223 } hitcount: 1 common_preempt_count: 0 + { len: 4854 } hitcount: 1 common_preempt_count: 0 + { len: 395 } hitcount: 1 common_preempt_count: 0 + { len: 177 } hitcount: 1 common_preempt_count: 0 + { len: 446 } hitcount: 1 common_preempt_count: 0 + { len: 1601 } hitcount: 1 common_preempt_count: 0 + . + . + . + { len: 1280 } hitcount: 66 common_preempt_count: 0 + { len: 116 } hitcount: 81 common_preempt_count: 40 + { len: 708 } hitcount: 112 common_preempt_count: 0 + { len: 46 } hitcount: 221 common_preempt_count: 0 + { len: 1264 } hitcount: 458 common_preempt_count: 0 + + Totals: + Hits: 1428 + Entries: 147 + Dropped: 0 + + + # event histogram + # + # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] + # + + { skbaddr: ffff8800baee5e00 } hitcount: 1 len: 130 + { skbaddr: ffff88005f3d5600 } hitcount: 1 len: 1280 + { skbaddr: ffff88005f3d4900 } hitcount: 1 len: 1280 + { skbaddr: ffff88009fed6300 } hitcount: 1 len: 115 + { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 115 + { skbaddr: ffff88008cdb1900 } hitcount: 1 len: 46 + { skbaddr: ffff880064b5ef00 } hitcount: 1 len: 118 + { skbaddr: ffff880044e3c700 } hitcount: 1 len: 60 + { skbaddr: ffff880100065900 } hitcount: 1 len: 46 + { skbaddr: ffff8800d46bd500 } hitcount: 1 len: 116 + { skbaddr: ffff88005f3d5f00 } hitcount: 1 len: 1280 + { skbaddr: ffff880100064700 } hitcount: 1 len: 365 + { skbaddr: ffff8800badb6f00 } hitcount: 1 len: 60 + . + . + . + { skbaddr: ffff88009fe0be00 } hitcount: 27 len: 24677 + { skbaddr: ffff88009fe0a400 } hitcount: 27 len: 23052 + { skbaddr: ffff88009fe0b700 } hitcount: 31 len: 25589 + { skbaddr: ffff88009fe0b600 } hitcount: 32 len: 27326 + { skbaddr: ffff88006a462800 } hitcount: 68 len: 71678 + { skbaddr: ffff88006a463700 } hitcount: 70 len: 72678 + { skbaddr: ffff88006a462b00 } hitcount: 71 len: 77589 + { skbaddr: ffff88006a463600 } hitcount: 73 len: 71307 + { skbaddr: ffff88006a462200 } hitcount: 81 len: 81032 + + Totals: + Hits: 1451 + Entries: 318 + Dropped: 0 + + + # event histogram + # + # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active] + # + + + Totals: + Hits: 0 + Entries: 0 + Dropped: 0 + + + # event histogram + # + # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active] + # + + { skbaddr: ffff88009fd2c300 } hitcount: 1 len: 7212 + { skbaddr: ffff8800d2bcce00 } hitcount: 1 len: 7212 + { skbaddr: ffff8800d2bcd700 } hitcount: 1 len: 7212 + { skbaddr: ffff8800d2bcda00 } hitcount: 1 len: 21492 + { skbaddr: ffff8800ae2e2d00 } hitcount: 1 len: 7212 + { skbaddr: ffff8800d2bcdb00 } hitcount: 1 len: 7212 + { skbaddr: ffff88006a4df500 } hitcount: 1 len: 4854 + { skbaddr: ffff88008ce47b00 } hitcount: 1 len: 18636 + { skbaddr: ffff8800ae2e2200 } hitcount: 1 len: 12924 + { skbaddr: ffff88005f3e1000 } hitcount: 1 len: 4356 + { skbaddr: ffff8800d2bcdc00 } hitcount: 2 len: 24420 + { skbaddr: ffff8800d2bcc200 } hitcount: 2 len: 12996 + + Totals: + Hits: 14 + Entries: 12 + Dropped: 0 + + + # event histogram + # + # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active] + # + + + Totals: + Hits: 0 + Entries: 0 + Dropped: 0
kernel/trace/trace.c +5 -3
@@ -3856,9 +3856,11 @@ static const char readme_msg[] ="\t sort field. The 'size' parameter can be used to specify more\n" "\t or fewer than the default 2048 entries for the hashtable size.\n\n" "\t Reading the 'hist' file for the event will dump the hash\n" -"\t table in its entirety to stdout. The default format used to\n" -"\t display a given field can be modified by appending any of the\n" -"\t following modifiers to the field name, as applicable:\n\n" +"\t table in its entirety to stdout. If there are multiple hist\n" +"\t triggers attached to an event, there will be a table for each\n" +"\t trigger in the output. The default format used to display a\n" +"\t given field can be modified by appending any of the following\n" +"\t modifiers to the field name, as applicable:\n\n" "\t .hex display a number as a hex value\n" "\t .sym display an address as a symbol\n" "\t .sym-offset display an address as a symbol and offset\n"
kernel/trace/trace_events_hist.c +140 -32
251 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 24/30 tracing: Add support for named triggers
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Named triggers are sets of triggers that share a common set of trigger data. An example of functionality that could benefit from this type of capability would be a set of inlined probes that would each contribute event counts, for example, to a shared counter data structure.
The first named trigger registered with a given name owns the common trigger data that the others subsequently registered with the same name will reference. The functions defined here allow users to add, delete, and find named triggers.
It also adds functions to pause and unpause named triggers; since named triggers act upon common data, they should also be paused and unpaused as a group.
--- kernel/trace/trace.h | 13 ++++ kernel/trace/trace_events_trigger.c | 143 ++++++++++++++++++++++++++++++++++++ 2 files changed, 156 insertions(+)
kernel/trace/trace.h +13 -0
@@ -1184,7 +1184,11 @@ struct event_trigger_data {char *filter_str;void *private_data;bool paused; +bool paused_tmp;struct list_head list; +char *name; +struct list_head named_list; +struct event_trigger_data *named_data; };/* Avoid typos */
@@ -1227,6 +1231,15 @@ extern void unregister_trigger(char *glob, struct event_trigger_ops *ops,extern int set_trigger_filter (char *filter_str,struct event_trigger_data *trigger_data,struct trace_event_file *file); +extern struct event_trigger_data *find_named_trigger (const char *name); +extern bool is_named_trigger (struct event_trigger_data *test); +extern int save_named_trigger (const char *name, +struct event_trigger_data *data); +extern void del_named_trigger (struct event_trigger_data *data); +extern void pause_named_trigger (struct event_trigger_data *data); +extern void unpause_named_trigger (struct event_trigger_data *data); +extern void set_named_trigger_data (struct event_trigger_data *data, +struct event_trigger_data *named_data);extern int register_event_command (struct event_command *cmd);extern int unregister_event_command (struct event_command *cmd);extern int register_trigger_hist_enable_disable_cmds (void );
kernel/trace/trace_events_trigger.c +143 -0
155 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 25/30 tracing: Add support for named hist triggers
In reply to Steven RostedtFrom: Tom Zanussi <[email protected]>
Allow users to define 'named' hist triggers. All triggers created with the same 'name=xxx' option will update the same shared histogram data.
This expands the hist trigger syntax from this:
# echo hist:keys=xxx ... [ if filter] > event/trigger
to this:
# echo hist:name=xxx:keys=xxx ... [ if filter] > event/trigger
Named histograms must use a 'compatible' set of keys and values, which means each event added to a set of named triggers must have the same names and types.
Reading the 'hist' file of any of the participating events will produce the same output as any other participating event, which is to be expected since they share the same data.
--- Documentation/trace/events.txt | 274 +++++++++++++++++++++++++++++++++++++-- kernel/trace/trace.c | 14 +- kernel/trace/trace_events_hist.c | 148 ++++++++++++++++++--- 3 files changed, 407 insertions(+), 29 deletions(-)
Documentation/trace/events.txt +266 -8
@@ -524,7 +524,7 @@ The following commands are supported: hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>] [:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue] - [:clear] [if <filter>] + [:clear][:name=histname1] [if <filter>] When a matching event is hit, an entry is added to a hash table using the key(s) and value(s) named. Keys and values correspond to
@@ -546,18 +546,28 @@ The following commands are supported: specified by the 'sort' keyword. If more than one field is specified, the result will be a 'sort within a sort': the first key is taken to be the primary sort key and the second the secondary - key. + key. If a hist trigger is given a name using the 'name' parameter, + its histogram data will be shared with other triggers of the same + name, and trigger hits will update this common data. Only triggers + with 'compatible' fields can be combined in this way; triggers are + 'compatible' if the fields named in the trigger share the same + number and type of fields and those fields also have the same names. + Note that any two events always share the compatible 'hitcount' and + 'stacktrace' fields and can therefore be combined using those + fields, however pointless that may be. 'hist' triggers add a 'hist' file to each event's subdirectory. Reading the 'hist' file for the event will dump the hash table in its entirety to stdout. If there are multiple hist triggers attached to an event, there will be a table for each trigger in the - output. Each printed hash table entry is a simple list of the keys - and values comprising the entry; keys are printed first and are - delineated by curly braces, and are followed by the set of value - fields for the entry. By default, numeric fields are displayed as - base-10 integers. This can be modified by appending any of the - following modifiers to the field name: + output. The table displayed for a named trigger will be the same as + any other instance having the same name. Each printed hash table + entry is a simple list of the keys and values comprising the entry; + keys are printed first and are delineated by curly braces, and are + followed by the set of value fields for the entry. By default, + numeric fields are displayed as base-10 integers. This can be + 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
@@ -1809,3 +1819,251 @@ The following commands are supported: Hits: 0 Entries: 0 Dropped: 0 + + Named triggers can be used to have triggers share a common set of + histogram data. This capability is mostly useful for combining the + 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: + + # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ + /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: + + # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist; + cat /sys/kernel/debug/tracing/events/net/netif_rx/hist + + # event histogram + # + # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] + # + + { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46 + { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76 + { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468 + { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46 + { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52 + { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168 + { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260 + { skbaddr: ffff880064505000 } hitcount: 1 len: 46 + { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32 + { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46 + { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44 + { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168 + { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40 + { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40 + { skbaddr: ffff880064505f00 } hitcount: 1 len: 174 + { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160 + { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76 + { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32 + { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988 + { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46 + { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44 + { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676 + { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107 + { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92 + { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142 + { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220 + { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92 + { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92 + { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675 + { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138 + { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138 + { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184 + { skbaddr: ffff880064504400 } hitcount: 4 len: 184 + { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184 + { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230 + { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196 + { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276 + { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276 + + Totals: + Hits: 81 + Entries: 42 + Dropped: 0 + # event histogram + # + # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] + # + + { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46 + { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76 + { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468 + { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46 + { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52 + { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168 + { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260 + { skbaddr: ffff880064505000 } hitcount: 1 len: 46 + { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32 + { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46 + { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44 + { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168 + { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40 + { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40 + { skbaddr: ffff880064505f00 } hitcount: 1 len: 174 + { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160 + { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76 + { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32 + { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988 + { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46 + { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44 + { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676 + { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107 + { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92 + { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142 + { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220 + { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92 + { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92 + { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675 + { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138 + { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138 + { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184 + { skbaddr: ffff880064504400 } hitcount: 4 len: 184 + { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184 + { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230 + { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196 + { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276 + { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276 + + Totals: + Hits: 81 + Entries: 42 + Dropped: 0 + + 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: + + # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger + # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \ + /sys/kernel/debug/tracing/events/net/netif_rx/trigger + + And displaying the output of either shows some interesting if + somewhat confusing output: + + # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist + # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist + + # event histogram + # + # trigger info: hist:name=bar:keys=stacktrace:vals=hitcount:sort=hitcount:size=2048 [active] + # + + { stacktrace: + _do_fork+0x18e/0x330 + kernel_thread+0x29/0x30 + kthreadd+0x154/0x1b0 + ret_from_fork+0x3f/0x70 + } hitcount: 1 + { stacktrace: + netif_rx_internal+0xb2/0xd0 + netif_rx_ni+0x20/0x70 + dev_loopback_xmit+0xaa/0xd0 + ip_mc_output+0x126/0x240 + ip_local_out_sk+0x31/0x40 + igmp_send_report+0x1e9/0x230 + igmp_timer_expire+0xe9/0x120 + call_timer_fn+0x39/0xf0 + run_timer_softirq+0x1e1/0x290 + __do_softirq+0xfd/0x290 + irq_exit+0x98/0xb0 + smp_apic_timer_interrupt+0x4a/0x60 + apic_timer_interrupt+0x6d/0x80 + cpuidle_enter+0x17/0x20 + call_cpuidle+0x3b/0x60 + cpu_startup_entry+0x22d/0x310 + } hitcount: 1 + { stacktrace: + netif_rx_internal+0xb2/0xd0 + netif_rx_ni+0x20/0x70 + dev_loopback_xmit+0xaa/0xd0 + ip_mc_output+0x17f/0x240 + ip_local_out_sk+0x31/0x40 + ip_send_skb+0x1a/0x50 + udp_send_skb+0x13e/0x270 + udp_sendmsg+0x2bf/0x980 + inet_sendmsg+0x67/0xa0 + sock_sendmsg+0x38/0x50 + SYSC_sendto+0xef/0x170 + SyS_sendto+0xe/0x10 + entry_SYSCALL_64_fastpath+0x12/0x6a + } hitcount: 2 + { stacktrace: + netif_rx_internal+0xb2/0xd0 + netif_rx+0x1c/0x60 + loopback_xmit+0x6c/0xb0 + dev_hard_start_xmit+0x219/0x3a0 + __dev_queue_xmit+0x415/0x4f0 + dev_queue_xmit_sk+0x13/0x20 + ip_finish_output2+0x237/0x340 + ip_finish_output+0x113/0x1d0 + ip_output+0x66/0xc0 + ip_local_out_sk+0x31/0x40 + ip_send_skb+0x1a/0x50 + udp_send_skb+0x16d/0x270 + udp_sendmsg+0x2bf/0x980 + inet_sendmsg+0x67/0xa0 + sock_sendmsg+0x38/0x50 + ___sys_sendmsg+0x14e/0x270 + } hitcount: 76 + { stacktrace: + netif_rx_internal+0xb2/0xd0 + netif_rx+0x1c/0x60 + loopback_xmit+0x6c/0xb0 + dev_hard_start_xmit+0x219/0x3a0 + __dev_queue_xmit+0x415/0x4f0 + dev_queue_xmit_sk+0x13/0x20 + ip_finish_output2+0x237/0x340 + ip_finish_output+0x113/0x1d0 + ip_output+0x66/0xc0 + ip_local_out_sk+0x31/0x40 + ip_send_skb+0x1a/0x50 + udp_send_skb+0x16d/0x270 + udp_sendmsg+0x2bf/0x980 + inet_sendmsg+0x67/0xa0 + sock_sendmsg+0x38/0x50 + ___sys_sendmsg+0x269/0x270 + } hitcount: 77 + { stacktrace: + netif_rx_internal+0xb2/0xd0 + netif_rx+0x1c/0x60 + loopback_xmit+0x6c/0xb0 + dev_hard_start_xmit+0x219/0x3a0 + __dev_queue_xmit+0x415/0x4f0 + dev_queue_xmit_sk+0x13/0x20 + ip_finish_output2+0x237/0x340 + ip_finish_output+0x113/0x1d0 + ip_output+0x66/0xc0 + ip_local_out_sk+0x31/0x40 + ip_send_skb+0x1a/0x50 + udp_send_skb+0x16d/0x270 + udp_sendmsg+0x2bf/0x980 + inet_sendmsg+0x67/0xa0 + sock_sendmsg+0x38/0x50 + SYSC_sendto+0xef/0x170 + } hitcount: 88 + { stacktrace: + _do_fork+0x18e/0x330 + SyS_clone+0x19/0x20 + entry_SYSCALL_64_fastpath+0x12/0x6a + } hitcount: 244 + + Totals: + Hits: 489 + Entries: 7 + Dropped: 0
kernel/trace/trace.c +10 -4
@@ -3842,6 +3842,7 @@ static const char readme_msg[] ="\t [:sort=<field1[,field2,...]>]\n" "\t [:size=#entries]\n" "\t [:pause][:continue][:clear]\n" +"\t [:name=histname1]\n" "\t [if <filter>]\n\n" "\t When a matching event is hit, an entry is added to a hash\n" "\t table using the key(s) and value(s) named, and the value of a\n"
@@ -3854,13 +3855,18 @@ static const char readme_msg[] ="\t specified using the 'sort' keyword. The sort direction can\n" "\t be modified by appending '.descending' or '.ascending' to a\n" "\t sort field. The 'size' parameter can be used to specify more\n" -"\t or fewer than the default 2048 entries for the hashtable size.\n\n" +"\t or fewer than the default 2048 entries for the hashtable size.\n" +"\t If a hist trigger is given a name using the 'name' parameter,\n" +"\t its histogram data will be shared with other triggers of the\n" +"\t same name, and trigger hits will update this common data.\n\n" "\t Reading the 'hist' file for the event will dump the hash\n" "\t table in its entirety to stdout. If there are multiple hist\n" "\t triggers attached to an event, there will be a table for each\n" -"\t trigger in the output. The default format used to display a\n" -"\t given field can be modified by appending any of the following\n" -"\t modifiers to the field name, as applicable:\n\n" +"\t trigger in the output. The table displayed for a named\n" +"\t trigger will be the same as any other instance having the\n" +"\t same name. The default format used to display a given field\n" +"\t can be modified by appending any of the following modifiers\n" +"\t to the field name, as applicable:\n\n" "\t .hex display a number as a hex value\n" "\t .sym display an address as a symbol\n" "\t .sym-offset display an address as a symbol and offset\n"
kernel/trace/trace_events_hist.c +131 -17
269 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 26/30 kselftests/ftrace : Add event trigger testcases
In reply to Steven RostedtFrom: Masami Hiramatsu <[email protected]>
This adds simple event trigger testcases for ftracetest, which covers following triggers.
- traceon-traceoff trigger
- enable/disable_event trigger
- snapshot trigger
- stacktrace trigger
- trigger filters
Here is the test result.
----
# ./ftracetest test.d/trigger/ === Ftrace unit tests === [1] event trigger - test event enable/disable trigger [PASS] [2] event trigger - test trigger filter [PASS] [3] event trigger - test snapshot-trigger [PASS] [4] event trigger - test stacktrace-trigger [PASS] [5] event trigger - test traceon/off trigger [PASS]
# of passed: 5 # of failed: 0 # of unresolved: 0 # of untested: 0 # of unsupported: 0 # of xfailed: 0 # of undefined(test bug): 0 ----
--- tools/testing/selftests/ftrace/test.d/functions | 9 +++ .../ftrace/test.d/trigger/trigger-eventonoff.tc | 64 ++++++++++++++++++++++ .../ftrace/test.d/trigger/trigger-filter.tc | 59 ++++++++++++++++++++ .../ftrace/test.d/trigger/trigger-snapshot.tc | 56 +++++++++++++++++++ .../ftrace/test.d/trigger/trigger-stacktrace.tc | 53 ++++++++++++++++++ .../ftrace/test.d/trigger/trigger-traceonoff.tc | 58 ++++++++++++++++++++ 6 files changed, 299 insertions(+) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-eventonoff.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-filter.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-snapshot.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-stacktrace.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-traceonoff.tc
tools/testing/selftests/ftrace/test.d/functions +9 -0
@@ -14,3 +14,12 @@ enable_tracing() { # start trace recording reset_tracer() { # reset the current tracer echo nop > current_tracer } + +reset_trigger() { # reset all current setting triggers + grep -v ^# events/*/*/trigger | + while read line; do + cmd=`echo $line | cut -f2- -d: | cut -f1 -d" "` + echo "!$cmd" > `echo $line | cut -f1 -d:` + done +} +
tools/testing/selftests/ftrace/test.d/trigger/trigger-eventonoff.tc new file +64 -0
64 lines not on this page · raw message
tools/testing/selftests/ftrace/test.d/trigger/trigger-filter.tc new file +59 -0
59 lines not on this page · raw message
tools/testing/selftests/ftrace/test.d/trigger/trigger-snapshot.tc new file +56 -0
56 lines not on this page · raw message
tools/testing/selftests/ftrace/test.d/trigger/trigger-stacktrace.tc new file +53 -0
53 lines not on this page · raw message
tools/testing/selftests/ftrace/test.d/trigger/trigger-traceonoff.tc new file +58 -0
58 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 27/30 kselftests/ftrace: Add hist trigger testcases
In reply to Steven RostedtFrom: Masami Hiramatsu <[email protected]>
Add the hist trigger testcases for ftracetest. This checks the basic histogram trigger behaviors like as;
- Histogram trigger itself
- Histogram with string key
- Histogram with compound keys
- Histogram with sort key
- Histogram trigger modifiers (execname, hex, syscall)
- Multiple histograms on an event
- Named histogram
- Named histogram on multi events
Here is the test result.
----
# ./ftracetest test.d/trigger/*hist*.tc === Ftrace unit tests === [1] event trigger - test histogram modifiers [PASS] [2] event trigger - test histogram trigger [PASS] [3] event trigger - test multiple histogram triggers [PASS]
# of passed: 3 # of failed: 0 # of unresolved: 0 # of untested: 0 # of unsupported: 0 # of xfailed: 0 # of undefined(test bug): 0 ----
--- .../ftrace/test.d/trigger/trigger-hist-mod.tc | 65 +++++++++++++++++ .../ftrace/test.d/trigger/trigger-hist.tc | 83 ++++++++++++++++++++++ .../ftrace/test.d/trigger/trigger-multihist.tc | 73 +++++++++++++++++++ 3 files changed, 221 insertions(+) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-mod.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-multihist.tc
tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-mod.tc new file +65 -0
@@ -0,0 +1,65 @@ +#!/bin/sh +# description: event trigger - test histogram modifiers + +do_reset() { + reset_trigger + echo > set_event + clear_trace +} + +fail() { #msg + do_reset + echo $1 + exit $FAIL +} + +if [ ! -f set_event -o ! -d events/sched ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f events/sched/sched_process_fork/trigger ]; then + echo "event trigger is not supported" + exit_unsupported +fi + +reset_tracer +do_reset + +FEATURE=`grep hist events/sched/sched_process_fork/trigger` +if [ -z "$FEATURE" ]; then + echo "hist trigger is not supported" + exit_unsupported +fi + +echo "Test histogram with execname modifier" + +echo 'hist:keys=common_pid.execname' > events/sched/sched_process_fork/trigger +for i in `seq 1 10` ; do ( echo "forked" > /dev/null); done +COMM=`cat /proc/$$/comm` +grep "common_pid: $COMM" events/sched/sched_process_fork/hist > /dev/null || \ + fail "execname modifier on sched_process_fork did not work" + +reset_trigger + +echo "Test histogram with hex modifier" + +echo 'hist:keys=parent_pid.hex' > events/sched/sched_process_fork/trigger +for i in `seq 1 10` ; do ( echo "forked" > /dev/null); done +# Note that $$ is the parent pid. $PID is current PID. +HEX=`printf %x $PID` +grep "parent_pid: $HEX" events/sched/sched_process_fork/hist > /dev/null || \ + fail "hex modifier on sched_process_fork did not work" + +reset_trigger + +echo "Test histogram with syscall modifier" + +echo 'hist:keys=id.syscall' > events/raw_syscalls/sys_exit/trigger +for i in `seq 1 10` ; do ( echo "forked" > /dev/null); done +grep "id: sys_" events/raw_syscalls/sys_exit/hist > /dev/null || \ + fail "syscall modifier on raw_syscalls/sys_exit did not work" + +do_reset + +exit 0
tools/testing/selftests/ftrace/test.d/trigger/trigger-hist.tc new file +83 -0
83 lines not on this page · raw message
tools/testing/selftests/ftrace/test.d/trigger/trigger-multihist.tc new file +73 -0
73 lines not on this page · raw message
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 28/30 tracing: Add hist trigger log2 modifier
In reply to Steven RostedtFrom: Namhyung Kim <[email protected]>
Allow users to have numeric fields displayed as log2 values in case value range is very wide by appending '.log2' to field names.
For example,
# echo 'hist:key=bytes_req' > kmalloc/trigger # cat kmalloc/hist
{ bytes_req: 504 } hitcount: 1
{ bytes_req: 11 } hitcount: 1
{ bytes_req: 104 } hitcount: 1
{ bytes_req: 48 } hitcount: 1
{ bytes_req: 2048 } hitcount: 1
{ bytes_req: 4096 } hitcount: 1
{ bytes_req: 240 } hitcount: 1
{ bytes_req: 392 } hitcount: 1
{ bytes_req: 13 } hitcount: 1
{ bytes_req: 28 } hitcount: 1
{ bytes_req: 12 } hitcount: 1
{ bytes_req: 64 } hitcount: 2
{ bytes_req: 128 } hitcount: 2
{ bytes_req: 32 } hitcount: 2
{ bytes_req: 8 } hitcount: 11
{ bytes_req: 10 } hitcount: 13
{ bytes_req: 24 } hitcount: 25
{ bytes_req: 160 } hitcount: 29
{ bytes_req: 16 } hitcount: 33
{ bytes_req: 80 } hitcount: 36When using '.log2' modifier, the output looks like:
# echo 'hist:key=bytes_req.log2' > kmalloc/trigger # cat kmalloc/hist
{ bytes_req: ~ 2^12 } hitcount: 1
{ bytes_req: ~ 2^11 } hitcount: 1
{ bytes_req: ~ 2^9 } hitcount: 2
{ bytes_req: ~ 2^6 } hitcount: 3
{ bytes_req: ~ 2^3 } hitcount: 13
{ bytes_req: ~ 2^5 } hitcount: 19
{ bytes_req: ~ 2^8 } hitcount: 49
{ bytes_req: ~ 2^7 } hitcount: 57
{ bytes_req: ~ 2^4 } hitcount: 74--- kernel/trace/trace.c | 1 + kernel/trace/trace_events_hist.c | 20 ++++++++++++++++++++ 2 files changed, 21 insertions(+)
kernel/trace/trace.c +1 -0
@@ -3872,6 +3872,7 @@ static const char readme_msg[] ="\t .sym-offset display an address as a symbol and offset\n" "\t .execname display a common_pid as a program name\n" "\t .syscall display a syscall id as a syscall name\n\n" +"\t .log2 display log2 value rather than raw number\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" "\t until told to do so. 'continue' can be used to start or\n"
kernel/trace/trace_events_hist.c +20 -0
@@ -68,6 +68,13 @@ static u64 hist_field_pstring(struct hist_field *hist_field, void *event)return (u64 )(unsigned long )*addr; } +static u64 hist_field_log2 (struct hist_field *hist_field,void *event) +{ +u64 val = *(u64 *)(event + hist_field->field->offset); + +return (u64 )ilog2 (roundup_pow_of_two (val)); +} +#define DEFINE_HIST_FIELD_FN (type) \ static u64 hist_field_##type(struct hist_field *hist_field, void *event)\ { \
@@ -111,6 +118,7 @@ enum hist_field_flags {HIST_FIELD_FL_EXECNAME =64 ,HIST_FIELD_FL_SYSCALL =128 ,HIST_FIELD_FL_STACKTRACE =256 , + HIST_FIELD_FL_LOG2 = 512, }; struct hist_trigger_attrs {
@@ -358,6 +366,11 @@ static struct hist_field *create_hist_field(struct ftrace_event_field *field, goto out; } +if (flags &HIST_FIELD_FL_LOG2 ) { + hist_field->fn = hist_field_log2; + goto out; + } +if (is_string_field (field)) { flags |=HIST_FIELD_FL_STRING ;
@@ -522,6 +535,8 @@ static int create_key_field(struct hist_trigger_data *hist_data, flags |=HIST_FIELD_FL_EXECNAME ; else if (strcmp(field_str, "syscall") == 0) flags |= HIST_FIELD_FL_SYSCALL; + else if (strcmp(field_str, "log2") == 0) + flags |= HIST_FIELD_FL_LOG2; else { ret = -EINVAL; goto out;
@@ -980,6 +995,9 @@ hist_trigger_entry_print(struct seq_file *m, key + key_field->offset, HIST_STACKTRACE_DEPTH); multiline = true; + }else if (key_field->flags &HIST_FIELD_FL_LOG2 ) { +seq_printf (m,"%s: ~ 2^%-2llu" , key_field->field->name, + *(u64 *)(key + key_field->offset)); }else if (key_field->flags &HIST_FIELD_FL_STRING ) {seq_printf (m,"%s: %-50s" , key_field->field->name, (char *)(key + key_field->offset));
@@ -1112,6 +1130,8 @@ static const char *get_hist_field_flags(struct hist_field *hist_field) flags_str ="execname" ; else if (hist_field->flags & HIST_FIELD_FL_SYSCALL) flags_str ="syscall" ; + else if (hist_field->flags & HIST_FIELD_FL_LOG2) + flags_str ="log2" ;return flags_str; }
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 29/30 kselftests/ftrace: Add a test for log2 modifier of hist trigger
In reply to Steven RostedtFrom: Masami Hiramatsu <[email protected]>
Add a test for log2 modifier of hist trigger in hist_mod.tc. Here is the test result.
----
# ./ftracetest test.d/trigger/trigger-hist-mod.tc === Ftrace unit tests === [1] event trigger - test histogram modifiers [PASS]
# of passed: 1 # of failed: 0 # of unresolved: 0 # of untested: 0 # of unsupported: 0 # of xfailed: 0 # of undefined(test bug): 0 ----
--- .../selftests/ftrace/test.d/trigger/trigger-hist-mod.tc | 10 ++++++++++ 1 file changed, 10 insertions(+)
tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-mod.tc +10 -0
@@ -60,6 +60,16 @@ for i in `seq 1 10` ; do ( echo "forked" > /dev/null); done grep "id: sys_" events/raw_syscalls/sys_exit/hist > /dev/null || \ fail "syscall modifier on raw_syscalls/sys_exit did not work" + +reset_trigger + +echo "Test histgram with log2 modifier" + +echo 'hist:keys=bytes_req.log2' > events/kmem/kmalloc/trigger +for i in `seq 1 10` ; do ( echo "forked" > /dev/null); done +grep 'bytes_req: ~ 2^[0-9]*' events/kmem/kmalloc/hist > /dev/null || \ + fail "log2 modifier on kmem/kmalloc did not work" + do_reset exit 0
Signature · 1 line
2.8.0.rc3
Steven Rostedt
maintainerPATCH 30/30 tracing: Fix unsigned comparison to zero in hist trigger code
In reply to Steven RostedtFrom: "Steven Rostedt (Red Hat)" <[email protected]>
Fengguang Wu's bot found two comparisons of unsigned integers to zero. These were real bugs, as it would miss error conditions returned to zero.
trace_events_hist.c:426:6-9: WARNING: Unsigned expression compared with zero: idx < 0 trace_events_hist.c:568:5-14: WARNING: Unsigned expression compared with zero: n_entries < 0
--- kernel/trace/trace_events_hist.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-)
kernel/trace/trace_events_hist.c +2 -2
@@ -734,7 +734,7 @@ static int create_tracing_map_fields(struct hist_trigger_data *hist_data)struct tracing_map *map = hist_data->map;struct ftrace_event_field *field;struct hist_field *hist_field; -unsigned int i, idx; +int i, idx;for_each_hist_field (i, hist_data) { hist_field = hist_data->fields[i];
@@ -1036,7 +1036,7 @@ static int print_entries(struct seq_file *m, {struct tracing_map_sort_entry **sort_entries =NULL ;struct tracing_map *map = hist_data->map; -unsigned int i, n_entries; +int i, n_entries; n_entries = tracing_map_sort_entries(map, hist_data->sort_keys, hist_data->n_sort_keys,
Signature · 1 line
2.8.0.rc3