* [PATCH v4 1/7] tracing: Make ftrace_event_field checking functions available
2015-04-10 16:05 [PATCH v4 0/7] tracing: 'hist' triggers Tom Zanussi
@ 2015-04-10 16:05 ` Tom Zanussi
2015-04-10 16:05 ` [PATCH v4 2/7] tracing: Add event record param to trigger_ops.func() Tom Zanussi
` (6 subsequent siblings)
7 siblings, 0 replies; 13+ messages in thread
From: Tom Zanussi @ 2015-04-10 16:05 UTC (permalink / raw)
To: rostedt
Cc: masami.hiramatsu.pt, namhyung, andi, alexei.starovoitov,
linux-kernel, Tom Zanussi
Make is_string_field() and is_function_field() accessible outside of
trace_event_filters.c for other users of ftrace_event_fields.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
kernel/trace/trace.h | 12 ++++++++++++
kernel/trace/trace_events_filter.c | 12 ------------
2 files changed, 12 insertions(+), 12 deletions(-)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index d951ded..6177486 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1050,6 +1050,18 @@ struct filter_pred {
unsigned short right;
};
+static inline bool is_string_field(struct ftrace_event_field *field)
+{
+ return field->filter_type == FILTER_DYN_STRING ||
+ field->filter_type == FILTER_STATIC_STRING ||
+ field->filter_type == FILTER_PTR_STRING;
+}
+
+static inline bool is_function_field(struct ftrace_event_field *field)
+{
+ return field->filter_type == FILTER_TRACE_FN;
+}
+
extern enum regex_type
filter_parse_regex(char *buff, int len, char **search, int *not);
extern void print_event_filter(struct ftrace_event_file *file,
diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index ced69da..aa8ab85 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -917,18 +917,6 @@ int filter_assign_type(const char *type)
return FILTER_OTHER;
}
-static bool is_function_field(struct ftrace_event_field *field)
-{
- return field->filter_type == FILTER_TRACE_FN;
-}
-
-static bool is_string_field(struct ftrace_event_field *field)
-{
- return field->filter_type == FILTER_DYN_STRING ||
- field->filter_type == FILTER_STATIC_STRING ||
- field->filter_type == FILTER_PTR_STRING;
-}
-
static int is_legal_op(struct ftrace_event_field *field, int op)
{
if (is_string_field(field) &&
--
1.9.3
^ permalink raw reply related [flat|nested] 13+ messages in thread* [PATCH v4 2/7] tracing: Add event record param to trigger_ops.func()
2015-04-10 16:05 [PATCH v4 0/7] tracing: 'hist' triggers Tom Zanussi
2015-04-10 16:05 ` [PATCH v4 1/7] tracing: Make ftrace_event_field checking functions available Tom Zanussi
@ 2015-04-10 16:05 ` Tom Zanussi
2015-04-10 16:05 ` [PATCH v4 3/7] tracing: Add get_syscall_name() Tom Zanussi
` (5 subsequent siblings)
7 siblings, 0 replies; 13+ messages in thread
From: Tom Zanussi @ 2015-04-10 16:05 UTC (permalink / raw)
To: rostedt
Cc: masami.hiramatsu.pt, namhyung, andi, alexei.starovoitov,
linux-kernel, Tom Zanussi
Some triggers may need access to the trace event, so pass it in. Also
fix up the existing trigger funcs and their callers.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
include/linux/ftrace_event.h | 7 ++++---
kernel/trace/trace.h | 6 ++++--
kernel/trace/trace_events_trigger.c | 35 ++++++++++++++++++-----------------
3 files changed, 26 insertions(+), 22 deletions(-)
diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
index c674ee8..b03dfa8 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -429,7 +429,8 @@ extern int call_filter_check_discard(struct ftrace_event_call *call, void *rec,
extern enum event_trigger_type event_triggers_call(struct ftrace_event_file *file,
void *rec);
extern void event_triggers_post_call(struct ftrace_event_file *file,
- enum event_trigger_type tt);
+ enum event_trigger_type tt,
+ void *rec);
/**
* ftrace_trigger_soft_disabled - do triggers and test if soft disabled
@@ -512,7 +513,7 @@ event_trigger_unlock_commit(struct ftrace_event_file *file,
trace_buffer_unlock_commit(buffer, event, irq_flags, pc);
if (tt)
- event_triggers_post_call(file, tt);
+ event_triggers_post_call(file, tt, entry);
}
/**
@@ -545,7 +546,7 @@ event_trigger_unlock_commit_regs(struct ftrace_event_file *file,
irq_flags, pc, regs);
if (tt)
- event_triggers_post_call(file, tt);
+ event_triggers_post_call(file, tt, entry);
}
enum {
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 6177486..89dd87a 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1125,7 +1125,8 @@ struct event_trigger_data {
* @func: The trigger 'probe' function called when the triggering
* event occurs. The data passed into this callback is the data
* that was supplied to the event_command @reg() function that
- * registered the trigger (see struct event_command).
+ * registered the trigger (see struct event_command) along with
+ * the trace record, rec.
*
* @init: An optional initialization function called for the trigger
* when the trigger is registered (via the event_command reg()
@@ -1150,7 +1151,8 @@ struct event_trigger_data {
* (see trace_event_triggers.c).
*/
struct event_trigger_ops {
- void (*func)(struct event_trigger_data *data);
+ void (*func)(struct event_trigger_data *data,
+ void *rec);
int (*init)(struct event_trigger_ops *ops,
struct event_trigger_data *data);
void (*free)(struct event_trigger_ops *ops,
diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
index 8712df9..a8dfd4e 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -74,7 +74,7 @@ event_triggers_call(struct ftrace_event_file *file, void *rec)
list_for_each_entry_rcu(data, &file->triggers, list) {
if (!rec) {
- data->ops->func(data);
+ data->ops->func(data, rec);
continue;
}
filter = rcu_dereference_sched(data->filter);
@@ -84,7 +84,7 @@ event_triggers_call(struct ftrace_event_file *file, void *rec)
tt |= data->cmd_ops->trigger_type;
continue;
}
- data->ops->func(data);
+ data->ops->func(data, rec);
}
return tt;
}
@@ -104,13 +104,14 @@ EXPORT_SYMBOL_GPL(event_triggers_call);
*/
void
event_triggers_post_call(struct ftrace_event_file *file,
- enum event_trigger_type tt)
+ enum event_trigger_type tt,
+ void *rec)
{
struct event_trigger_data *data;
list_for_each_entry_rcu(data, &file->triggers, list) {
if (data->cmd_ops->trigger_type & tt)
- data->ops->func(data);
+ data->ops->func(data, rec);
}
}
EXPORT_SYMBOL_GPL(event_triggers_post_call);
@@ -751,7 +752,7 @@ static int set_trigger_filter(char *filter_str,
}
static void
-traceon_trigger(struct event_trigger_data *data)
+traceon_trigger(struct event_trigger_data *data, void *rec)
{
if (tracing_is_on())
return;
@@ -760,7 +761,7 @@ traceon_trigger(struct event_trigger_data *data)
}
static void
-traceon_count_trigger(struct event_trigger_data *data)
+traceon_count_trigger(struct event_trigger_data *data, void *rec)
{
if (tracing_is_on())
return;
@@ -775,7 +776,7 @@ traceon_count_trigger(struct event_trigger_data *data)
}
static void
-traceoff_trigger(struct event_trigger_data *data)
+traceoff_trigger(struct event_trigger_data *data, void *rec)
{
if (!tracing_is_on())
return;
@@ -784,7 +785,7 @@ traceoff_trigger(struct event_trigger_data *data)
}
static void
-traceoff_count_trigger(struct event_trigger_data *data)
+traceoff_count_trigger(struct event_trigger_data *data, void *rec)
{
if (!tracing_is_on())
return;
@@ -880,13 +881,13 @@ static struct event_command trigger_traceoff_cmd = {
#ifdef CONFIG_TRACER_SNAPSHOT
static void
-snapshot_trigger(struct event_trigger_data *data)
+snapshot_trigger(struct event_trigger_data *data, void *rec)
{
tracing_snapshot();
}
static void
-snapshot_count_trigger(struct event_trigger_data *data)
+snapshot_count_trigger(struct event_trigger_data *data, void *rec)
{
if (!data->count)
return;
@@ -894,7 +895,7 @@ snapshot_count_trigger(struct event_trigger_data *data)
if (data->count != -1)
(data->count)--;
- snapshot_trigger(data);
+ snapshot_trigger(data, rec);
}
static int
@@ -973,13 +974,13 @@ static __init int register_trigger_snapshot_cmd(void) { return 0; }
#define STACK_SKIP 3
static void
-stacktrace_trigger(struct event_trigger_data *data)
+stacktrace_trigger(struct event_trigger_data *data, void *rec)
{
trace_dump_stack(STACK_SKIP);
}
static void
-stacktrace_count_trigger(struct event_trigger_data *data)
+stacktrace_count_trigger(struct event_trigger_data *data, void *rec)
{
if (!data->count)
return;
@@ -987,7 +988,7 @@ stacktrace_count_trigger(struct event_trigger_data *data)
if (data->count != -1)
(data->count)--;
- stacktrace_trigger(data);
+ stacktrace_trigger(data, rec);
}
static int
@@ -1058,7 +1059,7 @@ struct enable_trigger_data {
};
static void
-event_enable_trigger(struct event_trigger_data *data)
+event_enable_trigger(struct event_trigger_data *data, void *rec)
{
struct enable_trigger_data *enable_data = data->private_data;
@@ -1069,7 +1070,7 @@ event_enable_trigger(struct event_trigger_data *data)
}
static void
-event_enable_count_trigger(struct event_trigger_data *data)
+event_enable_count_trigger(struct event_trigger_data *data, void *rec)
{
struct enable_trigger_data *enable_data = data->private_data;
@@ -1083,7 +1084,7 @@ event_enable_count_trigger(struct event_trigger_data *data)
if (data->count != -1)
(data->count)--;
- event_enable_trigger(data);
+ event_enable_trigger(data, rec);
}
static int
--
1.9.3
^ permalink raw reply related [flat|nested] 13+ messages in thread* [PATCH v4 3/7] tracing: Add get_syscall_name()
2015-04-10 16:05 [PATCH v4 0/7] tracing: 'hist' triggers Tom Zanussi
2015-04-10 16:05 ` [PATCH v4 1/7] tracing: Make ftrace_event_field checking functions available Tom Zanussi
2015-04-10 16:05 ` [PATCH v4 2/7] tracing: Add event record param to trigger_ops.func() Tom Zanussi
@ 2015-04-10 16:05 ` Tom Zanussi
2015-04-10 16:05 ` [PATCH v4 4/7] tracing: Add a per-event-trigger 'paused' field Tom Zanussi
` (4 subsequent siblings)
7 siblings, 0 replies; 13+ messages in thread
From: Tom Zanussi @ 2015-04-10 16:05 UTC (permalink / raw)
To: rostedt
Cc: masami.hiramatsu.pt, namhyung, andi, alexei.starovoitov,
linux-kernel, Tom Zanussi
Add a utility function to grab the syscall name from the syscall
metadata, given a syscall id.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
kernel/trace/trace.h | 5 +++++
kernel/trace/trace_syscalls.c | 11 +++++++++++
2 files changed, 16 insertions(+)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 89dd87a..3d38c2e 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1317,8 +1317,13 @@ int perf_ftrace_event_register(struct ftrace_event_call *call,
#ifdef CONFIG_FTRACE_SYSCALLS
void init_ftrace_syscalls(void);
+const char *get_syscall_name(int syscall);
#else
static inline void init_ftrace_syscalls(void) { }
+static inline const char *get_syscall_name(int syscall)
+{
+ return NULL;
+}
#endif
#ifdef CONFIG_EVENT_TRACING
diff --git a/kernel/trace/trace_syscalls.c b/kernel/trace/trace_syscalls.c
index f97f6e3..d137e0a 100644
--- a/kernel/trace/trace_syscalls.c
+++ b/kernel/trace/trace_syscalls.c
@@ -106,6 +106,17 @@ static struct syscall_metadata *syscall_nr_to_meta(int nr)
return syscalls_metadata[nr];
}
+const char *get_syscall_name(int syscall)
+{
+ struct syscall_metadata *entry;
+
+ entry = syscall_nr_to_meta(syscall);
+ if (!entry)
+ return NULL;
+
+ return entry->name;
+}
+
static enum print_line_t
print_syscall_enter(struct trace_iterator *iter, int flags,
struct trace_event *event)
--
1.9.3
^ permalink raw reply related [flat|nested] 13+ messages in thread* [PATCH v4 4/7] tracing: Add a per-event-trigger 'paused' field
2015-04-10 16:05 [PATCH v4 0/7] tracing: 'hist' triggers Tom Zanussi
` (2 preceding siblings ...)
2015-04-10 16:05 ` [PATCH v4 3/7] tracing: Add get_syscall_name() Tom Zanussi
@ 2015-04-10 16:05 ` Tom Zanussi
2015-04-10 16:05 ` [PATCH v4 5/7] tracing: Add 'hist' event trigger command Tom Zanussi
` (3 subsequent siblings)
7 siblings, 0 replies; 13+ messages in thread
From: Tom Zanussi @ 2015-04-10 16:05 UTC (permalink / raw)
To: rostedt
Cc: masami.hiramatsu.pt, namhyung, andi, alexei.starovoitov,
linux-kernel, Tom Zanussi
Add a simple per-trigger 'paused' flag, allowing individual triggers
to pause. We could leave it to individual triggers that need this
functionality to do it themselves, but we also want to allow other
events to control pausing, so add it to the trigger data.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
kernel/trace/trace.h | 1 +
kernel/trace/trace_events_trigger.c | 4 ++++
2 files changed, 5 insertions(+)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 3d38c2e..5bc1752 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1110,6 +1110,7 @@ struct event_trigger_data {
struct event_filter __rcu *filter;
char *filter_str;
void *private_data;
+ bool paused;
struct list_head list;
};
diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
index a8dfd4e..010ce30 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -73,6 +73,8 @@ event_triggers_call(struct ftrace_event_file *file, void *rec)
return tt;
list_for_each_entry_rcu(data, &file->triggers, list) {
+ if (data->paused)
+ continue;
if (!rec) {
data->ops->func(data, rec);
continue;
@@ -110,6 +112,8 @@ event_triggers_post_call(struct ftrace_event_file *file,
struct event_trigger_data *data;
list_for_each_entry_rcu(data, &file->triggers, list) {
+ if (data->paused)
+ continue;
if (data->cmd_ops->trigger_type & tt)
data->ops->func(data, rec);
}
--
1.9.3
^ permalink raw reply related [flat|nested] 13+ messages in thread* [PATCH v4 5/7] tracing: Add 'hist' event trigger command
2015-04-10 16:05 [PATCH v4 0/7] tracing: 'hist' triggers Tom Zanussi
` (3 preceding siblings ...)
2015-04-10 16:05 ` [PATCH v4 4/7] tracing: Add a per-event-trigger 'paused' field Tom Zanussi
@ 2015-04-10 16:05 ` Tom Zanussi
2015-04-10 16:05 ` [PATCH v4 6/7] tracing: Add enable_hist/disable_hist triggers Tom Zanussi
` (2 subsequent siblings)
7 siblings, 0 replies; 13+ messages in thread
From: Tom Zanussi @ 2015-04-10 16:05 UTC (permalink / raw)
To: rostedt
Cc: masami.hiramatsu.pt, namhyung, andi, alexei.starovoitov,
linux-kernel, Tom Zanussi
'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:values=yyy [ 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 value fields specified.
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.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
include/linux/ftrace_event.h | 1 +
kernel/trace/Kconfig | 14 +
kernel/trace/Makefile | 1 +
kernel/trace/trace.c | 43 +
kernel/trace/trace.h | 21 +
kernel/trace/trace_events.c | 4 +
kernel/trace/trace_events_hist.c | 1593 +++++++++++++++++++++++++++++++++++
kernel/trace/trace_events_trigger.c | 29 +-
8 files changed, 1691 insertions(+), 15 deletions(-)
create mode 100644 kernel/trace/trace_events_hist.c
diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
index b03dfa8..d1fa0b5 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -416,6 +416,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);
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index a5da09c..002a9ff 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -520,6 +520,20 @@ config MMIOTRACE
See Documentation/trace/mmiotrace.txt.
If you are not helping to develop drivers, say N.
+config HIST_TRIGGERS
+ bool "Histogram triggers"
+ depends on ARCH_HAVE_NMI_SAFE_CMPXCHG
+ 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
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 98f2658..842ddbd 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -53,6 +53,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_KPROBE_EVENT) += trace_kprobe.o
obj-$(CONFIG_TRACEPOINTS) += power-traces.o
ifeq ($(CONFIG_PM),y)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index bcfa2ad..a08f904 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3730,6 +3730,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"
@@ -3745,6 +3748,46 @@ 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>:values=<field1[,field2,...]>\n"
+ "\t [:size=#entries][:sort=field1][:pause][:continue]\n"
+ "\t [:clear] [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. Keys and values\n"
+ "\t correspond to fields in the event's format description.\n"
+ "\t Values must correspond to numeric fields - on an event hit,\n"
+ "\t the value(s) will be added to a sum kept for that field.\n"
+ "\t The special string 'hitcount' can be used in place of an\n"
+ "\t explicit value field - this is simply a count of event hits.\n"
+ "\t Keys can be any field, or the special string 'stacktrace',\n"
+ "\t which will use the event's kernel stacktrace as the key.\n\n"
+ "\t Reading the 'hist' file for the event will dump the hash\n"
+ "\t table in its entirety to stdout. By default, numeric fields\n"
+ "\t are displayed as base-10 integers. This can be modified by\n"
+ "\t appending any of the following modifiers to the field name:\n\n"
+ "\t .hex display a number as a hex value\n"
+ "\t .sym display an address as a symbol\n"
+ "\t .syscall display a syscall id as a system call name\n"
+ "\t .execname display a common_pid as a program name\n\n"
+ "\t By default, the size of the hash table is 2048 entries. The\n"
+ "\t 'size' param can be used to specify more or fewer than that.\n"
+ "\t The units are in terms of hashtable entries - if a run uses\n"
+ "\t more entries than specified, the results will show the number\n"
+ "\t of 'drops', the number of hits that were ignored. The size\n"
+ "\t should be a power of 2 between 128 and 131072 (any non-\n"
+ "\t power-of-2 number specified will be rounded up).\n\n"
+ "\t The 'sort' param can be used to specify a value field to sort\n"
+ "\t on. The default if unspecified is 'hitcount' and the.\n"
+ "\t default sort order is 'ascending'. To sort in the opposite\n"
+ "\t direction, append .descending' to the sort key.\n\n"
+ "\t The 'pause' param 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"
+ "\t The 'clear' param will clear the contents of a running hist\n"
+ "\t trigger and leave its current paused/active state.\n\n"
+#endif
;
static ssize_t
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 5bc1752..1ae4d90 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1098,6 +1098,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);
@@ -1114,6 +1121,20 @@ struct event_trigger_data {
struct list_head list;
};
+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);
+extern int trace_event_trigger_enable_disable(struct ftrace_event_file *file,
+ int trigger_enable);
+extern void update_cond_flag(struct ftrace_event_file *file);
+extern void unregister_trigger(char *glob, struct event_trigger_ops *ops,
+ struct event_trigger_data *test,
+ struct ftrace_event_file *file);
+extern int set_trigger_filter(char *filter_str,
+ struct event_trigger_data *trigger_data,
+ struct ftrace_event_file *file);
+extern int register_event_command(struct event_command *cmd);
+
/**
* struct event_trigger_ops - callbacks for trace event triggers
*
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 0d2e473..495ace7 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -1621,6 +1621,10 @@ event_create_dir(struct dentry *parent, struct ftrace_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);
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
new file mode 100644
index 0000000..6fe3400
--- /dev/null
+++ b/kernel/trace/trace_events_hist.c
@@ -0,0 +1,1593 @@
+/*
+ * trace_events_hist - trace event hist triggers
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * GNU General Public License for more details.
+ *
+ * Copyright (C) 2015 Tom Zanussi <tom.zanussi@linux.intel.com>
+ *
+ * tracing_map implementation 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
+ */
+
+#include <linux/module.h>
+#include <linux/kallsyms.h>
+#include <linux/mutex.h>
+#include <linux/slab.h>
+#include <linux/jhash.h>
+#include <linux/stacktrace.h>
+#include <linux/sort.h>
+
+#include "trace.h"
+
+struct hist_field;
+
+typedef u64 (*hist_field_fn_t) (struct hist_field *field, void *event);
+
+struct hist_field {
+ struct ftrace_event_field *field;
+ unsigned long flags;
+ hist_field_fn_t fn;
+};
+
+static u64 hist_field_none(struct hist_field *field, void *event)
+{
+ return 0;
+}
+
+static u64 hist_field_string(struct hist_field *hist_field, void *event)
+{
+ char *addr = (char *)(event + hist_field->field->offset);
+
+ return (u64)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; \
+}
+
+DEFINE_HIST_FIELD_FN(s64);
+DEFINE_HIST_FIELD_FN(u64);
+DEFINE_HIST_FIELD_FN(s32);
+DEFINE_HIST_FIELD_FN(u32);
+DEFINE_HIST_FIELD_FN(s16);
+DEFINE_HIST_FIELD_FN(u16);
+DEFINE_HIST_FIELD_FN(s8);
+DEFINE_HIST_FIELD_FN(u8);
+
+#define HIST_TRIGGER_BITS 11
+#define HIST_TRIGGER_BITS_MAX 17
+#define HIST_TRIGGER_BITS_MIN 7
+#define HIST_VALS_MAX 2
+#define HIST_SORT_KEYS_MAX 2
+
+#define HIST_KEY_STRING_MAX 64
+
+enum hist_field_flags {
+ HIST_FIELD_SYM = 1,
+ HIST_FIELD_HEX = 2,
+ HIST_FIELD_STACKTRACE = 4,
+ HIST_FIELD_STRING = 8,
+ HIST_FIELD_EXECNAME = 16,
+ HIST_FIELD_SYSCALL = 32,
+};
+
+struct hist_trigger_sort_key {
+ bool use_hitcount;
+ bool use_key;
+ bool descending;
+ unsigned int idx;
+};
+
+struct hist_trigger_sort_entry {
+ void *key;
+ struct hist_trigger_entry *entry;
+ bool entry_copied;
+ bool dup;
+};
+
+struct hist_trigger_entry {
+ struct hist_trigger_data *hist_data;
+ void *key;
+ atomic64_t hitcount;
+ atomic64_t sums[HIST_VALS_MAX];
+ char *comm;
+};
+
+struct tracing_map_entry {
+ u32 key;
+ struct hist_trigger_entry *val;
+};
+
+struct tracing_map {
+ unsigned int key_size;
+ unsigned int map_bits;
+ unsigned int map_size;
+ unsigned int max_entries;
+ atomic_t next_entry;
+ struct tracing_map_entry *map;
+ struct hist_trigger_entry *entries;
+};
+
+struct hist_trigger_attrs {
+ char *keys_str;
+ char *vals_str;
+ char *sort_keys_str;
+ bool pause;
+ bool cont;
+ bool clear;
+ unsigned int map_bits;
+};
+
+struct hist_trigger_data {
+ atomic64_t total_hits;
+ struct hist_field *key;
+ struct hist_field *vals[HIST_VALS_MAX];
+ unsigned int n_vals;
+ struct ftrace_event_file *event_file;
+ atomic64_t drops;
+ struct hist_trigger_attrs *attrs;
+ struct hist_trigger_sort_key *sort_keys[HIST_SORT_KEYS_MAX];
+ struct hist_trigger_sort_key *sort_key_cur;
+ struct tracing_map *map;
+};
+
+#define HIST_STACKTRACE_DEPTH 16
+#define HIST_STACKTRACE_SKIP 5
+
+static hist_field_fn_t select_value_fn(int field_size, int field_is_signed)
+{
+ hist_field_fn_t fn = NULL;
+
+ switch (field_size) {
+ case 8:
+ if (field_is_signed)
+ fn = hist_field_s64;
+ else
+ fn = hist_field_u64;
+ break;
+ case 4:
+ if (field_is_signed)
+ fn = hist_field_s32;
+ else
+ fn = hist_field_u32;
+ break;
+ case 2:
+ if (field_is_signed)
+ fn = hist_field_s16;
+ else
+ fn = hist_field_u16;
+ break;
+ case 1:
+ if (field_is_signed)
+ fn = hist_field_s8;
+ else
+ fn = hist_field_u8;
+ break;
+ }
+
+ return fn;
+}
+
+static inline void save_comm(char *comm, struct task_struct *task)
+{
+ if (!task->pid) {
+ strcpy(comm, "<idle>");
+ return;
+ }
+
+ if (WARN_ON_ONCE(task->pid < 0)) {
+ strcpy(comm, "<XXX>");
+ return;
+ }
+
+ if (task->pid > PID_MAX_DEFAULT) {
+ strcpy(comm, "<...>");
+ return;
+ }
+
+ memcpy(comm, task->comm, TASK_COMM_LEN);
+}
+
+static void destroy_hist_field(struct hist_field *hist_field)
+{
+ kfree(hist_field);
+}
+
+static struct hist_field *create_hist_field(struct ftrace_event_field *field,
+ unsigned long flags)
+{
+ hist_field_fn_t fn = hist_field_none;
+ struct hist_field *hist_field;
+
+ hist_field = kzalloc(sizeof(struct hist_field), GFP_KERNEL);
+ if (!hist_field)
+ return NULL;
+
+ if (flags & HIST_FIELD_STACKTRACE) {
+ hist_field->flags = flags;
+ goto out;
+ }
+
+ if (is_function_field(field))
+ goto free;
+
+ if (is_string_field(field)) {
+ flags |= HIST_FIELD_STRING;
+ fn = hist_field_string;
+ } else {
+ fn = select_value_fn(field->size, field->is_signed);
+ if (!fn)
+ goto free;
+ }
+
+ hist_field->field = field;
+ hist_field->flags = flags;
+ hist_field->fn = fn;
+ out:
+ return hist_field;
+ free:
+ kfree(hist_field);
+ hist_field = NULL;
+
+ goto out;
+}
+
+static void destroy_hist_fields(struct hist_trigger_data *hist_data)
+{
+ unsigned int i;
+
+ destroy_hist_field(hist_data->key);
+ hist_data->key = NULL;
+
+ for (i = 0; i < hist_data->n_vals; i++) {
+ destroy_hist_field(hist_data->vals[i]);
+ hist_data->vals[i] = NULL;
+ }
+}
+
+static inline struct hist_trigger_sort_key *create_default_sort_key(void)
+{
+ struct hist_trigger_sort_key *sort_key;
+
+ sort_key = kzalloc(sizeof(*sort_key), GFP_KERNEL);
+ if (!sort_key)
+ return ERR_PTR(-ENOMEM);
+
+ sort_key->use_hitcount = true;
+
+ return sort_key;
+}
+
+static inline struct hist_trigger_sort_key *
+create_sort_key(char *field_name, struct hist_trigger_data *hist_data)
+{
+ struct hist_trigger_sort_key *sort_key;
+ unsigned int i;
+
+ if (!strcmp(field_name, "hitcount"))
+ return create_default_sort_key();
+
+ for (i = 0; i < hist_data->n_vals; i++)
+ if (!strcmp(field_name, hist_data->vals[i]->field->name))
+ goto out;
+
+ return ERR_PTR(-EINVAL);
+ out:
+ sort_key = kzalloc(sizeof(*sort_key), GFP_KERNEL);
+ if (!sort_key)
+ return ERR_PTR(-ENOMEM);
+
+ sort_key->idx = i;
+
+ return sort_key;
+}
+
+static int create_sort_keys(struct hist_trigger_data *hist_data)
+{
+ char *fields_str = hist_data->attrs->sort_keys_str;
+ struct hist_trigger_sort_key *sort_key;
+ char *field_str, *field_name;
+ unsigned int i;
+ int ret = 0;
+
+ if (!fields_str) {
+ sort_key = create_default_sort_key();
+ if (IS_ERR(sort_key)) {
+ ret = PTR_ERR(sort_key);
+ goto out;
+ }
+ hist_data->sort_keys[0] = sort_key;
+ goto out;
+ }
+
+ strsep(&fields_str, "=");
+ if (!fields_str) {
+ ret = -EINVAL;
+ goto free;
+ }
+
+ for (i = 0; i < HIST_SORT_KEYS_MAX; i++) {
+ field_str = strsep(&fields_str, ",");
+ if (!field_str) {
+ if (i == 0) {
+ ret = -EINVAL;
+ goto free;
+ } else
+ break;
+ }
+
+ field_name = strsep(&field_str, ".");
+ sort_key = create_sort_key(field_name, hist_data);
+ if (IS_ERR(sort_key)) {
+ ret = PTR_ERR(sort_key);
+ goto free;
+ }
+
+ if (field_str) {
+ if (!strcmp(field_str, "descending"))
+ sort_key->descending = true;
+ else if (strcmp(field_str, "ascending")) {
+ ret = -EINVAL;
+ goto free;
+ }
+ }
+ hist_data->sort_keys[i] = sort_key;
+ }
+ out:
+ return ret;
+ free:
+ for (i = 0; i < HIST_SORT_KEYS_MAX; i++) {
+ if (!hist_data->sort_keys[i])
+ break;
+ kfree(hist_data->sort_keys[i]);
+ hist_data->sort_keys[i] = NULL;
+ }
+ goto out;
+}
+
+static int create_key_field(struct hist_trigger_data *hist_data,
+ struct ftrace_event_file *file,
+ char *field_str)
+{
+ struct ftrace_event_field *field = NULL;
+ unsigned long flags = 0;
+ char *field_name;
+ int ret = 0;
+
+ if (!strcmp(field_str, "stacktrace"))
+ flags |= HIST_FIELD_STACKTRACE;
+ else {
+ field_name = strsep(&field_str, ".");
+ if (field_str) {
+ if (!strcmp(field_str, "sym"))
+ flags |= HIST_FIELD_SYM;
+ else if (!strcmp(field_str, "hex"))
+ flags |= HIST_FIELD_HEX;
+ else if (!strcmp(field_str, "execname") &&
+ !strcmp(field_name, "common_pid"))
+ flags |= HIST_FIELD_EXECNAME;
+ else if (!strcmp(field_str, "syscall"))
+ flags |= HIST_FIELD_SYSCALL;
+ }
+
+ field = trace_find_event_field(file->event_call, field_name);
+ if (!field) {
+ ret = -EINVAL;
+ goto out;
+ }
+ }
+
+ hist_data->key = create_hist_field(field, flags);
+ if (!hist_data->key)
+ ret = -ENOMEM;
+ out:
+ return ret;
+}
+
+static int create_val_field(struct hist_trigger_data *hist_data,
+ unsigned int val,
+ struct ftrace_event_file *file,
+ char *field_str)
+{
+ struct ftrace_event_field *field = NULL;
+ unsigned long flags = 0;
+ char *field_name;
+ int ret = 0;
+
+ if (!strcmp(field_str, "hitcount"))
+ return ret;
+
+ field_name = strsep(&field_str, ".");
+ if (field_str) {
+ if (!strcmp(field_str, "sym"))
+ flags |= HIST_FIELD_SYM;
+ else if (!strcmp(field_str, "hex"))
+ flags |= HIST_FIELD_HEX;
+ }
+
+ field = trace_find_event_field(file->event_call, field_name);
+ if (!field) {
+ ret = -EINVAL;
+ goto out;
+ }
+
+ hist_data->vals[val] = create_hist_field(field, flags);
+ if (!hist_data->vals[val]) {
+ ret = -ENOMEM;
+ goto out;
+ }
+ hist_data->n_vals++;
+ out:
+ return ret;
+}
+
+static int create_hist_fields(struct hist_trigger_data *hist_data,
+ struct ftrace_event_file *file)
+{
+ char *fields_str, *field_str;
+ unsigned int i;
+ int ret;
+
+ fields_str = hist_data->attrs->keys_str;
+ strsep(&fields_str, "=");
+ if (!fields_str) {
+ ret = -EINVAL;
+ goto out;
+ }
+
+ ret = create_key_field(hist_data, file, fields_str);
+ if (ret)
+ goto out;
+
+ fields_str = hist_data->attrs->vals_str;
+ strsep(&fields_str, "=");
+ if (!fields_str) {
+ ret = -EINVAL;
+ goto out;
+ }
+
+ for (i = 0; i < HIST_VALS_MAX; i++) {
+ field_str = strsep(&fields_str, ",");
+ if (!field_str) {
+ if (i == 0) {
+ ret = -EINVAL;
+ goto out;
+ } else
+ break;
+ }
+ ret = create_val_field(hist_data, i, file, field_str);
+ if (ret)
+ goto out;
+ }
+
+ ret = create_sort_keys(hist_data);
+ out:
+ return ret;
+}
+
+static u32 get_key_size(struct hist_trigger_data *hist_data)
+{
+ u32 key_size;
+
+ if (hist_data->key->flags & HIST_FIELD_STACKTRACE)
+ key_size = sizeof(unsigned long) * HIST_STACKTRACE_DEPTH;
+ else
+ key_size = hist_data->key->field->size;
+
+ return key_size;
+}
+
+static void destroy_hist_trigger_attrs(struct hist_trigger_attrs *attrs)
+{
+ kfree(attrs->sort_keys_str);
+ kfree(attrs->keys_str);
+ kfree(attrs->vals_str);
+ kfree(attrs);
+}
+
+static int parse_map_size(char *str)
+{
+ unsigned long size, map_bits;
+ int ret;
+
+ strsep(&str, "=");
+ if (!str) {
+ ret = -EINVAL;
+ goto out;
+ }
+
+ ret = kstrtoul(str, 0, &size);
+ if (ret)
+ goto out;
+
+ map_bits = ilog2(roundup_pow_of_two(size));
+ if (map_bits < HIST_TRIGGER_BITS_MIN ||
+ map_bits > HIST_TRIGGER_BITS_MAX)
+ ret = -EINVAL;
+ else
+ ret = map_bits;
+ out:
+ return ret;
+}
+
+static struct hist_trigger_attrs *parse_hist_trigger_attrs(char *trigger_str)
+{
+ struct hist_trigger_attrs *attrs;
+ int ret = 0;
+
+ attrs = kzalloc(sizeof(*attrs), GFP_KERNEL);
+ if (!attrs)
+ return ERR_PTR(-ENOMEM);
+
+ while (trigger_str) {
+ char *str = strsep(&trigger_str, ":");
+
+ if (!strncmp(str, "keys", strlen("keys")) ||
+ !strncmp(str, "key", strlen("key")))
+ attrs->keys_str = kstrdup(str, GFP_KERNEL);
+ else if (!strncmp(str, "values", strlen("values")) ||
+ !strncmp(str, "vals", strlen("vals")) ||
+ !strncmp(str, "val", strlen("val")))
+ attrs->vals_str = kstrdup(str, GFP_KERNEL);
+ else if (!strncmp(str, "sort", strlen("sort")))
+ attrs->sort_keys_str = kstrdup(str, GFP_KERNEL);
+ else if (!strncmp(str, "pause", strlen("pause")))
+ attrs->pause = true;
+ else if (!strncmp(str, "continue", strlen("continue")) ||
+ !strncmp(str, "cont", strlen("cont")))
+ attrs->cont = true;
+ else if (!strncmp(str, "clear", strlen("clear")))
+ attrs->clear = true;
+ else if (!strncmp(str, "size", strlen("size"))) {
+ int map_bits = parse_map_size(str);
+
+ if (map_bits < 0) {
+ ret = map_bits;
+ goto free;
+ }
+ attrs->map_bits = map_bits;
+ } else {
+ ret = -EINVAL;
+ goto free;
+ }
+ }
+
+ return attrs;
+ free:
+ destroy_hist_trigger_attrs(attrs);
+
+ return ERR_PTR(ret);
+}
+
+static struct hist_trigger_entry *
+hist_trigger_entry_create(struct tracing_map *map)
+{
+ struct hist_trigger_entry *entry = NULL;
+ int idx;
+
+ idx = atomic_inc_return(&map->next_entry);
+ if (idx < map->max_entries) {
+ entry = &map->entries[idx];
+ if (entry->comm)
+ save_comm(entry->comm, current);
+ }
+
+ return entry;
+}
+
+static inline bool keys_match(void *key, void *test_key, unsigned key_size)
+{
+ bool match = true;
+
+ if (memcmp(key, test_key, key_size))
+ match = false;
+
+ return match;
+}
+
+/**
+ * tracing_map_insert - Insert key and/or return associated val
+ * @map: The tracing_map to insert into
+ * @key: The key to insert
+ *
+ * Inserts a key into the map and creates and returns a new
+ * hist_trigger_entry for it, or if the key has already been inserted
+ * by a previous call, returns the hist_trigger_entry already
+ * associated with it. When the map was created, the number of
+ * entries for the map was specified, and that number of
+ * hist_trigger_entries was created at the same time. This is the
+ * pre-allocated pool of hist trigger entries that
+ * tracing_map_insert() will allocate from when adding new keys. Once
+ * that pool is exhausted, tracing_map_insert() is useless and will
+ * return NULL to signal that state.
+ *
+ * This is a lock-free tracing map insertion function implementing a
+ * modified form of Cliff Click's basic insertion algorithm. It
+ * requires the table size to be a power of two. To prevent any
+ * possibility of an infinite loop we always make the actual table
+ * size double the size of the requested table size (max_size * 2).
+ * Likewise, we never reuse a slot or resize or delete elements - when
+ * we've reached map_size entries, we simply return NULL once we've
+ * run out of entries. Readers can at any point in time traverse the
+ * tracing map and safely access the key/val pairs.
+ *
+ * Return: the hist_trigger_entry * val associated with the key. If
+ * this was a newly inserted key, the val will be a newly allocated
+ * and associated hist_trigger_entry * val. If the key wasn't found
+ * and the pool of hist_trigger_entries has been exhausted, NULL is
+ * returned and no further insertions will succeed.
+ */
+static struct hist_trigger_entry *
+tracing_map_insert(struct tracing_map *map, void *key)
+{
+ u32 idx, key_hash, test_key;
+
+ key_hash = jhash(key, map->key_size, 0);
+ idx = key_hash >> (32 - (map->map_bits + 1));
+
+ while (1) {
+ idx &= (map->map_size - 1);
+ test_key = map->map[idx].key;
+
+ if (test_key && test_key == key_hash && map->map[idx].val &&
+ keys_match(key, map->map[idx].val->key, map->key_size))
+ return map->map[idx].val;
+
+ if (!test_key && !cmpxchg(&map->map[idx].key, 0, key_hash)) {
+ struct hist_trigger_entry *entry;
+
+ entry = hist_trigger_entry_create(map);
+ if (!entry)
+ break;
+ memcpy(entry->key, key, map->key_size);
+ map->map[idx].val = entry;
+
+ return map->map[idx].val;
+ }
+
+ idx++;
+ }
+
+ return NULL;
+}
+
+/**
+ * tracing_map_destroy - Destroy a tracing_map
+ * @map: The tracing_map to destroy
+ *
+ * Frees a tracing_map along with its associated array of
+ * hist_trigger_entries.
+ *
+ * Callers should make sure there are no readers or writers actively
+ * reading or inserting into the map before calling this.
+ */
+static void tracing_map_destroy(struct tracing_map *map)
+{
+ unsigned int i;
+
+ if (!map)
+ return;
+
+ if (map->entries) {
+ for (i = 0; i < map->max_entries; i++) {
+ kfree(map->entries[i].key);
+ kfree(map->entries[i].comm);
+ }
+ }
+
+ kfree(map->entries);
+ kfree(map->map);
+ kfree(map);
+}
+
+/**
+ * tracing_map_clear - Clear a tracing_map
+ * @map: The tracing_map to clear
+ *
+ * Resets the tracing map to a cleared or initial state. The
+ * tracing_map_entries are all cleared, and the array of
+ * hist_trigger_entries are reset to an initialized state.
+ *
+ * Callers should make sure there are no writers actively inserting
+ * into the map before calling this.
+ */
+static void tracing_map_clear(struct tracing_map *map)
+{
+ unsigned int i, j, size;
+
+ atomic_set(&map->next_entry, -1);
+
+ size = map->map_size * sizeof(struct tracing_map_entry);
+ memset(map->map, 0, size);
+
+ for (i = 0; i < map->max_entries; i++) {
+ atomic64_set(&map->entries[i].hitcount, 0);
+ for (j = 0; j < HIST_VALS_MAX; j++)
+ atomic64_set(&map->entries[i].sums[j], 0);
+ }
+}
+
+/**
+ * tracing_map_create - Create a lock-free map and hist entry pool
+ * @hist_data: The hist_trigger_data to be associated with the map
+ * @map_bits: The size of the map (2 ** map_bits)
+ * @key_size: The size of the key for the map in bytes
+ * @comm: boolean, do the entries need space for a comm string?
+ *
+ * Creates and sets up a map to contain a max_size number of entries
+ * equal to a size of 2 ** map_bits. It also creates an array of
+ * (hist_trigger _entry) of the same size in order to avoid allocating
+ * anything in the map insertion path. These sizes reflect the number
+ * of entries requested by the user - internally we double that in
+ * order to keep the table sparse and keep collisions manageable.
+ *
+ * Return: the tracing_map * if successful, ERR_PTR if not.
+ */
+static struct tracing_map *
+tracing_map_create(struct hist_trigger_data *hist_data, unsigned int map_bits,
+ unsigned int key_size, bool comm)
+{
+ struct tracing_map *map;
+ unsigned int i, size;
+
+ map = kzalloc(sizeof(*map), GFP_KERNEL);
+ if (!map)
+ return ERR_PTR(-ENOMEM);
+
+ map->map_bits = map_bits;
+ map->max_entries = (1 << map_bits);
+ atomic_set(&map->next_entry, -1);
+
+ map->map_size = (1 << (map_bits + 1));
+ map->key_size = key_size;
+
+ size = map->map_size * sizeof(struct tracing_map_entry);
+ map->map = kzalloc(size, GFP_KERNEL);
+ if (!map->map)
+ goto free;
+
+ size = map->max_entries * sizeof(struct hist_trigger_entry);
+ map->entries = kzalloc(size, GFP_KERNEL);
+ if (!map->entries)
+ goto free;
+
+ for (i = 0; i < map->max_entries; i++) {
+ map->entries[i].hist_data = hist_data;
+ map->entries[i].key = kzalloc(key_size, GFP_KERNEL);
+ if (!map->entries[i].key)
+ goto free;
+
+ if (comm) {
+ size = TASK_COMM_LEN + 1;
+ map->entries[i].comm = kzalloc(size, GFP_KERNEL);
+ if (!map->entries[i].comm)
+ goto free;
+ }
+ }
+ tracing_map_clear(map);
+ out:
+ return map;
+ free:
+ tracing_map_destroy(map);
+ map = ERR_PTR(-ENOMEM);
+
+ goto out;
+}
+
+static void destroy_hist_data(struct hist_trigger_data *hist_data)
+{
+ destroy_hist_trigger_attrs(hist_data->attrs);
+ destroy_hist_fields(hist_data);
+ tracing_map_destroy(hist_data->map);
+ kfree(hist_data);
+}
+
+static struct hist_trigger_data *
+create_hist_data(unsigned int map_bits,
+ struct hist_trigger_attrs *attrs,
+ struct ftrace_event_file *file)
+{
+ struct hist_trigger_data *hist_data;
+ int ret = 0;
+ bool comm;
+
+ hist_data = kzalloc(sizeof(*hist_data), GFP_KERNEL);
+ if (!hist_data)
+ return NULL;
+
+ hist_data->attrs = attrs;
+
+ ret = create_hist_fields(hist_data, file);
+ if (ret < 0)
+ goto free;
+
+ comm = hist_data->key->flags & HIST_FIELD_EXECNAME;
+
+ hist_data->map = tracing_map_create(hist_data, map_bits,
+ get_key_size(hist_data),
+ comm);
+ if (IS_ERR(hist_data->map)) {
+ ret = PTR_ERR(hist_data->map);
+ hist_data->map = NULL;
+ goto free;
+ }
+
+ hist_data->event_file = file;
+ out:
+ return hist_data;
+ free:
+ destroy_hist_data(hist_data);
+ if (ret)
+ hist_data = ERR_PTR(ret);
+ else
+ hist_data = NULL;
+
+ goto out;
+}
+
+static void hist_trigger_entry_update(struct hist_trigger_data *hist_data,
+ struct hist_trigger_entry *entry,
+ void *rec)
+{
+ struct hist_field *hist_field;
+ unsigned int i;
+ u64 hist_val;
+
+ for (i = 0; i < hist_data->n_vals; i++) {
+ hist_field = hist_data->vals[i];
+ hist_val = hist_field->fn(hist_field, rec);
+ atomic64_add(hist_val, &entry->sums[i]);
+ }
+
+ atomic64_inc(&entry->hitcount);
+}
+
+static void event_hist_trigger(struct event_trigger_data *data, void *rec)
+{
+ struct hist_trigger_data *hist_data = data->private_data;
+ unsigned long entries[HIST_STACKTRACE_DEPTH];
+ struct hist_trigger_entry *entry;
+ struct stack_trace stacktrace;
+ u64 field_contents;
+ void *key;
+
+ if (atomic64_read(&hist_data->drops)) {
+ atomic64_inc(&hist_data->drops);
+ return;
+ }
+
+ if (hist_data->key->flags & HIST_FIELD_STACKTRACE) {
+ stacktrace.max_entries = HIST_STACKTRACE_DEPTH;
+ stacktrace.entries = entries;
+ stacktrace.nr_entries = 0;
+ stacktrace.skip = HIST_STACKTRACE_SKIP;
+
+ memset(stacktrace.entries, 0, hist_data->map->key_size);
+ save_stack_trace(&stacktrace);
+
+ key = entries;
+ } else {
+ field_contents = hist_data->key->fn(hist_data->key, rec);
+ if (hist_data->key->flags & HIST_FIELD_STRING)
+ key = (void *)field_contents;
+ else
+ key = (void *)&field_contents;
+ }
+
+ entry = tracing_map_insert(hist_data->map, key);
+ if (entry)
+ hist_trigger_entry_update(hist_data, entry, rec);
+ else
+ atomic64_inc(&hist_data->drops);
+
+ atomic64_inc(&hist_data->total_hits);
+}
+
+static void hist_trigger_stacktrace_print(struct seq_file *m,
+ unsigned long *stacktrace_entries,
+ unsigned int max_entries)
+{
+ char str[KSYM_SYMBOL_LEN];
+ unsigned int spaces = 8;
+ unsigned int i;
+
+ for (i = 0; i < max_entries; i++) {
+ if (stacktrace_entries[i] == ULONG_MAX)
+ return;
+
+ seq_printf(m, "%*c", 1 + spaces, ' ');
+ sprint_symbol(str, stacktrace_entries[i]);
+ seq_printf(m, "%s\n", str);
+ }
+}
+
+static void hist_trigger_entry_print(struct seq_file *m,
+ struct hist_trigger_data *hist_data,
+ void *key,
+ struct hist_trigger_entry *entry)
+{
+ char str[KSYM_SYMBOL_LEN];
+ unsigned int i;
+ u64 uval;
+
+ if (entry->hist_data->key->flags & HIST_FIELD_SYM) {
+ uval = *(u64 *)key;
+ kallsyms_lookup(uval, NULL, NULL, NULL, str);
+ seq_printf(m, "%s: [%llx] %-35s", hist_data->key->field->name,
+ uval, str);
+ } else if (entry->hist_data->key->flags & HIST_FIELD_HEX) {
+ uval = *(u64 *)key;
+ seq_printf(m, "%s: %llx", hist_data->key->field->name, uval);
+ } else if (entry->hist_data->key->flags & HIST_FIELD_STACKTRACE) {
+ seq_puts(m, "stacktrace:\n");
+ hist_trigger_stacktrace_print(m, key, HIST_STACKTRACE_DEPTH);
+ } else if (entry->hist_data->key->flags & HIST_FIELD_STRING) {
+ seq_printf(m, "%s: %-35s", hist_data->key->field->name,
+ (char *)key);
+ } else if (entry->hist_data->key->flags & HIST_FIELD_EXECNAME) {
+ uval = *(u64 *)key;
+ seq_printf(m, "%s: %-16s[%10llu]", hist_data->key->field->name,
+ entry->comm, uval);
+ } else if (entry->hist_data->key->flags & HIST_FIELD_SYSCALL) {
+ const char *syscall_name;
+
+ uval = *(u64 *)key;
+ syscall_name = get_syscall_name(uval);
+ if (!syscall_name)
+ syscall_name = "unknown_syscall";
+
+ seq_printf(m, "%s: %-30s", hist_data->key->field->name,
+ syscall_name);
+ } else {
+ uval = *(u64 *)key;
+ seq_printf(m, "%s: %10llu", hist_data->key->field->name, uval);
+ }
+
+ seq_printf(m, " hitcount: %10llu",
+ (u64)atomic64_read(&entry->hitcount));
+
+ for (i = 0; i < hist_data->n_vals; i++) {
+ seq_printf(m, " %s: %10llu", hist_data->vals[i]->field->name,
+ (u64)atomic64_read(&entry->sums[i]));
+ }
+
+ seq_puts(m, "\n");
+}
+
+static int cmp_entries(const struct hist_trigger_sort_entry **a,
+ const struct hist_trigger_sort_entry **b)
+{
+ const struct hist_trigger_entry *entry_a, *entry_b;
+ struct hist_trigger_sort_key *sort_key;
+ struct hist_trigger_data *hist_data;
+ u64 val_a, val_b;
+ int ret = 0;
+
+ entry_a = (*a)->entry;
+ entry_b = (*b)->entry;
+
+ hist_data = entry_a->hist_data;
+ sort_key = hist_data->sort_key_cur;
+
+ if (sort_key->use_key) {
+ if (memcmp((*a)->key, (*b)->key, hist_data->map->key_size))
+ ret = 1;
+ return ret;
+ }
+
+ if (sort_key->use_hitcount) {
+ val_a = atomic64_read(&entry_a->hitcount);
+ val_b = atomic64_read(&entry_b->hitcount);
+ } else {
+ val_a = atomic64_read(&entry_a->sums[sort_key->idx]);
+ val_b = atomic64_read(&entry_b->sums[sort_key->idx]);
+ }
+
+ if (val_a > val_b)
+ ret = 1;
+ else if (val_a < val_b)
+ ret = -1;
+
+ if (sort_key->descending)
+ ret = -ret;
+
+ return ret;
+}
+
+static void print_entries_unsorted(struct seq_file *m,
+ struct hist_trigger_data *hist_data)
+{
+ int i;
+
+ for (i = 0; i < hist_data->map->map_size; i++) {
+ if (!hist_data->map->map[i].key)
+ continue;
+ hist_trigger_entry_print(m, hist_data,
+ hist_data->map->map[i].val->key,
+ hist_data->map->map[i].val);
+ }
+}
+
+static void destroy_sort_entry(struct hist_trigger_sort_entry *entry)
+{
+ if (!entry)
+ return;
+
+ if (entry->entry_copied) {
+ kfree(entry->entry->key);
+ kfree(entry->entry->comm);
+ kfree(entry->entry);
+ }
+
+ kfree(entry->key);
+ kfree(entry);
+}
+
+static void destroy_sort_entries(struct hist_trigger_sort_entry **entries,
+ unsigned int entries_size)
+{
+ unsigned int i;
+
+ for (i = 0; i < entries_size; i++)
+ destroy_sort_entry(entries[i]);
+}
+
+static struct hist_trigger_sort_entry *
+create_sort_entry(void *key, struct hist_trigger_entry *entry)
+{
+ struct hist_trigger_sort_entry *sort_entry;
+
+ sort_entry = kzalloc(sizeof(*sort_entry), GFP_KERNEL);
+ if (!sort_entry)
+ return NULL;
+
+ sort_entry->key = kzalloc(entry->hist_data->map->key_size, GFP_KERNEL);
+ if (!sort_entry->key) {
+ destroy_sort_entry(sort_entry);
+ return NULL;
+ }
+ memcpy(sort_entry->key, key, entry->hist_data->map->key_size);
+ sort_entry->entry = entry;
+
+ return sort_entry;
+}
+
+static struct hist_trigger_entry *alloc_entry(struct hist_trigger_entry *entry)
+{
+ struct hist_trigger_entry *dup_entry;
+ unsigned int size;
+
+ size = sizeof(struct hist_trigger_entry);
+
+ dup_entry = kzalloc(size, GFP_KERNEL);
+ if (!dup_entry)
+ return NULL;
+
+ size = entry->hist_data->map->key_size;
+ dup_entry->key = kzalloc(size, GFP_KERNEL);
+ if (!dup_entry->key)
+ goto free;
+
+ if (entry->comm) {
+ size = TASK_COMM_LEN + 1;
+ dup_entry->comm = kzalloc(size, GFP_KERNEL);
+ if (!dup_entry->comm)
+ goto free;
+ }
+
+ return dup_entry;
+ free:
+ kfree(dup_entry->key);
+ kfree(dup_entry->comm);
+ kfree(dup_entry);
+
+ return NULL;
+}
+
+static struct hist_trigger_entry *copy_entry(struct hist_trigger_entry *entry)
+{
+ struct hist_trigger_entry *dup_entry;
+ unsigned int i;
+
+ dup_entry = alloc_entry(entry);
+ if (!dup_entry)
+ return NULL;
+
+ dup_entry->hist_data = entry->hist_data;
+
+ memcpy(dup_entry->key, entry->key, entry->hist_data->map->key_size);
+
+ if (entry->comm)
+ memcpy(dup_entry->comm, entry->comm, TASK_COMM_LEN);
+
+ atomic64_set(&dup_entry->hitcount, atomic64_read(&entry->hitcount));
+
+ for (i = 0; i < entry->hist_data->n_vals; i++)
+ atomic64_set(&dup_entry->sums[i],
+ atomic64_read(&entry->sums[i]));
+
+ return dup_entry;
+}
+
+static int merge_dup(struct hist_trigger_sort_entry **sort_entries,
+ unsigned int target, unsigned int dup)
+{
+ struct hist_trigger_entry *target_entry, *entry;
+ bool first_dup = (target - dup) == 1;
+ int i;
+
+ if (first_dup) {
+ entry = sort_entries[target]->entry;
+ target_entry = copy_entry(entry);
+ if (!target_entry)
+ return -ENOMEM;
+ sort_entries[target]->entry = target_entry;
+ sort_entries[target]->entry_copied = true;
+ } else
+ target_entry = sort_entries[target]->entry;
+
+ entry = sort_entries[dup]->entry;
+
+ atomic64_add(atomic64_read(&entry->hitcount), &target_entry->hitcount);
+
+ for (i = 0; i < entry->hist_data->n_vals; i++)
+ atomic64_add(atomic64_read(&entry->sums[i]),
+ &target_entry->sums[i]);
+
+ sort_entries[dup]->dup = true;
+
+ return 0;
+}
+
+static int merge_dups(struct hist_trigger_sort_entry **sort_entries,
+ int n_entries, struct hist_trigger_data *hist_data)
+{
+ unsigned int key_size, dups = 0, total_dups = 0;
+ int err, i, j;
+ void *key;
+
+ if (n_entries < 2)
+ return total_dups;
+
+ hist_data->sort_key_cur->use_key = true;
+ sort(sort_entries, n_entries, sizeof(struct hist_trigger_entry *),
+ (int (*)(const void *, const void *))cmp_entries, NULL);
+ hist_data->sort_key_cur->use_key = false;
+
+ key_size = hist_data->map->key_size;
+
+ key = sort_entries[0]->key;
+ for (i = 1; i < n_entries; i++) {
+ if (!memcmp(sort_entries[i]->key, key, key_size)) {
+ dups++; total_dups++;
+ err = merge_dup(sort_entries, i - dups, i);
+ if (err)
+ return err;
+ continue;
+ }
+ key = sort_entries[i]->key;
+ dups = 0;
+ }
+
+ if (!total_dups)
+ return total_dups;
+
+ for (i = 0, j = 0; i < n_entries; i++) {
+ if (!sort_entries[i]->dup) {
+ sort_entries[j] = sort_entries[i];
+ if (j++ != i)
+ sort_entries[i] = NULL;
+ } else {
+ destroy_sort_entry(sort_entries[i]);
+ sort_entries[i] = NULL;
+ }
+ }
+
+ return total_dups;
+}
+
+static int print_entries(struct seq_file *m,
+ struct hist_trigger_data *hist_data)
+{
+ struct hist_trigger_sort_entry **sort_entries;
+ struct hist_trigger_sort_entry *sort_entry;
+ struct tracing_map *map = hist_data->map;
+ int i, j, n_entries, ret;
+
+ sort_entries = kcalloc(map->max_entries, sizeof(sort_entry),
+ GFP_KERNEL);
+ if (!sort_entries)
+ return -ENOMEM;
+
+ for (i = 0, j = 0; i < map->map_size; i++) {
+ if (!map->map[i].key || !map->map[i].val)
+ continue;
+
+ sort_entries[j] = create_sort_entry(map->map[i].val->key,
+ map->map[i].val);
+ if (!sort_entries[j++]) {
+ ret = -ENOMEM;
+ n_entries = j;
+ goto free;
+ }
+ }
+ n_entries = j;
+
+ hist_data->sort_key_cur = hist_data->sort_keys[0];
+
+ ret = merge_dups(sort_entries, n_entries, hist_data);
+ if (ret < 0)
+ goto free;
+ j -= ret;
+
+ sort(sort_entries, j, sizeof(struct hist_trigger_entry *),
+ (int (*)(const void *, const void *))cmp_entries, NULL);
+
+ for (i = 0; i < j; i++)
+ hist_trigger_entry_print(m, hist_data,
+ sort_entries[i]->key,
+ sort_entries[i]->entry);
+ free:
+ destroy_sort_entries(sort_entries, n_entries);
+
+ return ret;
+}
+
+static int hist_show(struct seq_file *m, void *v)
+{
+ struct event_trigger_data *test, *data = NULL;
+ struct ftrace_event_file *event_file;
+ struct hist_trigger_data *hist_data;
+ int entries, dups, ret = 0;
+
+ mutex_lock(&event_mutex);
+
+ event_file = event_file_data(m->private);
+ if (unlikely(!event_file)) {
+ ret = -ENODEV;
+ goto out_unlock;
+ }
+
+ list_for_each_entry_rcu(test, &event_file->triggers, list) {
+ if (test->cmd_ops->trigger_type == ETT_EVENT_HIST) {
+ data = test;
+ break;
+ }
+ }
+ if (!data)
+ goto out_unlock;
+
+ seq_puts(m, "# trigger info: ");
+ data->ops->print(m, data->ops, data);
+ seq_puts(m, "\n");
+
+ hist_data = data->private_data;
+ dups = print_entries(m, hist_data);
+ if (dups < 0) {
+ print_entries_unsorted(m, hist_data);
+ dups = 0;
+ }
+
+ entries = atomic_read(&hist_data->map->next_entry) + 1;
+ if (entries > hist_data->map->max_entries)
+ entries = hist_data->map->max_entries;
+
+ seq_printf(m, "\nTotals:\n Hits: %lu\n Entries: %u\n Dropped: %lu\n",
+ atomic64_read(&hist_data->total_hits),
+ entries - dups,
+ atomic64_read(&hist_data->drops));
+ out_unlock:
+ mutex_unlock(&event_mutex);
+
+ return ret;
+}
+
+static int event_hist_open(struct inode *inode, struct file *file)
+{
+ return single_open(file, hist_show, file);
+}
+
+const struct file_operations event_hist_fops = {
+ .open = event_hist_open,
+ .read = seq_read,
+ .llseek = seq_lseek,
+ .release = single_release,
+};
+
+static const char *get_hist_field_flags(struct hist_field *hist_field)
+{
+ const char *flags_str = NULL;
+
+ if (hist_field->flags & HIST_FIELD_SYM)
+ flags_str = "sym";
+ else if (hist_field->flags & HIST_FIELD_HEX)
+ flags_str = "hex";
+ else if (hist_field->flags & HIST_FIELD_SYSCALL)
+ flags_str = "syscall";
+ else if (hist_field->flags & HIST_FIELD_EXECNAME)
+ flags_str = "execname";
+
+ return flags_str;
+}
+
+static void hist_field_print(struct seq_file *m, struct hist_field *hist_field)
+{
+ seq_printf(m, "%s", hist_field->field->name);
+ if (hist_field->flags) {
+ const char *flags_str = get_hist_field_flags(hist_field);
+
+ if (flags_str)
+ seq_printf(m, ".%s", flags_str);
+ }
+}
+
+static int event_hist_trigger_print(struct seq_file *m,
+ struct event_trigger_ops *ops,
+ struct event_trigger_data *data)
+{
+ struct hist_trigger_data *hist_data = data->private_data;
+ unsigned int i;
+
+ seq_puts(m, "hist:keys=");
+
+ if (hist_data->key->flags & HIST_FIELD_STACKTRACE)
+ seq_puts(m, "stacktrace");
+ else
+ hist_field_print(m, hist_data->key);
+
+ seq_puts(m, ":vals=");
+
+ for (i = 0; i < hist_data->n_vals; i++) {
+ if (i > 0)
+ seq_puts(m, ",");
+ hist_field_print(m, hist_data->vals[i]);
+ }
+
+ for (i = 0; i < HIST_SORT_KEYS_MAX; i++) {
+ if (!hist_data->sort_keys[i])
+ break;
+
+ if (i == 0)
+ seq_puts(m, ":sort=");
+ else
+ seq_puts(m, ",");
+
+ if (hist_data->sort_keys[i]->use_hitcount)
+ seq_puts(m, "hitcount");
+ else {
+ unsigned int idx = hist_data->sort_keys[i]->idx;
+
+ hist_field_print(m, hist_data->vals[idx]);
+ }
+ }
+
+ seq_printf(m, ":size=%u", (1 << hist_data->map->map_bits));
+
+ if (data->filter_str)
+ seq_printf(m, " if %s", data->filter_str);
+
+ if (data->paused)
+ seq_puts(m, " [paused]");
+ else
+ seq_puts(m, " [active]");
+
+ seq_putc(m, '\n');
+
+ return 0;
+}
+
+static void event_hist_trigger_free(struct event_trigger_ops *ops,
+ struct event_trigger_data *data)
+{
+ struct hist_trigger_data *hist_data = data->private_data;
+
+ if (WARN_ON_ONCE(data->ref <= 0))
+ return;
+
+ data->ref--;
+ if (!data->ref) {
+ trigger_data_free(data);
+ destroy_hist_data(hist_data);
+ }
+}
+
+static struct event_trigger_ops event_hist_trigger_ops = {
+ .func = event_hist_trigger,
+ .print = event_hist_trigger_print,
+ .init = event_trigger_init,
+ .free = event_hist_trigger_free,
+};
+
+static struct event_trigger_ops *event_hist_get_trigger_ops(char *cmd,
+ char *param)
+{
+ 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);
+
+ atomic64_set(&hist_data->total_hits, 0);
+ atomic64_set(&hist_data->drops, 0);
+
+ data->paused = paused;
+}
+
+static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
+ struct event_trigger_data *data,
+ struct ftrace_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) {
+ if (hist_data->attrs->clear)
+ hist_clear(test);
+ else 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->pause)
+ data->paused = true;
+
+ if (data->ops->init) {
+ ret = data->ops->init(data->ops, data);
+ if (ret < 0)
+ goto out;
+ }
+
+ list_add_rcu(&data->list, &file->triggers);
+ ret++;
+
+ if (trace_event_trigger_enable_disable(file, 1) < 0) {
+ list_del_rcu(&data->list);
+ ret--;
+ }
+ update_cond_flag(file);
+ out:
+ return ret;
+}
+
+static int event_hist_trigger_func(struct event_command *cmd_ops,
+ struct ftrace_event_file *file,
+ char *glob, char *cmd, char *param)
+{
+ unsigned int hist_trigger_bits = HIST_TRIGGER_BITS;
+ struct event_trigger_data *trigger_data;
+ struct hist_trigger_attrs *attrs;
+ struct event_trigger_ops *trigger_ops;
+ struct hist_trigger_data *hist_data;
+ char *trigger;
+ int ret = 0;
+
+ if (!param)
+ return -EINVAL;
+
+ /* separate the trigger from the filter (k:v [if filter]) */
+ trigger = strsep(¶m, " \t");
+ if (!trigger)
+ return -EINVAL;
+
+ attrs = parse_hist_trigger_attrs(trigger);
+ if (IS_ERR(attrs))
+ return PTR_ERR(attrs);
+
+ if (!attrs->keys_str || !attrs->vals_str)
+ return -EINVAL;
+
+ if (attrs->map_bits)
+ hist_trigger_bits = attrs->map_bits;
+
+ hist_data = create_hist_data(hist_trigger_bits, attrs, file);
+ if (IS_ERR(hist_data))
+ return PTR_ERR(hist_data);
+
+ trigger_ops = cmd_ops->get_trigger_ops(cmd, trigger);
+
+ ret = -ENOMEM;
+ trigger_data = kzalloc(sizeof(*trigger_data), GFP_KERNEL);
+ if (!trigger_data)
+ goto out;
+
+ trigger_data->count = -1;
+ trigger_data->ops = trigger_ops;
+ trigger_data->cmd_ops = cmd_ops;
+
+ INIT_LIST_HEAD(&trigger_data->list);
+ RCU_INIT_POINTER(trigger_data->filter, NULL);
+
+ trigger_data->private_data = hist_data;
+
+ if (glob[0] == '!') {
+ cmd_ops->unreg(glob+1, trigger_ops, trigger_data, file);
+ ret = 0;
+ goto out_free;
+ }
+
+ if (!param) /* if param is non-empty, it's supposed to be a filter */
+ goto out_reg;
+
+ if (!cmd_ops->set_filter)
+ goto out_reg;
+
+ ret = cmd_ops->set_filter(param, trigger_data, file);
+ if (ret < 0)
+ goto out_free;
+ out_reg:
+ ret = cmd_ops->reg(glob, trigger_ops, trigger_data, file);
+ /*
+ * The above returns on success the # of triggers registered,
+ * but if it didn't register any it returns zero. Consider no
+ * triggers registered a failure too.
+ */
+ if (!ret) {
+ if (!(attrs->pause || attrs->cont || attrs->clear))
+ ret = -ENOENT;
+ goto out_free;
+ } else if (ret < 0)
+ goto out_free;
+ /* Just return zero, not the number of registered triggers */
+ ret = 0;
+ out:
+ return ret;
+ out_free:
+ if (cmd_ops->set_filter)
+ cmd_ops->set_filter(NULL, trigger_data, NULL);
+ kfree(trigger_data);
+ destroy_hist_data(hist_data);
+
+ goto out;
+}
+
+static struct event_command trigger_hist_cmd = {
+ .name = "hist",
+ .trigger_type = ETT_EVENT_HIST,
+ .post_trigger = true, /* need non-NULL rec */
+ .func = event_hist_trigger_func,
+ .reg = hist_register_trigger,
+ .unreg = unregister_trigger,
+ .get_trigger_ops = event_hist_get_trigger_ops,
+ .set_filter = set_trigger_filter,
+};
+
+__init int register_trigger_hist_cmd(void)
+{
+ int ret;
+
+ ret = register_event_command(&trigger_hist_cmd);
+ WARN_ON(ret < 0);
+
+ return ret;
+}
diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
index 010ce30..a09eba3 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -28,8 +28,7 @@
static LIST_HEAD(trigger_commands);
static DEFINE_MUTEX(trigger_cmd_mutex);
-static void
-trigger_data_free(struct event_trigger_data *data)
+void trigger_data_free(struct event_trigger_data *data)
{
if (data->cmd_ops->set_filter)
data->cmd_ops->set_filter(NULL, data, NULL);
@@ -316,7 +315,7 @@ const struct file_operations event_trigger_fops = {
* Currently we only register event commands from __init, so mark this
* __init too.
*/
-static __init int register_event_command(struct event_command *cmd)
+__init int register_event_command(struct event_command *cmd)
{
struct event_command *p;
int ret = 0;
@@ -405,9 +404,8 @@ event_trigger_print(const char *name, struct seq_file *m,
*
* Return: 0 on success, errno otherwise
*/
-static int
-event_trigger_init(struct event_trigger_ops *ops,
- struct event_trigger_data *data)
+int event_trigger_init(struct event_trigger_ops *ops,
+ struct event_trigger_data *data)
{
data->ref++;
return 0;
@@ -435,8 +433,8 @@ event_trigger_free(struct event_trigger_ops *ops,
trigger_data_free(data);
}
-static int trace_event_trigger_enable_disable(struct ftrace_event_file *file,
- int trigger_enable)
+int trace_event_trigger_enable_disable(struct ftrace_event_file *file,
+ int trigger_enable)
{
int ret = 0;
@@ -493,7 +491,7 @@ clear_event_triggers(struct trace_array *tr)
* its TRIGGER_COND bit set, otherwise the TRIGGER_COND bit should be
* cleared.
*/
-static void update_cond_flag(struct ftrace_event_file *file)
+void update_cond_flag(struct ftrace_event_file *file)
{
struct event_trigger_data *data;
bool set_cond = false;
@@ -569,9 +567,9 @@ out:
* Usually used directly as the @unreg method in event command
* implementations.
*/
-static void unregister_trigger(char *glob, struct event_trigger_ops *ops,
- struct event_trigger_data *test,
- struct ftrace_event_file *file)
+void unregister_trigger(char *glob, struct event_trigger_ops *ops,
+ struct event_trigger_data *test,
+ struct ftrace_event_file *file)
{
struct event_trigger_data *data;
bool unregistered = false;
@@ -705,9 +703,9 @@ event_trigger_callback(struct event_command *cmd_ops,
*
* Return: 0 on success, errno otherwise
*/
-static int set_trigger_filter(char *filter_str,
- struct event_trigger_data *trigger_data,
- struct ftrace_event_file *file)
+int set_trigger_filter(char *filter_str,
+ struct event_trigger_data *trigger_data,
+ struct ftrace_event_file *file)
{
struct event_trigger_data *data = trigger_data;
struct event_filter *filter = NULL, *tmp;
@@ -1437,6 +1435,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;
}
--
1.9.3
^ permalink raw reply related [flat|nested] 13+ messages in thread* [PATCH v4 6/7] tracing: Add enable_hist/disable_hist triggers
2015-04-10 16:05 [PATCH v4 0/7] tracing: 'hist' triggers Tom Zanussi
` (4 preceding siblings ...)
2015-04-10 16:05 ` [PATCH v4 5/7] tracing: Add 'hist' event trigger command Tom Zanussi
@ 2015-04-10 16:05 ` Tom Zanussi
2015-04-10 16:05 ` [PATCH v4 7/7] tracing: Add 'hist' trigger Documentation Tom Zanussi
2015-04-20 12:52 ` [PATCH v4 0/7] tracing: 'hist' triggers Daniel Wagner
7 siblings, 0 replies; 13+ messages in thread
From: Tom Zanussi @ 2015-04-10 16:05 UTC (permalink / raw)
To: rostedt
Cc: masami.hiramatsu.pt, namhyung, andi, alexei.starovoitov,
linux-kernel, Tom Zanussi
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.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
include/linux/ftrace_event.h | 1 +
kernel/trace/trace.c | 11 ++++
kernel/trace/trace.h | 32 ++++++++++
kernel/trace/trace_events_hist.c | 115 ++++++++++++++++++++++++++++++++++++
kernel/trace/trace_events_trigger.c | 71 ++++++++++++----------
5 files changed, 199 insertions(+), 31 deletions(-)
diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
index d1fa0b5..0664b42 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -417,6 +417,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);
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index a08f904..31ed112 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3724,6 +3724,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
@@ -3787,6 +3791,13 @@ static const char readme_msg[] =
"\t restart a paused hist trigger.\n\n"
"\t The 'clear' param will clear the contents of a running hist\n"
"\t trigger and leave its current paused/active state.\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. Any number of enable_hist\n"
+ "\t and disable_hist triggers can be attached to a given event,\n"
+ "\t allowing that event to kick off and stop aggregations on\n"
+ "\t a host of other events. See Documentation/trace/events.txt\n"
+ "\t for examples.\n"
#endif
;
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 1ae4d90..d95264c 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1102,8 +1102,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);
@@ -1121,6 +1123,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 ftrace_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 ftrace_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 ftrace_event_file *file);
+extern void event_enable_unregister_trigger(char *glob,
+ struct event_trigger_ops *ops,
+ struct event_trigger_data *test,
+ struct ftrace_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);
@@ -1134,6 +1164,8 @@ extern int set_trigger_filter(char *filter_str,
struct event_trigger_data *trigger_data,
struct ftrace_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
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 6fe3400..200f0ad 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -1591,3 +1591,118 @@ __init int register_trigger_hist_cmd(void)
return ret;
}
+
+static void
+hist_enable_trigger(struct event_trigger_data *data, void *rec)
+{
+ struct enable_trigger_data *enable_data = data->private_data;
+ struct event_trigger_data *test;
+
+ list_for_each_entry_rcu(test, &enable_data->file->triggers, list) {
+ if (test->cmd_ops->trigger_type == ETT_EVENT_HIST) {
+ if (enable_data->enable)
+ test->paused = false;
+ else
+ test->paused = true;
+ break;
+ }
+ }
+}
+
+static void
+hist_enable_count_trigger(struct event_trigger_data *data, void *rec)
+{
+ if (!data->count)
+ return;
+
+ if (data->count != -1)
+ (data->count)--;
+
+ hist_enable_trigger(data, rec);
+}
+
+static struct event_trigger_ops hist_enable_trigger_ops = {
+ .func = hist_enable_trigger,
+ .print = event_enable_trigger_print,
+ .init = event_trigger_init,
+ .free = event_enable_trigger_free,
+};
+
+static struct event_trigger_ops hist_enable_count_trigger_ops = {
+ .func = hist_enable_count_trigger,
+ .print = event_enable_trigger_print,
+ .init = event_trigger_init,
+ .free = event_enable_trigger_free,
+};
+
+static struct event_trigger_ops hist_disable_trigger_ops = {
+ .func = hist_enable_trigger,
+ .print = event_enable_trigger_print,
+ .init = event_trigger_init,
+ .free = event_enable_trigger_free,
+};
+
+static struct event_trigger_ops hist_disable_count_trigger_ops = {
+ .func = hist_enable_count_trigger,
+ .print = event_enable_trigger_print,
+ .init = event_trigger_init,
+ .free = event_enable_trigger_free,
+};
+
+static struct event_trigger_ops *
+hist_enable_get_trigger_ops(char *cmd, char *param)
+{
+ struct event_trigger_ops *ops;
+ bool enable;
+
+ enable = (strcmp(cmd, ENABLE_HIST_STR) == 0);
+
+ if (enable)
+ ops = param ? &hist_enable_count_trigger_ops :
+ &hist_enable_trigger_ops;
+ else
+ ops = param ? &hist_disable_count_trigger_ops :
+ &hist_disable_trigger_ops;
+
+ return ops;
+}
+
+static struct event_command trigger_hist_enable_cmd = {
+ .name = ENABLE_HIST_STR,
+ .trigger_type = ETT_HIST_ENABLE,
+ .func = event_enable_trigger_func,
+ .reg = event_enable_register_trigger,
+ .unreg = event_enable_unregister_trigger,
+ .get_trigger_ops = hist_enable_get_trigger_ops,
+ .set_filter = set_trigger_filter,
+};
+
+static struct event_command trigger_hist_disable_cmd = {
+ .name = DISABLE_HIST_STR,
+ .trigger_type = ETT_HIST_ENABLE,
+ .func = event_enable_trigger_func,
+ .reg = event_enable_register_trigger,
+ .unreg = event_enable_unregister_trigger,
+ .get_trigger_ops = hist_enable_get_trigger_ops,
+ .set_filter = set_trigger_filter,
+};
+
+static __init void unregister_trigger_hist_enable_disable_cmds(void)
+{
+ unregister_event_command(&trigger_hist_enable_cmd);
+ unregister_event_command(&trigger_hist_disable_cmd);
+}
+
+__init int register_trigger_hist_enable_disable_cmds(void)
+{
+ int ret;
+
+ ret = register_event_command(&trigger_hist_enable_cmd);
+ if (WARN_ON(ret < 0))
+ return ret;
+ ret = register_event_command(&trigger_hist_disable_cmd);
+ if (WARN_ON(ret < 0))
+ unregister_trigger_hist_enable_disable_cmds();
+
+ return ret;
+}
diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
index a09eba3..7105f15 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -338,7 +338,7 @@ __init int register_event_command(struct event_command *cmd)
* Currently we only unregister event commands from __init, so mark
* this __init too.
*/
-static __init int unregister_event_command(struct event_command *cmd)
+__init int unregister_event_command(struct event_command *cmd)
{
struct event_command *p, *n;
int ret = -ENODEV;
@@ -1051,15 +1051,6 @@ static __init void unregister_trigger_traceon_traceoff_cmds(void)
unregister_event_command(&trigger_traceoff_cmd);
}
-/* Avoid typos */
-#define ENABLE_EVENT_STR "enable_event"
-#define DISABLE_EVENT_STR "disable_event"
-
-struct enable_trigger_data {
- struct ftrace_event_file *file;
- bool enable;
-};
-
static void
event_enable_trigger(struct event_trigger_data *data, void *rec)
{
@@ -1089,14 +1080,16 @@ event_enable_count_trigger(struct event_trigger_data *data, void *rec)
event_enable_trigger(data, rec);
}
-static int
-event_enable_trigger_print(struct seq_file *m, struct event_trigger_ops *ops,
- struct event_trigger_data *data)
+int event_enable_trigger_print(struct seq_file *m,
+ struct event_trigger_ops *ops,
+ struct event_trigger_data *data)
{
struct enable_trigger_data *enable_data = data->private_data;
seq_printf(m, "%s:%s:%s",
- enable_data->enable ? ENABLE_EVENT_STR : DISABLE_EVENT_STR,
+ enable_data->hist ?
+ (enable_data->enable ? ENABLE_HIST_STR : DISABLE_HIST_STR) :
+ (enable_data->enable ? ENABLE_EVENT_STR : DISABLE_EVENT_STR),
enable_data->file->event_call->class->system,
ftrace_event_name(enable_data->file->event_call));
@@ -1113,9 +1106,8 @@ event_enable_trigger_print(struct seq_file *m, struct event_trigger_ops *ops,
return 0;
}
-static void
-event_enable_trigger_free(struct event_trigger_ops *ops,
- struct event_trigger_data *data)
+void event_enable_trigger_free(struct event_trigger_ops *ops,
+ struct event_trigger_data *data)
{
struct enable_trigger_data *enable_data = data->private_data;
@@ -1160,10 +1152,9 @@ static struct event_trigger_ops event_disable_count_trigger_ops = {
.free = event_enable_trigger_free,
};
-static int
-event_enable_trigger_func(struct event_command *cmd_ops,
- struct ftrace_event_file *file,
- char *glob, char *cmd, char *param)
+int event_enable_trigger_func(struct event_command *cmd_ops,
+ struct ftrace_event_file *file,
+ char *glob, char *cmd, char *param)
{
struct ftrace_event_file *event_enable_file;
struct enable_trigger_data *enable_data;
@@ -1172,6 +1163,7 @@ event_enable_trigger_func(struct event_command *cmd_ops,
struct trace_array *tr = file->tr;
const char *system;
const char *event;
+ bool hist = false;
char *trigger;
char *number;
bool enable;
@@ -1196,8 +1188,15 @@ event_enable_trigger_func(struct event_command *cmd_ops,
if (!event_enable_file)
goto out;
- enable = strcmp(cmd, ENABLE_EVENT_STR) == 0;
+#ifdef CONFIG_HIST_TRIGGERS
+ hist = ((strcmp(cmd, ENABLE_HIST_STR) == 0) ||
+ (strcmp(cmd, DISABLE_HIST_STR) == 0));
+ enable = ((strcmp(cmd, ENABLE_EVENT_STR) == 0) ||
+ (strcmp(cmd, ENABLE_HIST_STR) == 0));
+#else
+ enable = strcmp(cmd, ENABLE_EVENT_STR) == 0;
+#endif
trigger_ops = cmd_ops->get_trigger_ops(cmd, trigger);
ret = -ENOMEM;
@@ -1217,6 +1216,7 @@ event_enable_trigger_func(struct event_command *cmd_ops,
INIT_LIST_HEAD(&trigger_data->list);
RCU_INIT_POINTER(trigger_data->filter, NULL);
+ enable_data->hist = hist;
enable_data->enable = enable;
enable_data->file = event_enable_file;
trigger_data->private_data = enable_data;
@@ -1294,10 +1294,10 @@ event_enable_trigger_func(struct event_command *cmd_ops,
goto out;
}
-static int event_enable_register_trigger(char *glob,
- struct event_trigger_ops *ops,
- struct event_trigger_data *data,
- struct ftrace_event_file *file)
+int event_enable_register_trigger(char *glob,
+ struct event_trigger_ops *ops,
+ struct event_trigger_data *data,
+ struct ftrace_event_file *file)
{
struct enable_trigger_data *enable_data = data->private_data;
struct enable_trigger_data *test_enable_data;
@@ -1307,6 +1307,8 @@ static int event_enable_register_trigger(char *glob,
list_for_each_entry_rcu(test, &file->triggers, list) {
test_enable_data = test->private_data;
if (test_enable_data &&
+ (test->cmd_ops->trigger_type ==
+ data->cmd_ops->trigger_type) &&
(test_enable_data->file == enable_data->file)) {
ret = -EEXIST;
goto out;
@@ -1331,10 +1333,10 @@ out:
return ret;
}
-static void event_enable_unregister_trigger(char *glob,
- struct event_trigger_ops *ops,
- struct event_trigger_data *test,
- struct ftrace_event_file *file)
+void event_enable_unregister_trigger(char *glob,
+ struct event_trigger_ops *ops,
+ struct event_trigger_data *test,
+ struct ftrace_event_file *file)
{
struct enable_trigger_data *test_enable_data = test->private_data;
struct enable_trigger_data *enable_data;
@@ -1344,6 +1346,8 @@ static void event_enable_unregister_trigger(char *glob,
list_for_each_entry_rcu(data, &file->triggers, list) {
enable_data = data->private_data;
if (enable_data &&
+ (data->cmd_ops->trigger_type ==
+ test->cmd_ops->trigger_type) &&
(enable_data->file == test_enable_data->file)) {
unregistered = true;
list_del_rcu(&data->list);
@@ -1363,8 +1367,12 @@ event_enable_get_trigger_ops(char *cmd, char *param)
struct event_trigger_ops *ops;
bool enable;
+#ifdef CONFIG_HIST_TRIGGERS
+ enable = ((strcmp(cmd, ENABLE_EVENT_STR) == 0) ||
+ (strcmp(cmd, ENABLE_HIST_STR) == 0));
+#else
enable = strcmp(cmd, ENABLE_EVENT_STR) == 0;
-
+#endif
if (enable)
ops = param ? &event_enable_count_trigger_ops :
&event_enable_trigger_ops;
@@ -1435,6 +1443,7 @@ __init int register_trigger_cmds(void)
register_trigger_snapshot_cmd();
register_trigger_stacktrace_cmd();
register_trigger_enable_disable_cmds();
+ register_trigger_hist_enable_disable_cmds();
register_trigger_hist_cmd();
return 0;
--
1.9.3
^ permalink raw reply related [flat|nested] 13+ messages in thread* [PATCH v4 7/7] tracing: Add 'hist' trigger Documentation
2015-04-10 16:05 [PATCH v4 0/7] tracing: 'hist' triggers Tom Zanussi
` (5 preceding siblings ...)
2015-04-10 16:05 ` [PATCH v4 6/7] tracing: Add enable_hist/disable_hist triggers Tom Zanussi
@ 2015-04-10 16:05 ` Tom Zanussi
2015-04-20 12:52 ` [PATCH v4 0/7] tracing: 'hist' triggers Daniel Wagner
7 siblings, 0 replies; 13+ messages in thread
From: Tom Zanussi @ 2015-04-10 16:05 UTC (permalink / raw)
To: rostedt
Cc: masami.hiramatsu.pt, namhyung, andi, alexei.starovoitov,
linux-kernel, Tom Zanussi
Add documentation and usage examples for 'hist' triggers.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
Documentation/trace/events.txt | 870 +++++++++++++++++++++++++++++++++++++++++
1 file changed, 870 insertions(+)
diff --git a/Documentation/trace/events.txt b/Documentation/trace/events.txt
index 75d25a1..d7d6e81 100644
--- a/Documentation/trace/events.txt
+++ b/Documentation/trace/events.txt
@@ -494,3 +494,873 @@ 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 a
+ 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>:values=<field1[,field2,...]>
+ [:size=#entries][:sort=field1][: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. 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 keyworks 'values', 'vals', or 'val' can be used to specify
+ values. For the time being, only a single key can be used -
+ compound keys aren't yet 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. 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
+ .syscall display a syscall id as a system call name
+ .execname display a common_pid as a program name
+
+ 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'
+ param 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' param 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' param 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' param will clear the contents of a running hist trigger
+ and leave its current paused/active state.
+
+- 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: 18446744071581750326 hitcount: 1 bytes_req: 24
+ call_site: 18446744071583151255 hitcount: 1 bytes_req: 32
+ call_site: 18446744071582443167 hitcount: 1 bytes_req: 264
+ call_site: 18446744072104099935 hitcount: 2 bytes_req: 464
+ call_site: 18446744071579323550 hitcount: 3 bytes_req: 168
+ call_site: 18446744071580558850 hitcount: 4 bytes_req: 65536
+ .
+ .
+ .
+ call_site: 18446744072101362738 hitcount: 4115 bytes_req: 362120
+ call_site: 18446744072103235682 hitcount: 4115 bytes_req: 427960
+ call_site: 18446744072102962280 hitcount: 4342 bytes_req: 1637584
+ call_site: 18446744072102962328 hitcount: 4973 bytes_req: 360624
+ call_site: 18446744072101400062 hitcount: 6465 bytes_req: 258600
+ call_site: 18446744071582063959 hitcount: 7818 bytes_req: 15636
+ call_site: 18446744072102968908 hitcount: 9315 bytes_req: 8912400
+ call_site: 18446744072103122419 hitcount: 9315 bytes_req: 819720
+ call_site: 18446744072101402850 hitcount: 10240 bytes_req: 573440
+ call_site: 18446744072099471334 hitcount: 23820 bytes_req: 476512
+
+ Totals:
+ Hits: 109976
+ Entries: 76
+ 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' fields 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' param).
+
+ Notice in the above output that there's an extra field, 'hitcount',
+ that wasn't specified in the trigger. Also notice that in the
+ trigger info a param,'sort=hitcount', which wasn't specified in the
+ trigger either. The reason is that every trigger implicitly keeps a
+ count of the total number of hits attributed to a given entry,
+ called the 'hitcount', and that in the absence of a user-specified
+ sort param, the hitcount is used as the default sort field.
+
+ The value 'hitcount' can be used in place of an explicit value in
+ the 'values' param 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 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 hex
+ values, 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: ffffffffa04e85cb hitcount: 1 bytes_req: 511
+ call_site: ffffffff810a66a9 hitcount: 1 bytes_req: 1024
+ call_site: ffffffff8152db82 hitcount: 1 bytes_req: 8
+ call_site: ffffffffa008829e hitcount: 1 bytes_req: 7
+ call_site: ffffffffa0087d6a hitcount: 1 bytes_req: 7
+ call_site: ffffffffa02eb7e1 hitcount: 1 bytes_req: 433
+ call_site: ffffffff8152cbde hitcount: 1 bytes_req: 192
+ call_site: ffffffff811a2602 hitcount: 2 bytes_req: 32768
+ .
+ .
+ .
+ call_site: ffffffffa0419062 hitcount: 724 bytes_req: 75296
+ call_site: ffffffffa024fc32 hitcount: 724 bytes_req: 63712
+ call_site: ffffffffa03d6468 hitcount: 852 bytes_req: 416736
+ call_site: ffffffffa03d6498 hitcount: 944 bytes_req: 70984
+ call_site: ffffffff81311d57 hitcount: 961 bytes_req: 1922
+ call_site: ffffffffa0258dfe hitcount: 1429 bytes_req: 57160
+ call_site: ffffffffa03fd5f3 hitcount: 1796 bytes_req: 158048
+ call_site: ffffffffa03d7e4c hitcount: 1796 bytes_req: 2206848
+ call_site: ffffffffa02598e2 hitcount: 3196 bytes_req: 178976
+ call_site: ffffffffa0081fe6 hitcount: 9529 bytes_req: 190584
+
+ Totals:
+ Hits: 24542
+ Entries: 60
+ 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' 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: [ffffffff8152db82] usb_control_msg hitcount: 1 bytes_req: 8
+ call_site: [ffffffffa04e85cb] __ieee80211_start_scan hitcount: 1 bytes_req: 511
+ call_site: [ffffffff815d7f6b] sk_prot_alloc hitcount: 1 bytes_req: 976
+ call_site: [ffffffff8152cbde] usb_alloc_urb hitcount: 1 bytes_req: 192
+ call_site: [ffffffff815d2c1b] sock_alloc_inode hitcount: 1 bytes_req: 64
+ call_site: [ffffffffa02eb7e1] nl80211_trigger_scan hitcount: 1 bytes_req: 433
+ call_site: [ffffffffa0087d6a] hidraw_report_event hitcount: 1 bytes_req: 7
+ call_site: [ffffffff810a66a9] syslog_print_all hitcount: 1 bytes_req: 1024
+ call_site: [ffffffffa008829e] hidraw_send_report hitcount: 1 bytes_req: 7
+ call_site: [ffffffff811f1316] mounts_open_common hitcount: 2 bytes_req: 368
+ call_site: [ffffffff811d0825] alloc_fdtable hitcount: 2 bytes_req: 96
+ call_site: [ffffffffa042106f] __intel_framebuffer_create hitcount: 3 bytes_req: 432
+ .
+ .
+ .
+ call_site: [ffffffff8136b079] sg_kmalloc hitcount: 461 bytes_req: 153696
+ call_site: [ffffffffa03dbc5e] i915_gem_obj_lookup_or_create_vma hitcount: 462 bytes_req: 92400
+ call_site: [ffffffffa03e213a] i915_gem_object_get_pages_gtt hitcount: 462 bytes_req: 7392
+ call_site: [ffffffffa03d6498] i915_gem_do_execbuffer.isra.22 hitcount: 697 bytes_req: 52064
+ call_site: [ffffffff81311d57] apparmor_file_alloc_security hitcount: 926 bytes_req: 1852
+ call_site: [ffffffffa0258dfe] drm_vma_node_allow hitcount: 1050 bytes_req: 42000
+ call_site: [ffffffffa03fd5f3] intel_ring_begin hitcount: 1116 bytes_req: 98208
+ call_site: [ffffffffa03d7e4c] i915_gem_execbuffer2 hitcount: 1116 bytes_req: 956984
+ call_site: [ffffffffa02598e2] drm_modeset_lock_crtc hitcount: 2055 bytes_req: 115080
+ call_site: [ffffffffa0081fe6] hid_report_raw_event hitcount: 6433 bytes_req: 128664
+
+ Totals:
+ Hits: 17384
+ Entries: 62
+ 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' param, 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:size=2048 [active]
+
+ call_site: [ffffffffa03d7e4c] i915_gem_execbuffer2 hitcount: 682 bytes_req: 766360
+ call_site: [ffffffff811d6c3b] seq_buf_alloc hitcount: 46 bytes_req: 186176
+ call_site: [ffffffffa03d6468] i915_gem_do_execbuffer.isra.22 hitcount: 377 bytes_req: 142808
+ call_site: [ffffffffa02598e2] drm_modeset_lock_crtc hitcount: 1107 bytes_req: 61992
+ call_site: [ffffffffa03fd5f3] intel_ring_begin hitcount: 682 bytes_req: 60016
+ call_site: [ffffffffa0081fe6] hid_report_raw_event hitcount: 2993 bytes_req: 59864
+ call_site: [ffffffff8136b079] sg_kmalloc hitcount: 206 bytes_req: 48096
+ call_site: [ffffffffa03dbc5e] i915_gem_obj_lookup_or_create_vma hitcount: 206 bytes_req: 41200
+ call_site: [ffffffff811a2602] __kmalloc hitcount: 2 bytes_req: 32768
+ call_site: [ffffffffa0419062] intel_crtc_page_flip hitcount: 305 bytes_req: 31720
+ call_site: [ffffffffa024fc32] drm_mode_page_flip_ioctl hitcount: 305 bytes_req: 26840
+ call_site: [ffffffffa0258dfe] drm_vma_node_allow hitcount: 603 bytes_req: 24120
+ call_site: [ffffffffa03d6498] i915_gem_do_execbuffer.isra.22 hitcount: 305 bytes_req: 23072
+ call_site: [ffffffff812775da] ext4_find_extent hitcount: 79 bytes_req: 7584
+ .
+ .
+ .
+ call_site: [ffffffff811f3b07] inotify_handle_event hitcount: 2 bytes_req: 96
+ call_site: [ffffffff811bfb6e] vfs_rename hitcount: 6 bytes_req: 66
+ call_site: [ffffffff815d2c1b] sock_alloc_inode hitcount: 1 bytes_req: 64
+ call_site: [ffffffff811d0825] alloc_fdtable hitcount: 1 bytes_req: 48
+ call_site: [ffffffff81220376] proc_self_follow_link hitcount: 2 bytes_req: 24
+ call_site: [ffffffff8112e1ec] hist_show hitcount: 2 bytes_req: 16
+ call_site: [ffffffff8112e1d0] hist_show hitcount: 2 bytes_req: 16
+ call_site: [ffffffff8152db82] usb_control_msg hitcount: 1 bytes_req: 8
+ call_site: [ffffffffa008829e] hidraw_send_report hitcount: 1 bytes_req: 7
+ call_site: [ffffffffa0087d6a] hidraw_report_event hitcount: 1 bytes_req: 7
+
+ Totals:
+ Hits: 9331
+ Entries: 57
+ Dropped: 0
+
+ We can also add multiple fields to the 'values' param. 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:size=2048 [active]
+
+ call_site: [ffffffffa03d7e4c] i915_gem_execbuffer2 hitcount: 4427 bytes_req: 4190032 bytes_alloc: 5967744
+ call_site: [ffffffff811d6c3b] seq_buf_alloc hitcount: 427 bytes_req: 1706768 bytes_alloc: 1765376
+ call_site: [ffffffffa03d6468] i915_gem_do_execbuffer.isra.22 hitcount: 1978 bytes_req: 765936 bytes_alloc: 1434304
+ call_site: [ffffffffa03fd5f3] intel_ring_begin hitcount: 4427 bytes_req: 389576 bytes_alloc: 424992
+ call_site: [ffffffff8136b079] sg_kmalloc hitcount: 993 bytes_req: 305824 bytes_alloc: 376576
+ call_site: [ffffffffa02598e2] drm_modeset_lock_crtc hitcount: 4319 bytes_req: 241864 bytes_alloc: 276416
+ call_site: [ffffffffa03dbc5e] i915_gem_obj_lookup_or_create_vma hitcount: 993 bytes_req: 198600 bytes_alloc: 254208
+ call_site: [ffffffffa0419062] intel_crtc_page_flip hitcount: 1806 bytes_req: 187824 bytes_alloc: 231168
+ call_site: [ffffffff81424d78] __tty_buffer_request_room hitcount: 61 bytes_req: 128928 bytes_alloc: 229376
+ call_site: [ffffffffa0081fe6] hid_report_raw_event hitcount: 9550 bytes_req: 191024 bytes_alloc: 210160
+ call_site: [ffffffffa03d6498] i915_gem_do_execbuffer.isra.22 hitcount: 2449 bytes_req: 184720 bytes_alloc: 209216
+ call_site: [ffffffffa0258dfe] drm_vma_node_allow hitcount: 3256 bytes_req: 130240 bytes_alloc: 208384
+ .
+ .
+ .
+ call_site: [ffffffffa04e85cb] __ieee80211_start_scan hitcount: 3 bytes_req: 1533 bytes_alloc: 1536
+ call_site: [ffffffffa02eb7e1] nl80211_trigger_scan hitcount: 3 bytes_req: 1299 bytes_alloc: 1536
+ call_site: [ffffffff8152cbde] usb_alloc_urb hitcount: 6 bytes_req: 1152 bytes_alloc: 1152
+ call_site: [ffffffff811f3b07] inotify_handle_event hitcount: 14 bytes_req: 744 bytes_alloc: 896
+ call_site: [ffffffff81206b81] load_elf_binary hitcount: 24 bytes_req: 672 bytes_alloc: 768
+ call_site: [ffffffff811bfb6e] vfs_rename hitcount: 38 bytes_req: 436 bytes_alloc: 640
+ call_site: [ffffffff81220376] proc_self_follow_link hitcount: 24 bytes_req: 288 bytes_alloc: 384
+ call_site: [ffffffff815d2c1b] sock_alloc_inode hitcount: 5 bytes_req: 320 bytes_alloc: 320
+ call_site: [ffffffff811d0825] alloc_fdtable hitcount: 4 bytes_req: 192 bytes_alloc: 256
+ call_site: [ffffffffa04ec05f] ieee80211_start_tx_ba_session hitcount: 1 bytes_req: 232 bytes_alloc: 256
+ call_site: [ffffffffa0244701] drm_vm_open_locked hitcount: 5 bytes_req: 160 bytes_alloc: 160
+ call_site: [ffffffff8112e1d0] hist_show hitcount: 10 bytes_req: 80 bytes_alloc: 80
+ call_site: [ffffffff8112e1ec] hist_show hitcount: 10 bytes_req: 80 bytes_alloc: 80
+ call_site: [ffffffff81074c9e] kthread_create_on_node hitcount: 1 bytes_req: 56 bytes_alloc: 64
+ call_site: [ffffffff8152db82] usb_control_msg hitcount: 6 bytes_req: 48 bytes_alloc: 48
+ call_site: [ffffffffa008829e] hidraw_send_report hitcount: 6 bytes_req: 42 bytes_alloc: 48
+ call_site: [ffffffffa0087d6a] hidraw_report_event hitcount: 6 bytes_req: 42 bytes_alloc: 48
+
+ Totals:
+ Hits: 45576
+ Entries: 66
+ 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_sites. To do that, we simply use the special
+ value 'stacktrace' for the key param:
+
+ # 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/0x190
+ kstrdup+0x35/0x70
+ __kernfs_new_node+0x34/0xf0
+ kernfs_new_node+0x26/0x50
+ kernfs_create_dir_ns+0x29/0x80
+ sysfs_create_dir_ns+0x40/0xa0
+ kobject_add_internal+0xbd/0x3a0
+ kobject_add+0x60/0xb0
+ device_add+0xff/0x5a0
+ device_register+0x1e/0x30
+ usb_create_ep_devs+0x81/0xd0
+ usb_new_device+0x357/0x410
+ hub_event+0xd68/0x11a0
+ process_one_work+0x149/0x3d0
+ worker_thread+0x121/0x4a0
+ kthread+0xd2/0xf0
+ hitcount: 1 bytes_req: 6 bytes_alloc: 8
+ stacktrace:
+ kmem_cache_alloc_trace+0xfb/0x160
+ usb_control_msg+0x42/0x110
+ hub_port_status+0x84/0x120
+ hub_port_reset+0x263/0x430
+ hub_port_init+0x77/0xbb0
+ hub_event+0x944/0x11a0
+ process_one_work+0x149/0x3d0
+ worker_thread+0x121/0x4a0
+ kthread+0xd2/0xf0
+ ret_from_fork+0x7c/0xb0
+ hitcount: 1 bytes_req: 8 bytes_alloc: 8
+ .
+ .
+ .
+ stacktrace:
+ __kmalloc+0x11b/0x1a0
+ load_elf_phdrs+0x76/0xa0
+ load_elf_binary+0x102/0x1780
+ search_binary_handler+0x97/0x1d0
+ do_execveat_common.isra.32+0x551/0x6e0
+ SyS_execve+0x3a/0x50
+ stub_execve+0x69/0xa0
+ hitcount: 131791 bytes_req: 67822944 bytes_alloc: 80279552
+ stacktrace:
+ __kmalloc+0x11b/0x1a0
+ i915_gem_execbuffer2+0x6c/0x2c0 [i915]
+ drm_ioctl+0x1a4/0x630 [drm]
+ do_vfs_ioctl+0x2f0/0x4f0
+ SyS_ioctl+0x81/0xa0
+ system_call_fastpath+0x12/0x17
+ hitcount: 164540 bytes_req: 134464456 bytes_alloc: 167693376
+ stacktrace:
+ kmem_cache_alloc_trace+0xfb/0x160
+ apparmor_file_alloc_security+0x27/0x40
+ security_file_alloc+0x16/0x20
+ get_empty_filp+0x93/0x1c0
+ path_openat+0x31/0x620
+ do_filp_open+0x3a/0x90
+ do_sys_open+0x128/0x220
+ SyS_open+0x1e/0x20
+ system_call_fastpath+0x12/0x17
+ hitcount: 22118413 bytes_req: 44236888 bytes_alloc: 176947328
+ stacktrace:
+ __kmalloc+0x11b/0x1a0
+ seq_buf_alloc+0x1b/0x50
+ seq_read+0x2cc/0x370
+ proc_reg_read+0x3d/0x80
+ __vfs_read+0x18/0x50
+ vfs_read+0x86/0x140
+ SyS_read+0x46/0xb0
+ system_call_fastpath+0x12/0x17
+ hitcount: 66168 bytes_req: 271015944 bytes_alloc: 271015952
+
+ Totals:
+ Hits: 26780801
+ Entries: 633
+ Dropped: 0
+
+ If you key a hist trigger on pid, 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:size=2048 [active]
+
+ common_pid: Xorg [18446612132314219843] hitcount: 166 count: 159744
+ common_pid: gnome-terminal [18446612132314221635] hitcount: 44 count: 113321
+ common_pid: compiz [18446612132314221491] hitcount: 13 count: 81968
+ common_pid: bash [18446612132314231931] hitcount: 3 count: 66369
+ common_pid: gdbus [18446612132314221135] hitcount: 91 count: 1456
+ common_pid: acpid [18446612132314219701] hitcount: 48 count: 1152
+ common_pid: ibus-daemon [18446612132314221129] hitcount: 71 count: 1136
+ common_pid: gdbus [18446612132314221638] hitcount: 42 count: 672
+ common_pid: gdbus [18446612132314221345] hitcount: 42 count: 672
+ common_pid: ibus-engine-sim [18446612132314221344] hitcount: 14 count: 224
+ common_pid: gdbus [18446612132314221262] hitcount: 12 count: 192
+ common_pid: gdbus [18446612132314221249] hitcount: 6 count: 96
+ common_pid: ibus-ui-gtk3 [18446612132314221245] hitcount: 6 count: 96
+ common_pid: gdbus [18446612132314221504] hitcount: 5 count: 80
+ common_pid: unity-panel-ser [18446612132314221243] hitcount: 3 count: 48
+ common_pid: postgres [18446612132314220339] hitcount: 1 count: 16
+ common_pid: gdbus [18446612132314221395] hitcount: 1 count: 16
+ common_pid: rtkit-daemon [18446612132314220509] hitcount: 1 count: 8
+ common_pid: upstart-dbus-br [18446612132314221100] hitcount: 4 count: 4
+ common_pid: bash [18446612132314221924] hitcount: 4 count: 4
+ common_pid: firefox [18446612132314222258] hitcount: 1 count: 1
+
+ Totals:
+ Hits: 578
+ Entries: 21
+ 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=:sort=hitcount:size=2048 [active]
+
+ id: sys_fadvise64 hitcount: 1
+ id: sys_bind hitcount: 1
+ id: sys_fsync hitcount: 1
+ id: sys_getsockname hitcount: 1
+ id: sys_readlink hitcount: 3
+ id: sys_set_tid_address hitcount: 4
+ .
+ .
+ .
+ id: sys_mprotect hitcount: 57
+ id: sys_waitid hitcount: 64
+ id: sys_rt_sigaction hitcount: 121
+ id: sys_inotify_add_watch hitcount: 234
+ id: sys_mmap hitcount: 258
+ id: sys_nanosleep hitcount: 310
+ id: sys_close hitcount: 323
+ id: sys_rt_sigprocmask hitcount: 3520
+ id: sys_futex hitcount: 4819
+ id: sys_write hitcount: 8907
+ id: sys_setitimer hitcount: 39039
+ id: sys_writev hitcount: 64528
+ id: sys_poll hitcount: 77493
+ id: sys_recvmsg hitcount: 168240
+ id: sys_ioctl hitcount: 448946
+
+ Totals:
+ Hits: 869971
+ Entries: 75
+ Dropped: 0
+
+ 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=:sort=hitcount:size=256 [active]
+
+ child_comm: gdbus hitcount: 1
+ child_comm: smbd hitcount: 1
+ child_comm: ibus-daemon hitcount: 1
+ child_comm: Cache2 I/O hitcount: 1
+ child_comm: dconf worker hitcount: 1
+ child_comm: postgres hitcount: 1
+ child_comm: unity-panel-ser hitcount: 2
+ child_comm: compiz hitcount: 3
+ child_comm: bash hitcount: 3
+ child_comm: firefox hitcount: 60
+
+ Totals:
+ Hits: 74
+ Entries: 10
+ Dropped: 0
+
+ # echo 'hist:key=child_comm:val=hitcount:size=256:pause' > \
+ /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
+
+ 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]:
+
+ # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
+ trigger info: hist:keys=child_comm:vals=:sort=hitcount:size=256 [paused]
+
+ child_comm: dconf worker hitcount: 1
+ child_comm: gdbus hitcount: 1
+ child_comm: Cache2 I/O hitcount: 1
+ child_comm: ibus-daemon hitcount: 1
+ child_comm: unity-panel-ser hitcount: 2
+ child_comm: smbd hitcount: 2
+ child_comm: postgres hitcount: 3
+ child_comm: compiz hitcount: 3
+ child_comm: bash hitcount: 3
+ child_comm: emacs hitcount: 8
+ child_comm: firefox hitcount: 60
+
+ Totals:
+ Hits: 85
+ Entries: 11
+ 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=:sort=hitcount:size=256 [active]
+
+ child_comm: Cache2 I/O hitcount: 1
+ child_comm: ibus-daemon hitcount: 1
+ child_comm: kthreadd hitcount: 1
+ child_comm: gdbus hitcount: 1
+ child_comm: dconf worker hitcount: 1
+ child_comm: unity-panel-ser hitcount: 2
+ child_comm: smbd hitcount: 2
+ child_comm: compiz hitcount: 3
+ child_comm: postgres hitcount: 4
+ child_comm: bash hitcount: 4
+ child_comm: emacs hitcount: 8
+ child_comm: firefox hitcount: 60
+
+ Totals:
+ Hits: 88
+ Entries: 12
+ 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, start the trigger in a paused state,
+ then unpause it and do something you want to measure, then pause the
+ trigger 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_received_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+0x4ad/0x780
+ __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/0x810
+ ip_output+0x68/0xa0
+ ip_local_out_sk+0x30/0x40
+ ip_send_skb+0x1a/0x50
+ udp_send_skb+0x173/0x2a0
+ udp_sendmsg+0x2bf/0x9f0
+ inet_sendmsg+0x63/0xb0
+ do_sock_sendmsg+0x8c/0x100
+ hitcount: 4 len: 388
+ stacktrace:
+ __netif_receive_skb_core+0x4ad/0x780
+ __netif_receive_skb+0x18/0x60
+ netif_receive_skb_internal+0x23/0x90
+ napi_gro_receive+0xc8/0x100
+ ieee80211_deliver_skb+0xba/0x250 [mac80211]
+ ieee80211_rx_handlers+0xcc5/0x2240 [mac80211]
+ ieee80211_prepare_and_rx_handle+0x4e7/0xc30 [mac80211]
+ ieee80211_rx+0x31d/0x920 [mac80211]
+ iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm]
+ iwl_rx_dispatch+0x8e/0xf0 [iwldvm]
+ iwl_pcie_irq_handler+0xe1c/0x12c0 [iwlwifi]
+ irq_thread_fn+0x20/0x50
+ irq_thread+0x11f/0x150
+ kthread+0xd2/0xf0
+ ret_from_fork+0x7c/0xb0
+ hitcount: 35 len: 17415
+ stacktrace:
+ __netif_receive_skb_core+0x4ad/0x780
+ __netif_receive_skb+0x18/0x60
+ netif_receive_skb_internal+0x23/0x90
+ napi_gro_complete+0xa4/0xe0
+ dev_gro_receive+0x233/0x360
+ napi_gro_receive+0x30/0x100
+ ieee80211_deliver_skb+0xba/0x250 [mac80211]
+ ieee80211_rx_handlers+0xcc5/0x2240 [mac80211]
+ ieee80211_prepare_and_rx_handle+0x4e7/0xc30 [mac80211]
+ ieee80211_rx+0x31d/0x920 [mac80211]
+ iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm]
+ iwl_rx_dispatch+0x8e/0xf0 [iwldvm]
+ iwl_pcie_irq_handler+0xe1c/0x12c0 [iwlwifi]
+ irq_thread_fn+0x20/0x50
+ irq_thread+0x11f/0x150
+ kthread+0xd2/0xf0
+ hitcount: 155 len: 636342
+ stacktrace:
+ __netif_receive_skb_core+0x4ad/0x780
+ __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+0x90f/0x12c0 [iwlwifi]
+ irq_thread_fn+0x20/0x50
+ irq_thread+0x11f/0x150
+ kthread+0xd2/0xf0
+ ret_from_fork+0x7c/0xb0
+ hitcount: 1013 len: 5531908
+
+ Totals:
+ Hits: 1207
+ 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 same events
+ being aggregated into the hash table, we add some additional
+ 'enable_event' events 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, whever 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.
+
+ 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
+ .
+ .
+ .
--
1.9.3
^ permalink raw reply related [flat|nested] 13+ messages in thread* Re: [PATCH v4 0/7] tracing: 'hist' triggers
2015-04-10 16:05 [PATCH v4 0/7] tracing: 'hist' triggers Tom Zanussi
` (6 preceding siblings ...)
2015-04-10 16:05 ` [PATCH v4 7/7] tracing: Add 'hist' trigger Documentation Tom Zanussi
@ 2015-04-20 12:52 ` Daniel Wagner
2015-04-20 14:15 ` Tom Zanussi
2015-04-20 22:03 ` Tom Zanussi
7 siblings, 2 replies; 13+ messages in thread
From: Daniel Wagner @ 2015-04-20 12:52 UTC (permalink / raw)
To: Tom Zanussi, rostedt
Cc: masami.hiramatsu.pt, namhyung, andi, alexei.starovoitov, linux-kernel
Hi Tom,
On 04/10/2015 06:05 PM, Tom Zanussi wrote:
> This is v4 of the 'hist triggers' patchset, following feedback from
> v3.
>
> This version fixes the race in tracing_map_insert() noted in v3, where
> map.val.key could be checked even if map.val wasn't yet set. The
> simple fix for that in tracing_map_insert() introduces the possibility
> of duplicates in the map, which though rare, need to be accounted for
> in the output. To address that, duplicate-merging code was added to
> the map-printing code.
Note: I might be abusing your patch. So this could be a completely
bogus question/feedback.
Most important information here is that I placed additional tracepoints
during state transitions. I needed to disable the rcu_dereference
consistency checks to be able to get it working (not claiming that this
is the right thing to do)
diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
index c728513..f194324 100644
--- a/include/linux/tracepoint.h
+++ b/include/linux/tracepoint.h
@@ -125,7 +125,7 @@ extern void syscall_unregfunc(void);
return; \
prercu; \
rcu_read_lock_sched_notrace(); \
- it_func_ptr = rcu_dereference_sched((tp)->funcs); \
+ it_func_ptr = rcu_dereference_raw_notrace((tp)->funcs); \
if (it_func_ptr) { \
do { \
it_func = (it_func_ptr)->func; \
@@ -175,7 +175,7 @@ extern void syscall_unregfunc(void);
TP_CONDITION(cond),,); \
if (IS_ENABLED(CONFIG_LOCKDEP) && (cond)) { \
rcu_read_lock_sched_notrace(); \
- rcu_dereference_sched(__tracepoint_##name.funcs);\
+ rcu_dereference_raw_notrace(__tracepoint_##name.funcs);\
rcu_read_unlock_sched_notrace(); \
} \
} \
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 8523ea3..03f42b9 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -14,6 +14,8 @@
#include <linux/module.h>
#include <linux/ftrace.h>
+#include <trace/events/sched.h>
+
#include "trace.h"
static struct trace_array *irqsoff_trace __read_mostly;
@@ -433,11 +435,13 @@ void start_critical_timings(void)
{
if (preempt_trace() || irq_trace())
start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+ trace_sched_latency_critical_timing(1);
}
EXPORT_SYMBOL_GPL(start_critical_timings);
void stop_critical_timings(void)
{
+ trace_sched_latency_critical_timing(0);
if (preempt_trace() || irq_trace())
stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
}
@@ -447,6 +451,7 @@ EXPORT_SYMBOL_GPL(stop_critical_timings);
#ifdef CONFIG_PROVE_LOCKING
void time_hardirqs_on(unsigned long a0, unsigned long a1)
{
+ trace_sched_latency_irqs(0);
if (!preempt_trace() && irq_trace())
stop_critical_timing(a0, a1);
}
@@ -455,6 +460,7 @@ void time_hardirqs_off(unsigned long a0, unsigned long a1)
{
if (!preempt_trace() && irq_trace())
start_critical_timing(a0, a1);
+ trace_sched_latency_irqs(1);
}
When activating now the hist trigger by
echo 'hist:key=common_pid:val=enabled' > \
/sys/kernel/debug/tracing/events/sched/sched_latency_preempt/trigger
the system crashes reliable after a very short time. Those tracepoints
do work normally, so I see them in /sys/kernel/debug/tracing/trace.
After some investigation I found out that event_hist_trigger() gets
called with rec=NULL. This is handed over to hist_field_s32() and
that function derefences the argument event (=NULL).
#19 event_hist_trigger (data=0xffff88007934c780, rec=0x0 <irq_stack_union>) at kernel/trace/trace_events_hist.c:885
#20 0xffffffff8113771b in event_triggers_call (file=<optimized out>, rec=0x0 <irq_stack_union>) at kernel/trace/trace_events_trigger.c:78
#21 0xffffffff81079def in ftrace_trigger_soft_disabled (file=<optimized out>) at include/linux/ftrace_event.h:453
#22 ftrace_raw_event_sched_latency_template (__data=0xffff88007c895aa8, enabled=0) at include/trace/events/sched.h:557
#23 0xffffffff8112cbec in trace_sched_latency_preempt (enabled=<optimized out>) at include/trace/events/sched.h:587
#24 trace_preempt_off (a0=18446744071579483412, a1=18446744071579485792) at kernel/trace/trace_irqsoff.c:532
#25 0xffffffff8107f449 in preempt_count_add (val=1) at kernel/sched/core.c:2554
#26 0xffffffff8109bd14 in get_lock_stats (class=0xffffffff82e235d0 <lock_classes+273296>) at kernel/locking/lockdep.c:249
#27 0xffffffff8109c660 in lock_release_holdtime (hlock=0xffff880079c8ee50) at kernel/locking/lockdep.c:267
#28 0xffffffff810a2cc9 in lock_release_holdtime (hlock=<optimized out>) at kernel/locking/lockdep.c:3464
#29 lock_release_nested (ip=<optimized out>, lock=<optimized out>, curr=<optimized out>) at kernel/locking/lockdep.c:3481
#30 __lock_release (ip=<optimized out>, nested=<optimized out>, lock=<optimized out>) at kernel/locking/lockdep.c:3507
#31 lock_release (lock=0xffffffff8226e5f0 <kernfs_mutex+112>, nested=<optimized out>, ip=18446744071590106190) at kernel/locking/lockdep.c:3628
#32 0xffffffff81abd306 in __mutex_unlock_common_slowpath (nested=<optimized out>, lock=<optimized out>) at kernel/locking/mutex.c:744
#33 __mutex_unlock_slowpath (lock_count=0xffff88007934c780) at kernel/locking/mutex.c:769
#34 0xffffffff81abd44e in mutex_unlock (lock=<optimized out>) at kernel/locking/mutex.c:446
#35 0xffffffff81238e84 in kernfs_dop_revalidate (dentry=0xffff88007acede00, flags=<optimized out>) at fs/kernfs/dir.c:470
#36 0xffffffff811c9813 in d_revalidate (flags=<optimized out>, dentry=<optimized out>) at fs/namei.c:607
#37 lookup_fast (nd=0xffff8800790e3e48, path=0xffff8800790e3ca8, inode=0xffff8800790e3cb8) at fs/namei.c:1465
#38 0xffffffff811cc05f in walk_component (follow=<optimized out>, path=<optimized out>, nd=<optimized out>) at fs/namei.c:1577
#39 link_path_walk (name=0xffff880079fa602d "virtual/block/loop6/subsystem", nd=0xffff8800790e3e48) at fs/namei.c:1836
#40 0xffffffff811cd327 in path_init (dfd=<optimized out>, name=0xffff880079fa6020 "/sys/devices/virtual/block/loop6/subsystem", flags=2051493056, nd=0xffff8800790e3e48)
at fs/namei.c:1952
#41 0xffffffff811cda90 in path_lookupat (dfd=<optimized out>, name=<optimized out>, flags=16448, nd=0xffff8800790e3e48) at fs/namei.c:1995
#42 0xffffffff811cec1a in filename_lookup (dfd=-100, name=0xffff880079fa6000, flags=16384, nd=0xffff8800790e3e48) at fs/namei.c:2030
#43 0xffffffff811d0d34 in user_path_at_empty (dfd=-100, name=<optimized out>, flags=16384, path=0xffff8800790e3f38, empty=<optimized out>) at fs/namei.c:2197
#44 0xffffffff811c285c in SYSC_readlinkat (bufsiz=<optimized out>, buf=<optimized out>, pathname=<optimized out>, dfd=<optimized out>) at fs/stat.c:327
#45 SyS_readlinkat (bufsiz=<optimized out>, buf=<optimized out>, pathname=<optimized out>, dfd=<optimized out>) at fs/stat.c:315
#46 SYSC_readlink (bufsiz=<optimized out>, buf=<optimized out>, path=<optimized out>) at fs/stat.c:352
#47 SyS_readlink (path=-131939361831040, buf=0, bufsiz=<optimized out>) at fs/stat.c:349
So I am wondering if the path from ftrace_trigger_soft_disabled()
to event_triggers_call() is supposed never to happen? The comment
on ftrace_trigger_soft_disabled() indicate this might happen on
normal operation:
/**
* ftrace_trigger_soft_disabled - do triggers and test if soft disabled
* @file: The file pointer of the event to test
*
* If any triggers without filters are attached to this event, they
* will be called here. If the event is soft disabled and has no
* triggers that require testing the fields, it will return true,
* otherwise false.
*/
static inline bool
ftrace_trigger_soft_disabled(struct ftrace_event_file *file)
{
unsigned long eflags = file->flags;
if (!(eflags & FTRACE_EVENT_FL_TRIGGER_COND)) {
if (eflags & FTRACE_EVENT_FL_TRIGGER_MODE)
event_triggers_call(file, NULL);
if (eflags & FTRACE_EVENT_FL_SOFT_DISABLED)
return true;
}
return false;
}
cheers,
daniel
^ permalink raw reply related [flat|nested] 13+ messages in thread* Re: [PATCH v4 0/7] tracing: 'hist' triggers
2015-04-20 12:52 ` [PATCH v4 0/7] tracing: 'hist' triggers Daniel Wagner
@ 2015-04-20 14:15 ` Tom Zanussi
2015-04-20 22:03 ` Tom Zanussi
1 sibling, 0 replies; 13+ messages in thread
From: Tom Zanussi @ 2015-04-20 14:15 UTC (permalink / raw)
To: Daniel Wagner
Cc: rostedt, masami.hiramatsu.pt, namhyung, andi, alexei.starovoitov,
linux-kernel
Hi Daniel,
I'm traveling and at a conference this week - let me take a look at this
next chance I get, but yeah, that ftrace_trigger_soft_disabled() path is
a legal path but obviously when called in the case of a NULL rec, things
aren't going to work. Probably a bug in my code somewhere - will let
you know once I get a chance..
Thanks,
Tom
On Mon, 2015-04-20 at 14:52 +0200, Daniel Wagner wrote:
> Hi Tom,
>
> On 04/10/2015 06:05 PM, Tom Zanussi wrote:
> > This is v4 of the 'hist triggers' patchset, following feedback from
> > v3.
> >
> > This version fixes the race in tracing_map_insert() noted in v3, where
> > map.val.key could be checked even if map.val wasn't yet set. The
> > simple fix for that in tracing_map_insert() introduces the possibility
> > of duplicates in the map, which though rare, need to be accounted for
> > in the output. To address that, duplicate-merging code was added to
> > the map-printing code.
>
> Note: I might be abusing your patch. So this could be a completely
> bogus question/feedback.
>
> Most important information here is that I placed additional tracepoints
> during state transitions. I needed to disable the rcu_dereference
> consistency checks to be able to get it working (not claiming that this
> is the right thing to do)
>
> diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
> index c728513..f194324 100644
> --- a/include/linux/tracepoint.h
> +++ b/include/linux/tracepoint.h
> @@ -125,7 +125,7 @@ extern void syscall_unregfunc(void);
> return; \
> prercu; \
> rcu_read_lock_sched_notrace(); \
> - it_func_ptr = rcu_dereference_sched((tp)->funcs); \
> + it_func_ptr = rcu_dereference_raw_notrace((tp)->funcs); \
> if (it_func_ptr) { \
> do { \
> it_func = (it_func_ptr)->func; \
> @@ -175,7 +175,7 @@ extern void syscall_unregfunc(void);
> TP_CONDITION(cond),,); \
> if (IS_ENABLED(CONFIG_LOCKDEP) && (cond)) { \
> rcu_read_lock_sched_notrace(); \
> - rcu_dereference_sched(__tracepoint_##name.funcs);\
> + rcu_dereference_raw_notrace(__tracepoint_##name.funcs);\
> rcu_read_unlock_sched_notrace(); \
> } \
> } \
>
>
> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> index 8523ea3..03f42b9 100644
> --- a/kernel/trace/trace_irqsoff.c
> +++ b/kernel/trace/trace_irqsoff.c
> @@ -14,6 +14,8 @@
> #include <linux/module.h>
> #include <linux/ftrace.h>
>
> +#include <trace/events/sched.h>
> +
> #include "trace.h"
>
> static struct trace_array *irqsoff_trace __read_mostly;
> @@ -433,11 +435,13 @@ void start_critical_timings(void)
> {
> if (preempt_trace() || irq_trace())
> start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
> + trace_sched_latency_critical_timing(1);
> }
> EXPORT_SYMBOL_GPL(start_critical_timings);
>
> void stop_critical_timings(void)
> {
> + trace_sched_latency_critical_timing(0);
> if (preempt_trace() || irq_trace())
> stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
> }
> @@ -447,6 +451,7 @@ EXPORT_SYMBOL_GPL(stop_critical_timings);
> #ifdef CONFIG_PROVE_LOCKING
> void time_hardirqs_on(unsigned long a0, unsigned long a1)
> {
> + trace_sched_latency_irqs(0);
> if (!preempt_trace() && irq_trace())
> stop_critical_timing(a0, a1);
> }
> @@ -455,6 +460,7 @@ void time_hardirqs_off(unsigned long a0, unsigned long a1)
> {
> if (!preempt_trace() && irq_trace())
> start_critical_timing(a0, a1);
> + trace_sched_latency_irqs(1);
> }
>
> When activating now the hist trigger by
>
> echo 'hist:key=common_pid:val=enabled' > \
> /sys/kernel/debug/tracing/events/sched/sched_latency_preempt/trigger
>
> the system crashes reliable after a very short time. Those tracepoints
> do work normally, so I see them in /sys/kernel/debug/tracing/trace.
>
> After some investigation I found out that event_hist_trigger() gets
> called with rec=NULL. This is handed over to hist_field_s32() and
> that function derefences the argument event (=NULL).
>
> #19 event_hist_trigger (data=0xffff88007934c780, rec=0x0 <irq_stack_union>) at kernel/trace/trace_events_hist.c:885
> #20 0xffffffff8113771b in event_triggers_call (file=<optimized out>, rec=0x0 <irq_stack_union>) at kernel/trace/trace_events_trigger.c:78
> #21 0xffffffff81079def in ftrace_trigger_soft_disabled (file=<optimized out>) at include/linux/ftrace_event.h:453
> #22 ftrace_raw_event_sched_latency_template (__data=0xffff88007c895aa8, enabled=0) at include/trace/events/sched.h:557
> #23 0xffffffff8112cbec in trace_sched_latency_preempt (enabled=<optimized out>) at include/trace/events/sched.h:587
> #24 trace_preempt_off (a0=18446744071579483412, a1=18446744071579485792) at kernel/trace/trace_irqsoff.c:532
> #25 0xffffffff8107f449 in preempt_count_add (val=1) at kernel/sched/core.c:2554
> #26 0xffffffff8109bd14 in get_lock_stats (class=0xffffffff82e235d0 <lock_classes+273296>) at kernel/locking/lockdep.c:249
> #27 0xffffffff8109c660 in lock_release_holdtime (hlock=0xffff880079c8ee50) at kernel/locking/lockdep.c:267
> #28 0xffffffff810a2cc9 in lock_release_holdtime (hlock=<optimized out>) at kernel/locking/lockdep.c:3464
> #29 lock_release_nested (ip=<optimized out>, lock=<optimized out>, curr=<optimized out>) at kernel/locking/lockdep.c:3481
> #30 __lock_release (ip=<optimized out>, nested=<optimized out>, lock=<optimized out>) at kernel/locking/lockdep.c:3507
> #31 lock_release (lock=0xffffffff8226e5f0 <kernfs_mutex+112>, nested=<optimized out>, ip=18446744071590106190) at kernel/locking/lockdep.c:3628
> #32 0xffffffff81abd306 in __mutex_unlock_common_slowpath (nested=<optimized out>, lock=<optimized out>) at kernel/locking/mutex.c:744
> #33 __mutex_unlock_slowpath (lock_count=0xffff88007934c780) at kernel/locking/mutex.c:769
> #34 0xffffffff81abd44e in mutex_unlock (lock=<optimized out>) at kernel/locking/mutex.c:446
> #35 0xffffffff81238e84 in kernfs_dop_revalidate (dentry=0xffff88007acede00, flags=<optimized out>) at fs/kernfs/dir.c:470
> #36 0xffffffff811c9813 in d_revalidate (flags=<optimized out>, dentry=<optimized out>) at fs/namei.c:607
> #37 lookup_fast (nd=0xffff8800790e3e48, path=0xffff8800790e3ca8, inode=0xffff8800790e3cb8) at fs/namei.c:1465
> #38 0xffffffff811cc05f in walk_component (follow=<optimized out>, path=<optimized out>, nd=<optimized out>) at fs/namei.c:1577
> #39 link_path_walk (name=0xffff880079fa602d "virtual/block/loop6/subsystem", nd=0xffff8800790e3e48) at fs/namei.c:1836
> #40 0xffffffff811cd327 in path_init (dfd=<optimized out>, name=0xffff880079fa6020 "/sys/devices/virtual/block/loop6/subsystem", flags=2051493056, nd=0xffff8800790e3e48)
> at fs/namei.c:1952
> #41 0xffffffff811cda90 in path_lookupat (dfd=<optimized out>, name=<optimized out>, flags=16448, nd=0xffff8800790e3e48) at fs/namei.c:1995
> #42 0xffffffff811cec1a in filename_lookup (dfd=-100, name=0xffff880079fa6000, flags=16384, nd=0xffff8800790e3e48) at fs/namei.c:2030
> #43 0xffffffff811d0d34 in user_path_at_empty (dfd=-100, name=<optimized out>, flags=16384, path=0xffff8800790e3f38, empty=<optimized out>) at fs/namei.c:2197
> #44 0xffffffff811c285c in SYSC_readlinkat (bufsiz=<optimized out>, buf=<optimized out>, pathname=<optimized out>, dfd=<optimized out>) at fs/stat.c:327
> #45 SyS_readlinkat (bufsiz=<optimized out>, buf=<optimized out>, pathname=<optimized out>, dfd=<optimized out>) at fs/stat.c:315
> #46 SYSC_readlink (bufsiz=<optimized out>, buf=<optimized out>, path=<optimized out>) at fs/stat.c:352
> #47 SyS_readlink (path=-131939361831040, buf=0, bufsiz=<optimized out>) at fs/stat.c:349
>
> So I am wondering if the path from ftrace_trigger_soft_disabled()
> to event_triggers_call() is supposed never to happen? The comment
> on ftrace_trigger_soft_disabled() indicate this might happen on
> normal operation:
>
> /**
> * ftrace_trigger_soft_disabled - do triggers and test if soft disabled
> * @file: The file pointer of the event to test
> *
> * If any triggers without filters are attached to this event, they
> * will be called here. If the event is soft disabled and has no
> * triggers that require testing the fields, it will return true,
> * otherwise false.
> */
> static inline bool
> ftrace_trigger_soft_disabled(struct ftrace_event_file *file)
> {
> unsigned long eflags = file->flags;
>
> if (!(eflags & FTRACE_EVENT_FL_TRIGGER_COND)) {
> if (eflags & FTRACE_EVENT_FL_TRIGGER_MODE)
> event_triggers_call(file, NULL);
> if (eflags & FTRACE_EVENT_FL_SOFT_DISABLED)
> return true;
> }
> return false;
> }
>
> cheers,
> daniel
^ permalink raw reply [flat|nested] 13+ messages in thread* Re: [PATCH v4 0/7] tracing: 'hist' triggers
2015-04-20 12:52 ` [PATCH v4 0/7] tracing: 'hist' triggers Daniel Wagner
2015-04-20 14:15 ` Tom Zanussi
@ 2015-04-20 22:03 ` Tom Zanussi
2015-04-21 10:36 ` Daniel Wagner
1 sibling, 1 reply; 13+ messages in thread
From: Tom Zanussi @ 2015-04-20 22:03 UTC (permalink / raw)
To: Daniel Wagner
Cc: rostedt, masami.hiramatsu.pt, namhyung, andi, alexei.starovoitov,
linux-kernel
Hi Daniel,
On Mon, 2015-04-20 at 14:52 +0200, Daniel Wagner wrote:
> Hi Tom,
>
> On 04/10/2015 06:05 PM, Tom Zanussi wrote:
> > This is v4 of the 'hist triggers' patchset, following feedback from
> > v3.
> >
> > This version fixes the race in tracing_map_insert() noted in v3, where
> > map.val.key could be checked even if map.val wasn't yet set. The
> > simple fix for that in tracing_map_insert() introduces the possibility
> > of duplicates in the map, which though rare, need to be accounted for
> > in the output. To address that, duplicate-merging code was added to
> > the map-printing code.
>
> Note: I might be abusing your patch. So this could be a completely
> bogus question/feedback.
>
> Most important information here is that I placed additional tracepoints
> during state transitions. I needed to disable the rcu_dereference
> consistency checks to be able to get it working (not claiming that this
> is the right thing to do)
>
> diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
> index c728513..f194324 100644
> --- a/include/linux/tracepoint.h
> +++ b/include/linux/tracepoint.h
> @@ -125,7 +125,7 @@ extern void syscall_unregfunc(void);
> return; \
> prercu; \
> rcu_read_lock_sched_notrace(); \
> - it_func_ptr = rcu_dereference_sched((tp)->funcs); \
> + it_func_ptr = rcu_dereference_raw_notrace((tp)->funcs); \
> if (it_func_ptr) { \
> do { \
> it_func = (it_func_ptr)->func; \
> @@ -175,7 +175,7 @@ extern void syscall_unregfunc(void);
> TP_CONDITION(cond),,); \
> if (IS_ENABLED(CONFIG_LOCKDEP) && (cond)) { \
> rcu_read_lock_sched_notrace(); \
> - rcu_dereference_sched(__tracepoint_##name.funcs);\
> + rcu_dereference_raw_notrace(__tracepoint_##name.funcs);\
> rcu_read_unlock_sched_notrace(); \
> } \
> } \
>
>
> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> index 8523ea3..03f42b9 100644
> --- a/kernel/trace/trace_irqsoff.c
> +++ b/kernel/trace/trace_irqsoff.c
> @@ -14,6 +14,8 @@
> #include <linux/module.h>
> #include <linux/ftrace.h>
>
> +#include <trace/events/sched.h>
> +
> #include "trace.h"
>
> static struct trace_array *irqsoff_trace __read_mostly;
> @@ -433,11 +435,13 @@ void start_critical_timings(void)
> {
> if (preempt_trace() || irq_trace())
> start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
> + trace_sched_latency_critical_timing(1);
> }
> EXPORT_SYMBOL_GPL(start_critical_timings);
>
> void stop_critical_timings(void)
> {
> + trace_sched_latency_critical_timing(0);
> if (preempt_trace() || irq_trace())
> stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
> }
> @@ -447,6 +451,7 @@ EXPORT_SYMBOL_GPL(stop_critical_timings);
> #ifdef CONFIG_PROVE_LOCKING
> void time_hardirqs_on(unsigned long a0, unsigned long a1)
> {
> + trace_sched_latency_irqs(0);
> if (!preempt_trace() && irq_trace())
> stop_critical_timing(a0, a1);
> }
> @@ -455,6 +460,7 @@ void time_hardirqs_off(unsigned long a0, unsigned long a1)
> {
> if (!preempt_trace() && irq_trace())
> start_critical_timing(a0, a1);
> + trace_sched_latency_irqs(1);
> }
>
> When activating now the hist trigger by
>
> echo 'hist:key=common_pid:val=enabled' > \
> /sys/kernel/debug/tracing/events/sched/sched_latency_preempt/trigger
>
> the system crashes reliable after a very short time. Those tracepoints
> do work normally, so I see them in /sys/kernel/debug/tracing/trace.
>
> After some investigation I found out that event_hist_trigger() gets
> called with rec=NULL. This is handed over to hist_field_s32() and
> that function derefences the argument event (=NULL).
>
> #19 event_hist_trigger (data=0xffff88007934c780, rec=0x0 <irq_stack_union>) at kernel/trace/trace_events_hist.c:885
> #20 0xffffffff8113771b in event_triggers_call (file=<optimized out>, rec=0x0 <irq_stack_union>) at kernel/trace/trace_events_trigger.c:78
> #21 0xffffffff81079def in ftrace_trigger_soft_disabled (file=<optimized out>) at include/linux/ftrace_event.h:453
> #22 ftrace_raw_event_sched_latency_template (__data=0xffff88007c895aa8, enabled=0) at include/trace/events/sched.h:557
> #23 0xffffffff8112cbec in trace_sched_latency_preempt (enabled=<optimized out>) at include/trace/events/sched.h:587
> #24 trace_preempt_off (a0=18446744071579483412, a1=18446744071579485792) at kernel/trace/trace_irqsoff.c:532
> #25 0xffffffff8107f449 in preempt_count_add (val=1) at kernel/sched/core.c:2554
> #26 0xffffffff8109bd14 in get_lock_stats (class=0xffffffff82e235d0 <lock_classes+273296>) at kernel/locking/lockdep.c:249
> #27 0xffffffff8109c660 in lock_release_holdtime (hlock=0xffff880079c8ee50) at kernel/locking/lockdep.c:267
> #28 0xffffffff810a2cc9 in lock_release_holdtime (hlock=<optimized out>) at kernel/locking/lockdep.c:3464
> #29 lock_release_nested (ip=<optimized out>, lock=<optimized out>, curr=<optimized out>) at kernel/locking/lockdep.c:3481
> #30 __lock_release (ip=<optimized out>, nested=<optimized out>, lock=<optimized out>) at kernel/locking/lockdep.c:3507
> #31 lock_release (lock=0xffffffff8226e5f0 <kernfs_mutex+112>, nested=<optimized out>, ip=18446744071590106190) at kernel/locking/lockdep.c:3628
> #32 0xffffffff81abd306 in __mutex_unlock_common_slowpath (nested=<optimized out>, lock=<optimized out>) at kernel/locking/mutex.c:744
> #33 __mutex_unlock_slowpath (lock_count=0xffff88007934c780) at kernel/locking/mutex.c:769
> #34 0xffffffff81abd44e in mutex_unlock (lock=<optimized out>) at kernel/locking/mutex.c:446
> #35 0xffffffff81238e84 in kernfs_dop_revalidate (dentry=0xffff88007acede00, flags=<optimized out>) at fs/kernfs/dir.c:470
> #36 0xffffffff811c9813 in d_revalidate (flags=<optimized out>, dentry=<optimized out>) at fs/namei.c:607
> #37 lookup_fast (nd=0xffff8800790e3e48, path=0xffff8800790e3ca8, inode=0xffff8800790e3cb8) at fs/namei.c:1465
> #38 0xffffffff811cc05f in walk_component (follow=<optimized out>, path=<optimized out>, nd=<optimized out>) at fs/namei.c:1577
> #39 link_path_walk (name=0xffff880079fa602d "virtual/block/loop6/subsystem", nd=0xffff8800790e3e48) at fs/namei.c:1836
> #40 0xffffffff811cd327 in path_init (dfd=<optimized out>, name=0xffff880079fa6020 "/sys/devices/virtual/block/loop6/subsystem", flags=2051493056, nd=0xffff8800790e3e48)
> at fs/namei.c:1952
> #41 0xffffffff811cda90 in path_lookupat (dfd=<optimized out>, name=<optimized out>, flags=16448, nd=0xffff8800790e3e48) at fs/namei.c:1995
> #42 0xffffffff811cec1a in filename_lookup (dfd=-100, name=0xffff880079fa6000, flags=16384, nd=0xffff8800790e3e48) at fs/namei.c:2030
> #43 0xffffffff811d0d34 in user_path_at_empty (dfd=-100, name=<optimized out>, flags=16384, path=0xffff8800790e3f38, empty=<optimized out>) at fs/namei.c:2197
> #44 0xffffffff811c285c in SYSC_readlinkat (bufsiz=<optimized out>, buf=<optimized out>, pathname=<optimized out>, dfd=<optimized out>) at fs/stat.c:327
> #45 SyS_readlinkat (bufsiz=<optimized out>, buf=<optimized out>, pathname=<optimized out>, dfd=<optimized out>) at fs/stat.c:315
> #46 SYSC_readlink (bufsiz=<optimized out>, buf=<optimized out>, path=<optimized out>) at fs/stat.c:352
> #47 SyS_readlink (path=-131939361831040, buf=0, bufsiz=<optimized out>) at fs/stat.c:349
>
> So I am wondering if the path from ftrace_trigger_soft_disabled()
> to event_triggers_call() is supposed never to happen? The comment
> on ftrace_trigger_soft_disabled() indicate this might happen on
> normal operation:
>
So I looked at this on the plane and you're right, this is a path that
should never be taken in this case, since the hist trigger does set the
post_trigger flag and should therefore TRIGGER_COND would be true and
that block should never be entered.
However, the code that registers the trigger first enables the event,
then sets the cond flag, which would allow this to happen - a trigger
expecting data would be passed a NULL rec.
Can you try the patch below and see if it fixes the problem? (untested
and I haven't even had a chance to compile-test it..)
Tom
[PATCH] tracing: Update cond flag before enabling or disabling a trigger
Before a trigger is enabled, the cond flag should be set beforehand,
otherwise an trigger that's expecting to process a trace record
(e.g. one with post_trigger set) could be invoked without one.
Likewise a trigger's cond flag should be reset after it's disabled,
not before.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
kernel/trace/trace_events_trigger.c | 10 ++++++----
1 file changed, 6 insertions(+), 4 deletions(-)
diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
index 7105f15..108e46c 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -546,11 +546,12 @@ static int register_trigger(char *glob, struct event_trigger_ops *ops,
list_add_rcu(&data->list, &file->triggers);
ret++;
+ update_cond_flag(file);
if (trace_event_trigger_enable_disable(file, 1) < 0) {
list_del_rcu(&data->list);
+ update_cond_flag(file);
ret--;
}
- update_cond_flag(file);
out:
return ret;
}
@@ -578,8 +579,8 @@ void unregister_trigger(char *glob, struct event_trigger_ops *ops,
if (data->cmd_ops->trigger_type == test->cmd_ops->trigger_type) {
unregistered = true;
list_del_rcu(&data->list);
- update_cond_flag(file);
trace_event_trigger_enable_disable(file, 0);
+ update_cond_flag(file);
break;
}
}
@@ -1324,11 +1325,12 @@ int event_enable_register_trigger(char *glob,
list_add_rcu(&data->list, &file->triggers);
ret++;
+ update_cond_flag(file);
if (trace_event_trigger_enable_disable(file, 1) < 0) {
list_del_rcu(&data->list);
+ update_cond_flag(file);
ret--;
}
- update_cond_flag(file);
out:
return ret;
}
@@ -1351,8 +1353,8 @@ void event_enable_unregister_trigger(char *glob,
(enable_data->file == test_enable_data->file)) {
unregistered = true;
list_del_rcu(&data->list);
- update_cond_flag(file);
trace_event_trigger_enable_disable(file, 0);
+ update_cond_flag(file);
break;
}
}
--
1.9.3
> /**
> * ftrace_trigger_soft_disabled - do triggers and test if soft disabled
> * @file: The file pointer of the event to test
> *
> * If any triggers without filters are attached to this event, they
> * will be called here. If the event is soft disabled and has no
> * triggers that require testing the fields, it will return true,
> * otherwise false.
> */
> static inline bool
> ftrace_trigger_soft_disabled(struct ftrace_event_file *file)
> {
> unsigned long eflags = file->flags;
>
> if (!(eflags & FTRACE_EVENT_FL_TRIGGER_COND)) {
> if (eflags & FTRACE_EVENT_FL_TRIGGER_MODE)
> event_triggers_call(file, NULL);
> if (eflags & FTRACE_EVENT_FL_SOFT_DISABLED)
> return true;
> }
> return false;
> }
>
> cheers,
> daniel
^ permalink raw reply related [flat|nested] 13+ messages in thread* Re: [PATCH v4 0/7] tracing: 'hist' triggers
2015-04-20 22:03 ` Tom Zanussi
@ 2015-04-21 10:36 ` Daniel Wagner
2015-04-21 19:03 ` Tom Zanussi
0 siblings, 1 reply; 13+ messages in thread
From: Daniel Wagner @ 2015-04-21 10:36 UTC (permalink / raw)
To: Tom Zanussi
Cc: rostedt, masami.hiramatsu.pt, namhyung, andi, alexei.starovoitov,
linux-kernel
Hi Tom,
On 04/21/2015 12:03 AM, Tom Zanussi wrote:
> On Mon, 2015-04-20 at 14:52 +0200, Daniel Wagner wrote:
>> On 04/10/2015 06:05 PM, Tom Zanussi wrote:
>> So I am wondering if the path from ftrace_trigger_soft_disabled()
>> to event_triggers_call() is supposed never to happen? The comment
>> on ftrace_trigger_soft_disabled() indicate this might happen on
>> normal operation:
>>
>
> So I looked at this on the plane and you're right, this is a path that
> should never be taken in this case, since the hist trigger does set the
> post_trigger flag and should therefore TRIGGER_COND would be true and
> that block should never be entered.
>
> However, the code that registers the trigger first enables the event,
> then sets the cond flag, which would allow this to happen - a trigger
> expecting data would be passed a NULL rec.
>
> Can you try the patch below and see if it fixes the problem? (untested
> and I haven't even had a chance to compile-test it..)
Thanks for the explanation. With that and your patch I could get
it working. There are a couple of calling places missing in your
patch. With them it works nicely. Maybe moving update_cond_flag()
inside trace_event_trigger_enable_disable() would be an option?
cheers,
daniel
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 4d8f5df..221ab1f 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -1471,11 +1471,12 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
list_add_rcu(&data->list, &file->triggers);
ret++;
+ update_cond_flag(file);
if (trace_event_trigger_enable_disable(file, 1) < 0) {
list_del_rcu(&data->list);
+ update_cond_flag(file);
ret--;
}
- update_cond_flag(file);
out:
return ret;
}
diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
index 8c8f2ee..e47a229 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -1264,6 +1264,7 @@ int event_enable_trigger_func(struct event_command *cmd_ops,
goto out_free;
}
+ update_cond_flag(file);
ret = trace_event_enable_disable(event_enable_file, 1, 1);
if (ret < 0)
goto out_put;
@@ -1286,6 +1287,7 @@ int event_enable_trigger_func(struct event_command *cmd_ops,
out_disable:
trace_event_enable_disable(event_enable_file, 0, 1);
out_put:
+ update_cond_flag(file);
module_put(event_enable_file->event_call->mod);
out_free:
if (cmd_ops->set_filter)
> Tom
>
> [PATCH] tracing: Update cond flag before enabling or disabling a trigger
>
> Before a trigger is enabled, the cond flag should be set beforehand,
> otherwise an trigger that's expecting to process a trace record
> (e.g. one with post_trigger set) could be invoked without one.
>
> Likewise a trigger's cond flag should be reset after it's disabled,
> not before.
>
> Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> ---
> kernel/trace/trace_events_trigger.c | 10 ++++++----
> 1 file changed, 6 insertions(+), 4 deletions(-)
>
> diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
> index 7105f15..108e46c 100644
> --- a/kernel/trace/trace_events_trigger.c
> +++ b/kernel/trace/trace_events_trigger.c
> @@ -546,11 +546,12 @@ static int register_trigger(char *glob, struct event_trigger_ops *ops,
> list_add_rcu(&data->list, &file->triggers);
> ret++;
>
> + update_cond_flag(file);
> if (trace_event_trigger_enable_disable(file, 1) < 0) {
> list_del_rcu(&data->list);
> + update_cond_flag(file);
> ret--;
> }
> - update_cond_flag(file);
> out:
> return ret;
> }
> @@ -578,8 +579,8 @@ void unregister_trigger(char *glob, struct event_trigger_ops *ops,
> if (data->cmd_ops->trigger_type == test->cmd_ops->trigger_type) {
> unregistered = true;
> list_del_rcu(&data->list);
> - update_cond_flag(file);
> trace_event_trigger_enable_disable(file, 0);
> + update_cond_flag(file);
> break;
> }
> }
> @@ -1324,11 +1325,12 @@ int event_enable_register_trigger(char *glob,
> list_add_rcu(&data->list, &file->triggers);
> ret++;
>
> + update_cond_flag(file);
> if (trace_event_trigger_enable_disable(file, 1) < 0) {
> list_del_rcu(&data->list);
> + update_cond_flag(file);
> ret--;
> }
> - update_cond_flag(file);
> out:
> return ret;
> }
> @@ -1351,8 +1353,8 @@ void event_enable_unregister_trigger(char *glob,
> (enable_data->file == test_enable_data->file)) {
> unregistered = true;
> list_del_rcu(&data->list);
> - update_cond_flag(file);
> trace_event_trigger_enable_disable(file, 0);
> + update_cond_flag(file);
> break;
> }
> }
>
^ permalink raw reply related [flat|nested] 13+ messages in thread* Re: [PATCH v4 0/7] tracing: 'hist' triggers
2015-04-21 10:36 ` Daniel Wagner
@ 2015-04-21 19:03 ` Tom Zanussi
0 siblings, 0 replies; 13+ messages in thread
From: Tom Zanussi @ 2015-04-21 19:03 UTC (permalink / raw)
To: Daniel Wagner
Cc: rostedt, masami.hiramatsu.pt, namhyung, andi, alexei.starovoitov,
linux-kernel
On Tue, 2015-04-21 at 12:36 +0200, Daniel Wagner wrote:
> Hi Tom,
>
> On 04/21/2015 12:03 AM, Tom Zanussi wrote:
> > On Mon, 2015-04-20 at 14:52 +0200, Daniel Wagner wrote:
> >> On 04/10/2015 06:05 PM, Tom Zanussi wrote:
> >> So I am wondering if the path from ftrace_trigger_soft_disabled()
> >> to event_triggers_call() is supposed never to happen? The comment
> >> on ftrace_trigger_soft_disabled() indicate this might happen on
> >> normal operation:
> >>
> >
> > So I looked at this on the plane and you're right, this is a path that
> > should never be taken in this case, since the hist trigger does set the
> > post_trigger flag and should therefore TRIGGER_COND would be true and
> > that block should never be entered.
> >
> > However, the code that registers the trigger first enables the event,
> > then sets the cond flag, which would allow this to happen - a trigger
> > expecting data would be passed a NULL rec.
> >
> > Can you try the patch below and see if it fixes the problem? (untested
> > and I haven't even had a chance to compile-test it..)
>
> Thanks for the explanation. With that and your patch I could get
> it working. There are a couple of calling places missing in your
> patch. With them it works nicely. Maybe moving update_cond_flag()
> inside trace_event_trigger_enable_disable() would be an option?
>
Yeah, I guess I missed the most important bit in my haste, but glad it
works for you now. I'll write up a proper patch as soon as I can..
Thanks,
Tom
> cheers,
> daniel
>
>
> diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
> index 4d8f5df..221ab1f 100644
> --- a/kernel/trace/trace_events_hist.c
> +++ b/kernel/trace/trace_events_hist.c
> @@ -1471,11 +1471,12 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
> list_add_rcu(&data->list, &file->triggers);
> ret++;
>
> + update_cond_flag(file);
> if (trace_event_trigger_enable_disable(file, 1) < 0) {
> list_del_rcu(&data->list);
> + update_cond_flag(file);
> ret--;
> }
> - update_cond_flag(file);
> out:
> return ret;
> }
> diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
> index 8c8f2ee..e47a229 100644
> --- a/kernel/trace/trace_events_trigger.c
> +++ b/kernel/trace/trace_events_trigger.c
> @@ -1264,6 +1264,7 @@ int event_enable_trigger_func(struct event_command *cmd_ops,
> goto out_free;
> }
>
> + update_cond_flag(file);
> ret = trace_event_enable_disable(event_enable_file, 1, 1);
> if (ret < 0)
> goto out_put;
> @@ -1286,6 +1287,7 @@ int event_enable_trigger_func(struct event_command *cmd_ops,
> out_disable:
> trace_event_enable_disable(event_enable_file, 0, 1);
> out_put:
> + update_cond_flag(file);
> module_put(event_enable_file->event_call->mod);
> out_free:
> if (cmd_ops->set_filter)
>
>
>
>
> > Tom
> >
> > [PATCH] tracing: Update cond flag before enabling or disabling a trigger
> >
> > Before a trigger is enabled, the cond flag should be set beforehand,
> > otherwise an trigger that's expecting to process a trace record
> > (e.g. one with post_trigger set) could be invoked without one.
> >
> > Likewise a trigger's cond flag should be reset after it's disabled,
> > not before.
> >
> > Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> > ---
> > kernel/trace/trace_events_trigger.c | 10 ++++++----
> > 1 file changed, 6 insertions(+), 4 deletions(-)
> >
> > diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
> > index 7105f15..108e46c 100644
> > --- a/kernel/trace/trace_events_trigger.c
> > +++ b/kernel/trace/trace_events_trigger.c
> > @@ -546,11 +546,12 @@ static int register_trigger(char *glob, struct event_trigger_ops *ops,
> > list_add_rcu(&data->list, &file->triggers);
> > ret++;
> >
> > + update_cond_flag(file);
> > if (trace_event_trigger_enable_disable(file, 1) < 0) {
> > list_del_rcu(&data->list);
> > + update_cond_flag(file);
> > ret--;
> > }
> > - update_cond_flag(file);
> > out:
> > return ret;
> > }
> > @@ -578,8 +579,8 @@ void unregister_trigger(char *glob, struct event_trigger_ops *ops,
> > if (data->cmd_ops->trigger_type == test->cmd_ops->trigger_type) {
> > unregistered = true;
> > list_del_rcu(&data->list);
> > - update_cond_flag(file);
> > trace_event_trigger_enable_disable(file, 0);
> > + update_cond_flag(file);
> > break;
> > }
> > }
> > @@ -1324,11 +1325,12 @@ int event_enable_register_trigger(char *glob,
> > list_add_rcu(&data->list, &file->triggers);
> > ret++;
> >
> > + update_cond_flag(file);
> > if (trace_event_trigger_enable_disable(file, 1) < 0) {
> > list_del_rcu(&data->list);
> > + update_cond_flag(file);
> > ret--;
> > }
> > - update_cond_flag(file);
> > out:
> > return ret;
> > }
> > @@ -1351,8 +1353,8 @@ void event_enable_unregister_trigger(char *glob,
> > (enable_data->file == test_enable_data->file)) {
> > unregistered = true;
> > list_del_rcu(&data->list);
> > - update_cond_flag(file);
> > trace_event_trigger_enable_disable(file, 0);
> > + update_cond_flag(file);
> > break;
> > }
> > }
> >
^ permalink raw reply [flat|nested] 13+ messages in thread