[PATCH v5 00/10] tracing: 'hist' triggers

[PATCH v5 00/10] tracing: 'hist' triggers

[Tom Zanussi]

This is v5 of the 'hist triggers' patchset, following feedback from
v4.

Changes from v4:

This version addresses some problems and suggestions made by Daniel
Wagner - a lot of the code was reworked to get rid of the distinction
between keys and values, and as a result, both keys and values can be
used as sort keys.  As suggested, it also allows 'val=' to be absent
in a trigger command - if no 'val' is specified, hitcount is assumed
and automatically used as the only val.

The map code was also separated out into a separate file,
tracing_map.c, allowing it to be reused.  It also adds a second tracer
called function_hist that actually does reuse the code, as an RFC
patch.

Patch 01/10 [tracing: Update cond flag when enabling or disabling..]
is a fix for a problem noticed by Daniel and that fixes a problem in
existing trigger code and should be applied regardless of whether the
rest of the patchset is merged.

As mentioned, patch 10/10 is an RFC patch implementing a new tracer
based on the function tracer code.  It's a fun little tool and is
useful for a specific problem I'm working on (and is also a nice test
of the tracing_map code), but is an RFC because first, I'm not sure it
would really be of general interest and secondly, it's POC-level
quality and I'd need to spend more time fixing it up to make it
upstreamable, but I don't want to waste my time if not.

There are a couple of important bits of functionality that were
present in v1 but not yet reimplemented in v5.

The first is support for compound keys.  Currently, maps can only be
keyed on a single event field, whereas in v1 they could be keyed on
multiple keys.  With support for compound keys, you can create much
more interesting output, such as for example per-pid lists of
syscalls or read counts e.g.:

  # echo 'hist:keys=common_pid.execname,id.syscall:vals=hitcount' > \
        /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger

  # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist

  key: common_pid:bash[3112], id:sys_write		       vals: count:69
  key: common_pid:bash[3112], id:sys_rt_sigprocmask	       vals: count:218

  key: common_pid:update-notifier[3164], id:sys_poll	       vals: count:37
  key: common_pid:update-notifier[3164], id:sys_recvfrom       vals: count:118

  key: common_pid:deja-dup-monito[3194], id:sys_sendto	       vals: count:1
  key: common_pid:deja-dup-monito[3194], id:sys_read	       vals: count:4
  key: common_pid:deja-dup-monito[3194], id:sys_poll	       vals: count:8
  key: common_pid:deja-dup-monito[3194], id:sys_recvmsg	       vals: count:8
  key: common_pid:deja-dup-monito[3194], id:sys_getegid	       vals: count:8

  key: common_pid:emacs[3275], id:sys_fsync		       vals: count:1
  key: common_pid:emacs[3275], id:sys_open		       vals: count:1
  key: common_pid:emacs[3275], id:sys_symlink		       vals: count:2
  key: common_pid:emacs[3275], id:sys_poll		       vals: count:23
  key: common_pid:emacs[3275], id:sys_select		       vals: count:23
  key: common_pid:emacs[3275], id:unknown_syscall	       vals: count:34
  key: common_pid:emacs[3275], id:sys_ioctl		       vals: count:60
  key: common_pid:emacs[3275], id:sys_rt_sigprocmask	       vals: count:116

  key: common_pid:cat[3323], id:sys_munmap		       vals: count:1
  key: common_pid:cat[3323], id:sys_fadvise64		       vals: count:1

Related to that is support for sorting on multiple fields.  Currently,
you can sort using only a primary key.  Being able to sort on multiple
or at least a secondary key is indispensible for seeing trends when
displaying multiple values.

Changes from v3:

v4 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.

It was also pointed out that it didn't seem correct to include
module.h, but the fix for that has deeper roots and is being addressed
by a separate patchset; for now we need to continue including
module.h, though prompted by that I did some other header include
cleanup.

The functionality remains the same as v2, but this version no longer
tries to export and use bpf_maps, and more importantly removes the
associated GFP_NOTRACE/trace event hacks and kmem macros required to
work around the bpf_map implementation.

The tracing_map functionality is instead built on top of a simple
lock-free map algorithm originated by Dr. Cliff Click (see references
in the code for more details), which though too restrictive to be
general-purpose in its current form, functions nicely as a
special-purpose tracing map.

v3 also moves the hist triggers code into a separate file and puts it
all behind a new config option, CONFIG_HIST_TRIGGERS.  It also merges
in the sorting code rather than keeping it as a separate patch.

This patchset also includes a couple other new and related triggers,
enable_hist and disable_hist, very similar to the existing
enable_event/disable_event triggers used to automatically enable and
disable events based on a triggering condition, but in this case
allowing hist triggers to be enabled and disabled in the same way.

 - Added an insert check for val before checking the key associated with val
 - Added code to merge possible duplicates in the map

Changes from v2:
 - reimplemented tracing_map, replacing bpf_map with nmi-safe/lock-free map
 - removed GPF_NOTRACE, kmalloc/free macros and event hacks needed by bpf_maps
 - moved hist triggers from trace_events_trigger.c to trace_events_hist.c
 - added CONFIG_HIST_TRIGGERS config option
 - consolidated sorting code with main patch

Changes from v1:
 - completely rewritten on top of tracing_map (renamed and exported bpf_map)
 - added map clearing and client ops to tracing_map
 - changed the name from 'hash' triggers to 'hist' triggers
 - added new trigger 'pause' feature
 - added new enable_hist and disable_hist triggers
 - added usage for hist/enable_hist/disable hist to tracing/README
 - moved examples into Documentation/trace/event.txt
 - added ___GFP_NOTRACE, kmalloc/kfree macros, and conditional kmem tracepoints

The following changes since commit f267caab44451baa70d25fa3191a68bb79ad1b08:

  tracing: Remove unused prototype ftrace_event_define_field() (2015-05-13 14:03:51 -0400)

are available in the git repository at:

  git://git.yoctoproject.org/linux-yocto-contrib.git tzanussi/hist-triggers-v5
  http://git.yoctoproject.org/cgit/cgit.cgi/linux-yocto-contrib/log/?h=tzanussi/hist-triggers-v5

Tom Zanussi (10):
  tracing: Update cond flag when enabling or disabling a trigger
  tracing: Make ftrace_event_field checking functions available
  tracing: Add event record param to trigger_ops.func()
  tracing: Add get_syscall_name()
  tracing: Add a per-event-trigger 'paused' field
  trace: Add lock-free tracing_map
  tracing: Add 'hist' event trigger command
  tracing: Add enable_hist/disable_hist triggers
  tracing: Add 'hist' trigger Documentation
  ftrace: Add function_hist tracer

 Documentation/trace/events.txt      |  872 ++++++++++++++++++++++++
 include/linux/ftrace_event.h        |    9 +-
 kernel/trace/Kconfig                |   14 +
 kernel/trace/Makefile               |    3 +
 kernel/trace/trace.c                |   58 ++
 kernel/trace/trace.h                |   88 ++-
 kernel/trace/trace_events.c         |    4 +
 kernel/trace/trace_events_filter.c  |   12 -
 kernel/trace/trace_events_hist.c    | 1238 +++++++++++++++++++++++++++++++++++
 kernel/trace/trace_events_trigger.c |  149 +++--
 kernel/trace/trace_functions_hist.c |  345 ++++++++++
 kernel/trace/trace_syscalls.c       |   11 +
 kernel/trace/tracing_map.c          |  831 +++++++++++++++++++++++
 kernel/trace/tracing_map.h          |  133 ++++
 14 files changed, 3683 insertions(+), 84 deletions(-)
 create mode 100644 kernel/trace/trace_events_hist.c
 create mode 100644 kernel/trace/trace_functions_hist.c
 create mode 100644 kernel/trace/tracing_map.c
 create mode 100644 kernel/trace/tracing_map.h

-- 
1.9.3

[PATCH 01/10] tracing: Update cond flag when enabling or disabling a trigger

[Tom Zanussi]

When a trigger is enabled, the cond flag should be set beforehand,
otherwise a 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>
Signed-off-by: Daniel Wagner <daniel.wagner@bmw-carit.de>
---
 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 8712df9..51e2664 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -543,11 +543,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;
 }
@@ -575,8 +576,8 @@ static 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;
 		}
 	}
@@ -1319,11 +1320,12 @@ static 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;
 }
@@ -1344,8 +1346,8 @@ static 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

[PATCH v5 02/10] tracing: Make ftrace_event_field checking functions available

[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 d261201..3c557b3 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

[PATCH v5 03/10] tracing: Add event record param to trigger_ops.func()

[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 f8465d6..c4c16ed 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -423,7 +423,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
@@ -506,7 +507,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);
 }
 
 /**
@@ -539,7 +540,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);
 }
 
 #ifdef CONFIG_BPF_SYSCALL
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 3c557b3..6935bf5 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 51e2664..c8feeb7 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);
@@ -752,7 +753,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;
@@ -761,7 +762,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;
@@ -776,7 +777,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;
@@ -785,7 +786,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;
@@ -881,13 +882,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;
@@ -895,7 +896,7 @@ snapshot_count_trigger(struct event_trigger_data *data)
 	if (data->count != -1)
 		(data->count)--;
 
-	snapshot_trigger(data);
+	snapshot_trigger(data, rec);
 }
 
 static int
@@ -974,13 +975,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;
@@ -988,7 +989,7 @@ stacktrace_count_trigger(struct event_trigger_data *data)
 	if (data->count != -1)
 		(data->count)--;
 
-	stacktrace_trigger(data);
+	stacktrace_trigger(data, rec);
 }
 
 static int
@@ -1059,7 +1060,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;
 
@@ -1070,7 +1071,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;
 
@@ -1084,7 +1085,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

[PATCH v5 04/10] tracing: Add get_syscall_name()

[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 6935bf5..46555ba 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

[PATCH v5 05/10] tracing: Add a per-event-trigger 'paused' field

[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 46555ba..56fd2db 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 c8feeb7..9438abc 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

[PATCH v5 06/10] trace: Add lock-free tracing_map

[Tom Zanussi]

Add tracing_map, a special-purpose lock-free map for tracing.

tracing_map is designed to aggregate or 'sum' one or more values
associated with a specific object of type tracing_map_elt, which
is associated by the map to a given key.

It provides various hooks allowing per-tracer customization and is
separated out into a separate file in order to allow it to be shared
between multiple tracers, but isn't meant to be generally used outside
of that context.

The tracing_map implementation was inspired by lock-free map
algorithms originated by Dr. Cliff Click:

 http://www.azulsystems.com/blog/cliff/2007-03-26-non-blocking-hashtable
 http://www.azulsystems.com/events/javaone_2007/2007_LockFreeHash.pdf

Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
 kernel/trace/Makefile      |   1 +
 kernel/trace/tracing_map.c | 831 +++++++++++++++++++++++++++++++++++++++++++++
 kernel/trace/tracing_map.h | 133 ++++++++
 3 files changed, 965 insertions(+)
 create mode 100644 kernel/trace/tracing_map.c
 create mode 100644 kernel/trace/tracing_map.h

diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 9b1044e..3b26cfb 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -31,6 +31,7 @@ obj-$(CONFIG_TRACING) += trace_output.o
 obj-$(CONFIG_TRACING) += trace_seq.o
 obj-$(CONFIG_TRACING) += trace_stat.o
 obj-$(CONFIG_TRACING) += trace_printk.o
+obj-$(CONFIG_TRACING) += tracing_map.o
 obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o
 obj-$(CONFIG_FUNCTION_TRACER) += trace_functions.o
 obj-$(CONFIG_IRQSOFF_TRACER) += trace_irqsoff.o
diff --git a/kernel/trace/tracing_map.c b/kernel/trace/tracing_map.c
new file mode 100644
index 0000000..cdbf377
--- /dev/null
+++ b/kernel/trace/tracing_map.c
@@ -0,0 +1,831 @@
+/*
+ * tracing_map - lock-free map for tracing
+ *
+ * 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/slab.h>
+#include <linux/jhash.h>
+#include <linux/sort.h>
+
+#include "tracing_map.h"
+#include "trace.h"
+
+/**
+ * tracing_map_update_sum - Add a value to a tracing_map_elt's sum
+ * @elt: The tracing_map_elt
+ * @i: The index of the given sum associated with the tracing_map_elt
+ * @n: The value to add to the sum
+ *
+ * Add n to sum i associated with the specified tracing_map_elt
+ * instance.  The index i is the index returned by the call to
+ * tracing_map_add_sum_field() when the tracing map was set up.
+ */
+void tracing_map_update_sum(struct tracing_map_elt *elt, unsigned int i, u64 n)
+{
+	atomic64_add(n, &elt->fields[i].sum);
+}
+
+/**
+ * tracing_map_read_sum - Return the value of a tracing_map_elt's sum
+ * @elt: The tracing_map_elt
+ * @i: The index of the given sum associated with the tracing_map_elt
+ *
+ * Retrieve the value of the sum i associated with the specified
+ * tracing_map_elt instance.  The index i is the index returned by the
+ * call to tracing_map_add_sum_field() when the tracing map was set
+ * up.
+ *
+ * Return: The sum associated with field i for elt.
+ */
+u64 tracing_map_read_sum(struct tracing_map_elt *elt, unsigned int i)
+{
+	return (u64)atomic64_read(&elt->fields[i].sum);
+}
+
+int tracing_map_cmp_string(void *val_a, void *val_b)
+{
+	char *a = val_a;
+	char *b = val_b;
+
+	return strcmp(a, b);
+}
+
+int tracing_map_cmp_none(void *val_a, void *val_b)
+{
+	return 0;
+}
+
+static int tracing_map_cmp_atomic64(void *val_a, void *val_b)
+{
+	u64 a = atomic64_read((atomic64_t *)val_a);
+	u64 b = atomic64_read((atomic64_t *)val_b);
+
+	return (a > b) ? 1 : ((a < b) ? -1 : 0);
+}
+
+#define DEFINE_TRACING_MAP_CMP_FN(type)					\
+static int tracing_map_cmp_##type(void *val_a, void *val_b)		\
+{									\
+	type a = *(type *)val_a;					\
+	type b = *(type *)val_b;					\
+									\
+	return (a > b) ? 1 : ((a < b) ? -1 : 0);			\
+}
+
+DEFINE_TRACING_MAP_CMP_FN(s64);
+DEFINE_TRACING_MAP_CMP_FN(u64);
+DEFINE_TRACING_MAP_CMP_FN(s32);
+DEFINE_TRACING_MAP_CMP_FN(u32);
+DEFINE_TRACING_MAP_CMP_FN(s16);
+DEFINE_TRACING_MAP_CMP_FN(u16);
+DEFINE_TRACING_MAP_CMP_FN(s8);
+DEFINE_TRACING_MAP_CMP_FN(u8);
+
+tracing_map_cmp_fn_t tracing_map_cmp_num(int field_size,
+					 int field_is_signed)
+{
+	tracing_map_cmp_fn_t fn = tracing_map_cmp_none;
+
+	switch (field_size) {
+	case 8:
+		if (field_is_signed)
+			fn = tracing_map_cmp_s64;
+		else
+			fn = tracing_map_cmp_u64;
+		break;
+	case 4:
+		if (field_is_signed)
+			fn = tracing_map_cmp_s32;
+		else
+			fn = tracing_map_cmp_u32;
+		break;
+	case 2:
+		if (field_is_signed)
+			fn = tracing_map_cmp_s16;
+		else
+			fn = tracing_map_cmp_u16;
+		break;
+	case 1:
+		if (field_is_signed)
+			fn = tracing_map_cmp_s8;
+		else
+			fn = tracing_map_cmp_u8;
+		break;
+	}
+
+	return fn;
+}
+
+static int tracing_map_add_field(struct tracing_map *map,
+				 tracing_map_cmp_fn_t cmp_fn)
+{
+	int ret = -EINVAL;
+
+	if (map->n_fields < TRACING_MAP_FIELDS_MAX) {
+		ret = map->n_fields;
+		map->field_descr[map->n_fields++].cmp_fn = cmp_fn;
+	}
+
+	return ret;
+}
+
+/**
+ * tracing_map_add_sum_field - Add a field describing a tracing_map sum
+ * @map: The tracing_map
+ *
+ * Add a sum field to the key and return the index identifying it in
+ * the map and associated tracing_map_elts.  This is the index used
+ * for instance to update a sum for a particular tracing_map_elt using
+ * tracing_map_update_sum() or reading it via tracing_map_read_sum().
+ *
+ * Return: The index identifying the field in the map and associated
+ * tracing_map_elts.
+ */
+int tracing_map_add_sum_field(struct tracing_map *map)
+{
+	return tracing_map_add_field(map, tracing_map_cmp_atomic64);
+}
+
+/**
+ * tracing_map_add_key_field - Add a field describing the tracing_map key
+ * @map: The tracing_map
+ * @cmp_fn: The comparison function that will be used to sort on the key
+ *
+ * Let the map know there is a key and that if it's used as a sort key
+ * to use cmp_fn.
+ *
+ * Return: The index identifying the field in the map and associated
+ * tracing_map_elts.
+ */
+int tracing_map_add_key_field(struct tracing_map *map,
+			      tracing_map_cmp_fn_t cmp_fn)
+{
+	int idx = tracing_map_add_field(map, cmp_fn);
+
+	if (idx < 0)
+		return idx;
+
+	map->key_idx = idx;
+
+	return idx;
+}
+
+static void tracing_map_elt_clear(struct tracing_map_elt *elt)
+{
+	unsigned i;
+
+	for (i = 0; i < elt->map->n_fields; i++)
+		atomic64_set(&elt->fields[i].sum, 0);
+
+	if (elt->map->ops && elt->map->ops->elt_clear)
+		elt->map->ops->elt_clear(elt);
+}
+
+static void tracing_map_elt_init_fields(struct tracing_map_elt *elt)
+{
+	unsigned int i;
+
+	tracing_map_elt_clear(elt);
+
+	for (i = 0; i < elt->map->n_fields; i++)
+		elt->fields[i].cmp_fn = elt->map->field_descr[i].cmp_fn;
+}
+
+static void tracing_map_elt_free(struct tracing_map_elt *elt)
+{
+	if (!elt)
+		return;
+
+	if (elt->map->ops && elt->map->ops->elt_free)
+		elt->map->ops->elt_free(elt);
+	kfree(elt->fields);
+	kfree(elt->key);
+	kfree(elt);
+}
+
+static struct tracing_map_elt *tracing_map_elt_alloc(struct tracing_map *map)
+{
+	struct tracing_map_elt *elt;
+	int err = 0;
+
+	elt = kzalloc(sizeof(*elt), GFP_KERNEL);
+	if (!elt)
+		return ERR_PTR(-ENOMEM);
+
+	elt->map = map;
+
+	elt->key = kzalloc(map->key_size, GFP_KERNEL);
+	if (!elt->key) {
+		err = -ENOMEM;
+		goto free;
+	}
+
+	elt->fields = kcalloc(map->n_fields, sizeof(*elt->fields), GFP_KERNEL);
+	if (!elt->fields) {
+		err = -ENOMEM;
+		goto free;
+	}
+
+	tracing_map_elt_init_fields(elt);
+
+	if (map->ops && map->ops->elt_alloc) {
+		err = map->ops->elt_alloc(elt);
+		if (err)
+			goto free;
+	}
+	return elt;
+ free:
+	tracing_map_elt_free(elt);
+
+	return ERR_PTR(err);
+}
+
+static struct tracing_map_elt *get_free_elt(struct tracing_map *map)
+{
+	struct tracing_map_elt *elt = NULL;
+	int idx;
+
+	idx = atomic_inc_return(&map->next_elt);
+	if (idx < map->max_elts) {
+		elt = map->elts[idx];
+		if (map->ops && map->ops->elt_init)
+			map->ops->elt_init(elt);
+	}
+
+	return elt;
+}
+
+static void tracing_map_free_elts(struct tracing_map *map)
+{
+	unsigned int i;
+
+	if (!map->elts)
+		return;
+
+	for (i = 0; i < map->max_elts; i++)
+		tracing_map_elt_free(map->elts[i]);
+
+	kfree(map->elts);
+}
+
+static int tracing_map_alloc_elts(struct tracing_map *map)
+{
+	unsigned int i;
+
+	map->elts = kcalloc(map->max_elts, sizeof(struct tracing_map_elt *),
+			    GFP_KERNEL);
+	if (!map->elts)
+		return -ENOMEM;
+
+	for (i = 0; i < map->max_elts; i++) {
+		map->elts[i] = tracing_map_elt_alloc(map);
+		if (!map->elts[i]) {
+			tracing_map_free_elts(map);
+
+			return -ENOMEM;
+		}
+	}
+
+	return 0;
+}
+
+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
+ * tracing_map_elt for it, or if the key has already been inserted by
+ * a previous call, returns the tracing_map_elt already associated
+ * with it.  When the map was created, the number of elements to be
+ * allocated for the map was specified, and that number of
+ * tracing_map_elts was created by tracing_map_init().  This is the
+ * pre-allocated pool of tracing map element 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 tracing_map_elt * val associated with the key.  If this
+ * was a newly inserted key, the val will be a newly allocated and
+ * associated tracing_map_elt * val.  If the key wasn't found and the
+ * pool of tracing_map_elts has been exhausted, NULL is returned and
+ * no further insertions will succeed.
+ */
+struct tracing_map_elt *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 tracing_map_elt *elt;
+
+			elt = get_free_elt(map);
+			if (!elt)
+				break;
+			memcpy(elt->key, key, map->key_size);
+			map->map[idx].val = elt;
+
+			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
+ * tracing_map_elts.
+ *
+ * Callers should make sure there are no readers or writers actively
+ * reading or inserting into the map before calling this.
+ */
+void tracing_map_destroy(struct tracing_map *map)
+{
+	if (!map)
+		return;
+
+	tracing_map_free_elts(map);
+
+	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_elts are all cleared, and the array of
+ * tracing_map_entries are reset to an initialized state.
+ *
+ * Callers should make sure there are no writers actively inserting
+ * into the map before calling this.
+ */
+void tracing_map_clear(struct tracing_map *map)
+{
+	unsigned int i, size;
+
+	atomic_set(&map->next_elt, -1);
+
+	size = map->map_size * sizeof(struct tracing_map_entry);
+	memset(map->map, 0, size);
+
+	for (i = 0; i < map->max_elts; i++)
+		tracing_map_elt_clear(map->elts[i]);
+}
+
+static void set_sort_key(struct tracing_map *map,
+			 struct tracing_map_sort_key *sort_key)
+{
+	map->sort_key = *sort_key;
+}
+
+/**
+ * tracing_map_create - Create a lock-free map and hist element pool
+ * @map_bits: The size of the map (2 ** map_bits)
+ * @key_size: The size of the key for the map in bytes
+ * @ops: Optional client-defined tracing_map_ops instance
+ * @private_data: Client data associated with the map
+ *
+ * Creates and sets up a map to contain a max_size number of entries
+ * equal to a size of 2 ** map_bits.  Before using, the map fields
+ * should be added to the map with tracing_map_add_sum_field() and
+ * tracing_map_add_key_field().  tracing_map_init() should then be
+ * called to allocate the array of tracing_map_elts, in order to avoid
+ * allocating anything in the map insertion path.  The user-specified
+ * map_size reflect the max number of entries requested by the user -
+ * internally we double that in order to keep the table sparse and
+ * keep collisions manageable.
+ *
+ * A tracing_map is a special-purpose map designed to aggregate or
+ * 'sum' one or more values associated with a specific object of type
+ * tracing_map_elt, which is attached by the map to a given key.
+ *
+ * tracing_map_create() sets up the map itself, and provides
+ * operations for inserting tracing_map_elts, but doesn't allocate the
+ * tracing_map_elts themselves, or provide a means for describing the
+ * keys or sums associated with the tracing_map_elts.  All
+ * tracing_map_elts for a given map have the same set of sums and
+ * keys, which are defined by the client using the functions
+ * tracing_map_add_key_field() and tracing_map_add_sum_field().
+ * Currently a tracing map can only have one key field i.e. compound
+ * keys aren't yet supported.  Once the fields are defined, the pool
+ * of elements allocated for the map can be created, which occurs when
+ * the client code calls tracing_map_init().
+ *
+ * When tracing_map_init() returns, tracing_map_elt elements can be
+ * inserted into the map using tracing_map_insert().  When called,
+ * tracing_map_insert() grabs a free tracing_map_elt from the pool, or
+ * finds an existing match in the map and in either case returns it.
+ * The client can then use tracing_map_update_sum() and
+ * tracing_map_read_sum() to update or read a given sum field for the
+ * tracing_map_elt.
+ *
+ * The client can at any point retrieve and traverse the map and
+ * the set of inserted tracing_map_elts via tracing_map_sort_entries().
+ * Sorting can be done on any field, including the key.
+ *
+ * See tracing_map.h for a description of tracing_map_ops.
+ *
+ * Return: the tracing_map * if successful, ERR_PTR if not.
+ */
+struct tracing_map *tracing_map_create(unsigned int map_bits,
+				       unsigned int key_size,
+				       struct tracing_map_ops *ops,
+				       void *private_data)
+{
+	struct tracing_map *map;
+
+	if (map_bits < TRACING_MAP_BITS_MIN ||
+	    map_bits > TRACING_MAP_BITS_MAX)
+		return ERR_PTR(-EINVAL);
+
+	map = kzalloc(sizeof(*map), GFP_KERNEL);
+	if (!map)
+		return ERR_PTR(-ENOMEM);
+
+	map->map_bits = map_bits;
+	map->max_elts = (1 << map_bits);
+	atomic_set(&map->next_elt, -1);
+
+	map->map_size = (1 << (map_bits + 1));
+	map->ops = ops;
+
+	map->private_data = private_data;
+
+	map->map = kcalloc(map->map_size, sizeof(struct tracing_map_entry),
+			   GFP_KERNEL);
+	if (!map->map)
+		goto free;
+
+	map->key_size = key_size;
+ out:
+	return map;
+ free:
+	tracing_map_destroy(map);
+	map = ERR_PTR(-ENOMEM);
+
+	goto out;
+}
+
+/**
+ * tracing_map_init - Allocate and clear a map's tracing_map_elts
+ * @map: The tracing_map to initialize
+ *
+ * Creates and sets up a map to contain a max_size number of entries
+ * equal to a size of 2 ** map_bits.  Before using, the map fields
+ * should be added to the map with tracing_map_add_key_field() and
+ * tracing_map_add_key_field().  tracing_map_init() should then be
+ * called to allocate the array of tracing_map_elts, in order to avoid
+ * allocating anything in the map insertion path.  The user-specified
+ * map_size reflect the max number of entries requested by the user -
+ * internally we double that in order to keep the table sparse and
+ * keep collisions manageable.
+ *
+ * See tracing_map.h for a description of tracing_map_ops.
+ *
+ * Return: the tracing_map * if successful, ERR_PTR if not.
+ */
+int tracing_map_init(struct tracing_map *map)
+{
+	int err;
+
+	if (map->n_fields < 2)
+		return -EINVAL; /* need at least 1 key and 1 val */
+
+	err = tracing_map_alloc_elts(map);
+	if (err)
+		return err;
+
+	tracing_map_clear(map);
+
+	return err;
+}
+
+static int cmp_entries_dup(const struct tracing_map_sort_entry **a,
+			   const struct tracing_map_sort_entry **b)
+{
+	int ret = 0;
+
+	if (memcmp((*a)->key, (*b)->key, (*a)->elt->map->key_size))
+		ret = 1;
+
+	return ret;
+}
+
+static int cmp_entries_sum(const struct tracing_map_sort_entry **a,
+			   const struct tracing_map_sort_entry **b)
+{
+	const struct tracing_map_elt *elt_a, *elt_b;
+	struct tracing_map_sort_key *sort_key;
+	struct tracing_map_field *field;
+	tracing_map_cmp_fn_t cmp_fn;
+	void *val_a, *val_b;
+	int ret = 0;
+
+	elt_a = (*a)->elt;
+	elt_b = (*b)->elt;
+
+	sort_key = &elt_a->map->sort_key;
+
+	field = &elt_a->fields[sort_key->idx];
+	cmp_fn = field->cmp_fn;
+
+	val_a = &elt_a->fields[sort_key->idx].sum;
+	val_b = &elt_b->fields[sort_key->idx].sum;
+
+	ret = cmp_fn(val_a, val_b);
+	if (sort_key->descending)
+		ret = -ret;
+
+	return ret;
+}
+
+static int cmp_entries_key(const struct tracing_map_sort_entry **a,
+			   const struct tracing_map_sort_entry **b)
+{
+	const struct tracing_map_elt *elt_a, *elt_b;
+	struct tracing_map_sort_key *sort_key;
+	struct tracing_map_field *field;
+	tracing_map_cmp_fn_t cmp_fn;
+	void *val_a, *val_b;
+	int ret = 0;
+
+	elt_a = (*a)->elt;
+	elt_b = (*b)->elt;
+
+	sort_key = &elt_a->map->sort_key;
+
+	field = &elt_a->fields[sort_key->idx];
+	cmp_fn = field->cmp_fn;
+
+	val_a = elt_a->key;
+	val_b = elt_b->key;
+
+	ret = cmp_fn(val_a, val_b);
+	if (sort_key->descending)
+		ret = -ret;
+
+	return ret;
+}
+
+static void destroy_sort_entry(struct tracing_map_sort_entry *entry)
+{
+	if (!entry)
+		return;
+
+	if (entry->elt_copied)
+		tracing_map_elt_free(entry->elt);
+
+	kfree(entry);
+}
+
+/**
+ * tracing_map_destroy_entries - Destroy a tracing_map_sort_entries() array
+ * @entries: The entries to destroy
+ * @n_entries: The number of entries in the array
+ *
+ * Destroy the elements returned by a tracing_map_sort_entries() call.
+ */
+void tracing_map_destroy_sort_entries(struct tracing_map_sort_entry **entries,
+				      unsigned int n_entries)
+{
+	unsigned int i;
+
+	for (i = 0; i < n_entries; i++)
+		destroy_sort_entry(entries[i]);
+}
+
+static struct tracing_map_sort_entry *
+create_sort_entry(void *key, struct tracing_map_elt *elt)
+{
+	struct tracing_map_sort_entry *sort_entry;
+
+	sort_entry = kzalloc(sizeof(*sort_entry), GFP_KERNEL);
+	if (!sort_entry)
+		return NULL;
+
+	sort_entry->key = key;
+	sort_entry->elt = elt;
+
+	return sort_entry;
+}
+
+static struct tracing_map_elt *copy_elt(struct tracing_map_elt *elt)
+{
+	struct tracing_map_elt *dup_elt;
+	unsigned int i;
+
+	dup_elt = tracing_map_elt_alloc(elt->map);
+	if (!dup_elt)
+		return NULL;
+
+	if (elt->map->ops && elt->map->ops->elt_copy)
+		elt->map->ops->elt_copy(dup_elt, elt);
+
+	dup_elt->private_data = elt->private_data;
+	memcpy(dup_elt->key, elt->key, elt->map->key_size);
+
+	for (i = 0; i < elt->map->n_fields; i++) {
+		atomic64_set(&dup_elt->fields[i].sum,
+			     atomic64_read(&elt->fields[i].sum));
+		dup_elt->fields[i].cmp_fn = elt->fields[i].cmp_fn;
+	}
+
+	return dup_elt;
+}
+
+static int merge_dup(struct tracing_map_sort_entry **sort_entries,
+		     unsigned int target, unsigned int dup)
+{
+	struct tracing_map_elt *target_elt, *elt;
+	bool first_dup = (target - dup) == 1;
+	int i;
+
+	if (first_dup) {
+		elt = sort_entries[target]->elt;
+		target_elt = copy_elt(elt);
+		if (!target_elt)
+			return -ENOMEM;
+		sort_entries[target]->elt = target_elt;
+		sort_entries[target]->elt_copied = true;
+	} else
+		target_elt = sort_entries[target]->elt;
+
+	elt = sort_entries[dup]->elt;
+
+	for (i = 0; i < elt->map->n_fields; i++)
+		atomic64_add(atomic64_read(&elt->fields[i].sum),
+			     &target_elt->fields[i].sum);
+
+	sort_entries[dup]->dup = true;
+
+	return 0;
+}
+
+static int merge_dups(struct tracing_map_sort_entry **sort_entries,
+		      int n_entries, unsigned int key_size)
+{
+	unsigned int dups = 0, total_dups = 0;
+	int err, i, j;
+	void *key;
+
+	if (n_entries < 2)
+		return total_dups;
+
+	sort(sort_entries, n_entries, sizeof(struct tracing_map_sort_entry *),
+	     (int (*)(const void *, const void *))cmp_entries_dup, NULL);
+
+	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;
+}
+
+/**
+ * tracing_map_sort_entries - Sort the current set of tracing_map_lts in a map
+ * @map: The tracing_map
+ * @sort_key: The sort key to use for sorting
+ * @sort_entries: outval: pointer to allocated and sorted array of entries
+ *
+ * tracing_map_sort_entries() sorts the current set of entries in the
+ * map and returns the list of tracing_map_sort_entries containing
+ * them to the client in the sort_entries param.
+ *
+ * The sort_key has only two fields: idx and descending.  'idx' refers
+ * to the index of the field added via tracing_map_add_sum_field() or
+ * tracing_map_add_key_field() when the tracing_map was initialized.
+ * 'descending' is a flag that if set reverses the sort order, which
+ * by default is ascending.
+ *
+ * The client should not hold on to the returned array but use it
+ * and call tracing_map_destroy_sort_entries() when done.
+ *
+ * Return: the number of sort_entries in the tracing_map_sort_entry
+ * array, negative on err
+ */
+int tracing_map_sort_entries(struct tracing_map *map,
+			     struct tracing_map_sort_key *sort_key,
+			     struct tracing_map_sort_entry ***sort_entries)
+{
+	int (*cmp_entries_fn)(const struct tracing_map_sort_entry **,
+			      const struct tracing_map_sort_entry **);
+	struct tracing_map_sort_entry *sort_entry, **entries;
+	int i, j, n_entries, ret;
+
+	set_sort_key(map, sort_key);
+
+	entries = kcalloc(map->max_elts, sizeof(sort_entry), GFP_KERNEL);
+	if (!entries)
+		return -ENOMEM;
+
+	for (i = 0, j = 0; i < map->map_size; i++) {
+		if (!map->map[i].key || !map->map[i].val)
+			continue;
+
+		entries[j] = create_sort_entry(map->map[i].val->key,
+					       map->map[i].val);
+		if (!entries[j++]) {
+			ret = -ENOMEM;
+			n_entries = j;
+			goto free;
+		}
+	}
+	n_entries = j;
+
+	ret = merge_dups(entries, n_entries, map->key_size);
+	if (ret < 0)
+		goto free;
+	n_entries -= ret;
+
+	if (sort_key->idx == map->key_idx)
+		cmp_entries_fn = cmp_entries_key;
+	else
+		cmp_entries_fn = cmp_entries_sum;
+
+	sort(entries, n_entries, sizeof(struct hist_trigger_entry *),
+	     (int (*)(const void *, const void *))cmp_entries_fn, NULL);
+
+	*sort_entries = entries;
+
+	return n_entries;
+ free:
+	tracing_map_destroy_sort_entries(entries, n_entries);
+
+	return ret;
+}
diff --git a/kernel/trace/tracing_map.h b/kernel/trace/tracing_map.h
new file mode 100644
index 0000000..e60e3e7
--- /dev/null
+++ b/kernel/trace/tracing_map.h
@@ -0,0 +1,133 @@
+#ifndef __TRACING_MAP_H
+#define __TRACING_MAP_H
+
+#define TRACING_MAP_BITS_DEFAULT	11
+#define TRACING_MAP_BITS_MAX		17
+#define TRACING_MAP_BITS_MIN		7
+
+#define TRACING_MAP_FIELDS_MAX		4
+
+typedef int (*tracing_map_cmp_fn_t) (void *val_a, void *val_b);
+
+struct tracing_map_field {
+	tracing_map_cmp_fn_t		cmp_fn;
+	atomic64_t			sum;
+};
+
+struct tracing_map_elt {
+	struct tracing_map		*map;
+	struct tracing_map_field	*fields;
+	void				*key;
+	void				*private_data;
+};
+
+struct tracing_map_entry {
+	u32				key;
+	struct tracing_map_elt		*val;
+};
+
+struct tracing_map_sort_key {
+	unsigned int			idx;
+	bool				descending;
+};
+
+struct tracing_map_sort_entry {
+	void				*key;
+	struct tracing_map_elt		*elt;
+	bool				elt_copied;
+	bool				dup;
+};
+
+struct tracing_map {
+	unsigned int			key_size;
+	unsigned int			map_bits;
+	unsigned int			map_size;
+	unsigned int			max_elts;
+	atomic_t			next_elt;
+	struct tracing_map_elt		**elts;
+	struct tracing_map_entry	*map;
+	struct tracing_map_ops		*ops;
+	void				*private_data;
+	struct tracing_map_field	field_descr[TRACING_MAP_FIELDS_MAX];
+	unsigned int			n_fields;
+	unsigned int			key_idx;
+	struct tracing_map_sort_key	sort_key;
+};
+
+/**
+ * struct tracing_map_ops - callbacks for tracing_map
+ *
+ * The methods in this structure provide per-event trigger hooks for
+ * various trigger operations.
+ *
+ * All the methods below are optional.
+ *
+ * @elt_alloc: When a tracing_map_elt is allocated, this function, if
+ *	defined, will be called and gives clients the opportunity to
+ *	allocate additional data and attach it to the element
+ *	(tracing_map_elt->private_data is meant for that purpose).
+ *	Element allocation occurs before tracing begins, when the
+ *	tracing_map_init() call is made by client code.
+ *
+ * @elt_copy: At certain points in the lifetime of an element, it may
+ *	need to be copied.  The copy should include a copy of the
+ *	client-allocated data, which can be copied into the 'to'
+ *	element from the 'from' element.
+ *
+ * @elt_free: When a tracing_map_element is freed, this function is
+ *	called and allows client-allocated per-element data to be
+ *	freed.
+ *
+ * @elt_clear: This callback allows per-element client-defined data to
+ *	be cleared, if applicable.
+ *
+ * @elt_init: This callback allows per-element client-defined data to
+ *	be initialized when used i.e. when the element is actually
+ *	claimed by tracing_map_insert() in the context of the map
+ *	insertion.
+ */
+struct tracing_map_ops {
+	int			(*elt_alloc)(struct tracing_map_elt *elt);
+	void			(*elt_copy)(struct tracing_map_elt *to,
+					    struct tracing_map_elt *from);
+	void			(*elt_free)(struct tracing_map_elt *elt);
+	void			(*elt_clear)(struct tracing_map_elt *elt);
+	void			(*elt_init)(struct tracing_map_elt *elt);
+};
+
+extern struct tracing_map *tracing_map_create(unsigned int map_bits,
+					      unsigned int key_size,
+					      struct tracing_map_ops *ops,
+					      void *private_data);
+extern int tracing_map_init(struct tracing_map *map);
+
+extern int tracing_map_add_sum_field(struct tracing_map *map);
+extern int tracing_map_add_key_field(struct tracing_map *map,
+				     tracing_map_cmp_fn_t cmp_fn);
+
+extern void tracing_map_destroy(struct tracing_map *map);
+extern void tracing_map_clear(struct tracing_map *map);
+
+extern struct tracing_map_elt *
+tracing_map_insert(struct tracing_map *map, void *key);
+
+extern tracing_map_cmp_fn_t tracing_map_cmp_num(int field_size,
+						int field_is_signed);
+extern int tracing_map_cmp_string(void *val_a, void *val_b);
+extern int tracing_map_cmp_none(void *val_a, void *val_b);
+
+extern void tracing_map_update_sum(struct tracing_map_elt *elt,
+				   unsigned int i, u64 n);
+extern u64 tracing_map_read_sum(struct tracing_map_elt *elt, unsigned int i);
+extern void tracing_map_set_field_descr(struct tracing_map *map,
+					unsigned int i,
+					unsigned int key_offset,
+					tracing_map_cmp_fn_t cmp_fn);
+extern int
+tracing_map_sort_entries(struct tracing_map *map,
+			 struct tracing_map_sort_key *sort_key,
+			 struct tracing_map_sort_entry ***sort_entries);
+extern void
+tracing_map_destroy_sort_entries(struct tracing_map_sort_entry **entries,
+				 unsigned int n_entries);
+#endif /* __TRACING_MAP_H */
-- 
1.9.3

[PATCH v5 07/10] tracing: Add 'hist' event trigger command

[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                |   44 ++
 kernel/trace/trace.h                |   21 +
 kernel/trace/trace_events.c         |    4 +
 kernel/trace/trace_events_hist.c    | 1123 +++++++++++++++++++++++++++++++++++
 kernel/trace/trace_events_trigger.c |   29 +-
 8 files changed, 1222 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 c4c16ed..3ce364c 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -410,6 +410,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 3b9a48a..85f8025 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -528,6 +528,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 3b26cfb..7faace3 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -54,6 +54,7 @@ obj-$(CONFIG_EVENT_TRACING) += trace_event_perf.o
 endif
 obj-$(CONFIG_EVENT_TRACING) += trace_events_filter.o
 obj-$(CONFIG_EVENT_TRACING) += trace_events_trigger.o
+obj-$(CONFIG_HIST_TRIGGERS) += trace_events_hist.o
 obj-$(CONFIG_BPF_EVENTS) += bpf_trace.o
 obj-$(CONFIG_KPROBE_EVENT) += trace_kprobe.o
 obj-$(CONFIG_TRACEPOINTS) += power-traces.o
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 458031c..cb45dab 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3767,6 +3767,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"
@@ -3782,6 +3785,47 @@ 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    If 'values' is not specified, 'hitcount' will be assumed.\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 56fd2db..38074b7 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 c4de47f..18a35c8 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -1628,6 +1628,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..1b2e5b7
--- /dev/null
+++ b/kernel/trace/trace_events_hist.c
@@ -0,0 +1,1123 @@
+/*
+ * 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>
+ */
+
+#include <linux/module.h>
+#include <linux/kallsyms.h>
+#include <linux/mutex.h>
+#include <linux/slab.h>
+#include <linux/stacktrace.h>
+
+#include "tracing_map.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;
+	unsigned int			size;
+};
+
+static u64 hist_field_none(struct hist_field *field, void *event)
+{
+	return 0;
+}
+
+static u64 hist_field_counter(struct hist_field *field, void *event)
+{
+	return 1;
+}
+
+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 HITCOUNT_IDX		0
+
+enum hist_field_flags {
+	HIST_FIELD_HITCOUNT	= 1,
+	HIST_FIELD_KEY		= 2,
+	HIST_FIELD_SYM		= 4,
+	HIST_FIELD_HEX		= 8,
+	HIST_FIELD_STACKTRACE	= 16,
+	HIST_FIELD_STRING	= 32,
+	HIST_FIELD_EXECNAME	= 64,
+	HIST_FIELD_SYSCALL	= 128,
+};
+
+struct hist_trigger_attrs {
+	char		*keys_str;
+	char		*vals_str;
+	char		*sort_key_str;
+	bool		pause;
+	bool		cont;
+	bool		clear;
+	unsigned int	map_bits;
+};
+
+struct hist_trigger_data {
+	atomic64_t			total_hits;
+	struct hist_field               *fields[TRACING_MAP_FIELDS_MAX];
+	unsigned int			n_vals;
+	unsigned int			n_fields;
+	struct tracing_map_sort_key	sort_key;
+	struct ftrace_event_file	*event_file;
+	atomic64_t			drops;
+	struct hist_trigger_attrs	*attrs;
+	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 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 < TRACING_MAP_BITS_MIN ||
+	    map_bits > TRACING_MAP_BITS_MAX)
+		ret = -EINVAL;
+	else
+		ret = map_bits;
+ out:
+	return ret;
+}
+
+static void destroy_hist_trigger_attrs(struct hist_trigger_attrs *attrs)
+{
+	kfree(attrs->sort_key_str);
+	kfree(attrs->keys_str);
+	kfree(attrs->vals_str);
+	kfree(attrs);
+}
+
+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_key_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 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 hist_trigger_elt_free(struct tracing_map_elt *elt)
+{
+	kfree((char *)elt->private_data);
+}
+
+static int hist_trigger_elt_alloc(struct tracing_map_elt *elt)
+{
+	struct hist_trigger_data *hist_data = elt->map->private_data;
+	struct hist_field *key_field;
+
+	key_field = hist_data->fields[hist_data->n_vals];
+
+	if (key_field->flags & HIST_FIELD_EXECNAME) {
+		unsigned int size = TASK_COMM_LEN + 1;
+
+		elt->private_data = kzalloc(size, GFP_KERNEL);
+		if (!elt->private_data)
+			return -ENOMEM;
+	}
+
+	return 0;
+}
+
+static void hist_trigger_elt_copy(struct tracing_map_elt *to,
+				  struct tracing_map_elt *from)
+{
+	char *comm_from = from->private_data;
+	char *comm_to = to->private_data;
+
+	if (comm_from)
+		memcpy(comm_to, comm_from, TASK_COMM_LEN + 1);
+}
+
+static void hist_trigger_elt_init(struct tracing_map_elt *elt)
+{
+	char *comm = elt->private_data;
+
+	if (comm)
+		save_comm(comm, current);
+}
+
+static struct tracing_map_ops hist_trigger_ops = {
+	.elt_alloc	= hist_trigger_elt_alloc,
+	.elt_copy	= hist_trigger_elt_copy,
+	.elt_free	= hist_trigger_elt_free,
+	.elt_init	= hist_trigger_elt_init,
+};
+
+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)
+{
+	struct hist_field *hist_field;
+
+	if (field && is_function_field(field))
+		return NULL;
+
+	hist_field = kzalloc(sizeof(struct hist_field), GFP_KERNEL);
+	if (!hist_field)
+		return NULL;
+
+	if (flags & HIST_FIELD_HITCOUNT) {
+		hist_field->fn = hist_field_counter;
+		goto out;
+	}
+
+	if (flags & HIST_FIELD_STACKTRACE) {
+		hist_field->fn = hist_field_none;
+		goto out;
+	}
+
+	if (is_string_field(field)) {
+		flags |= HIST_FIELD_STRING;
+		hist_field->fn = hist_field_string;
+	} else {
+		hist_field->fn = select_value_fn(field->size,
+						 field->is_signed);
+		if (!hist_field->fn) {
+			destroy_hist_field(hist_field);
+			return NULL;
+		}
+	}
+ out:
+	hist_field->field = field;
+	hist_field->flags = flags;
+
+	return hist_field;
+}
+
+static void destroy_hist_fields(struct hist_trigger_data *hist_data)
+{
+	unsigned int i;
+
+	for (i = 0; i < hist_data->n_fields; i++) {
+		destroy_hist_field(hist_data->fields[i]);
+		hist_data->fields[i] = NULL;
+	}
+}
+
+static int create_hitcount_val(struct hist_trigger_data *hist_data)
+{
+	hist_data->fields[HITCOUNT_IDX] =
+		create_hist_field(NULL, HIST_FIELD_HITCOUNT);
+	if (!hist_data->fields[HITCOUNT_IDX])
+		return -ENOMEM;
+
+	hist_data->n_vals++;
+
+	return 0;
+}
+
+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->fields[val] = create_hist_field(field, flags);
+	if (!hist_data->fields[val]) {
+		ret = -ENOMEM;
+		goto out;
+	}
+	hist_data->n_vals++;
+ out:
+	return ret;
+}
+
+static int create_key_field(struct hist_trigger_data *hist_data,
+			    struct ftrace_event_file *file,
+			    char *field_str)
+{
+	unsigned int key_size, key_idx = hist_data->n_vals;
+	struct ftrace_event_field *field = NULL;
+	unsigned long flags = 0;
+	char *field_name;
+	int ret = 0;
+
+	flags |= HIST_FIELD_KEY;
+
+	if (!strcmp(field_str, "stacktrace")) {
+		flags |= HIST_FIELD_STACKTRACE;
+		key_size = sizeof(unsigned long) * HIST_STACKTRACE_DEPTH;
+	} 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;
+		}
+		key_size = field->size;
+	}
+	hist_data->fields[key_idx] = create_hist_field(field, flags);
+	if (!hist_data->fields[key_idx])
+		ret = -ENOMEM;
+	hist_data->fields[key_idx]->size = key_size;
+ out:
+	return ret;
+}
+
+static int create_val_fields(struct hist_trigger_data *hist_data,
+			     struct ftrace_event_file *file)
+{
+	char *fields_str, *field_str;
+	unsigned int i;
+	int ret;
+
+	ret = create_hitcount_val(hist_data);
+	if (ret)
+		goto out;
+
+	fields_str = hist_data->attrs->vals_str;
+	if (!fields_str)
+		goto out;
+
+	strsep(&fields_str, "=");
+	if (!fields_str)
+		goto out;
+
+	for (i = 1; i < TRACING_MAP_FIELDS_MAX - 1; i++) {
+		field_str = strsep(&fields_str, ",");
+		if (!field_str)
+				break;
+		ret = create_val_field(hist_data, i, file, field_str);
+		if (ret)
+			goto out;
+	}
+ out:
+	return ret;
+}
+
+static int create_hist_fields(struct hist_trigger_data *hist_data,
+			      struct ftrace_event_file *file)
+{
+	char *fields_str;
+	int ret;
+
+	ret = create_val_fields(hist_data, file);
+	if (ret)
+		goto out;
+
+	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;
+
+	hist_data->n_fields = hist_data->n_vals + 1;
+ out:
+	return ret;
+}
+
+static int create_sort_key(struct hist_trigger_data *hist_data)
+{
+	char *field_str = hist_data->attrs->sort_key_str;
+	struct ftrace_event_field *field = NULL;
+	unsigned int i;
+	char *field_name;
+	int ret = 0;
+
+	if (!field_str)
+		goto out;
+
+	strsep(&field_str, "=");
+	if (!field_str)
+		goto out;
+
+	field_name = strsep(&field_str, ".");
+	if (!strcmp(field_name, "hitcount"))
+		goto out;
+
+	for (i = 1; i < hist_data->n_fields; i++) {
+		field = hist_data->fields[i]->field;
+		if (field && !strcmp(field_name, field->name)) {
+			hist_data->sort_key.idx = i;
+			goto out;
+		}
+	}
+	return -EINVAL;
+ out:
+	if (field_str && (!strcmp(field_str, "descending")))
+		hist_data->sort_key.descending = true;
+
+	return ret;
+}
+
+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 int create_tracing_map_fields(struct hist_trigger_data *hist_data)
+{
+	struct tracing_map *map = hist_data->map;
+	struct ftrace_event_field *field;
+	struct hist_field *hist_field;
+	unsigned int i, idx;
+
+	for (i = 0; i < hist_data->n_fields; i++) {
+		hist_field = hist_data->fields[i];
+		if (hist_field->flags & HIST_FIELD_KEY) {
+			tracing_map_cmp_fn_t cmp_fn;
+
+			field = hist_field->field;
+
+			if (hist_field->flags & HIST_FIELD_STACKTRACE)
+				cmp_fn = tracing_map_cmp_none;
+			else if (is_string_field(field))
+				cmp_fn = tracing_map_cmp_string;
+			else
+				cmp_fn = tracing_map_cmp_num(field->size,
+							     field->is_signed);
+			idx = tracing_map_add_key_field(map, cmp_fn);
+		} else
+			idx = tracing_map_add_sum_field(map);
+
+		if (idx < 0)
+			return idx;
+	}
+
+	return 0;
+}
+
+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;
+	unsigned int key_size;
+	int ret = 0;
+
+	hist_data = kzalloc(sizeof(*hist_data), GFP_KERNEL);
+	if (!hist_data)
+		return ERR_PTR(-ENOMEM);
+
+	hist_data->attrs = attrs;
+
+	ret = create_hist_fields(hist_data, file);
+	if (ret < 0)
+		goto free;
+
+	ret = create_sort_key(hist_data);
+	if (ret < 0)
+		goto free;
+
+	key_size = hist_data->fields[hist_data->n_vals]->size;
+	hist_data->map = tracing_map_create(map_bits, key_size,
+					    &hist_trigger_ops,
+					    hist_data);
+	if (IS_ERR(hist_data->map)) {
+		ret = PTR_ERR(hist_data->map);
+		hist_data->map = NULL;
+		goto free;
+	}
+
+	ret = create_tracing_map_fields(hist_data);
+	if (ret)
+		goto free;
+
+	ret = tracing_map_init(hist_data->map);
+	if (ret)
+		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_elt_update(struct hist_trigger_data *hist_data,
+				    struct tracing_map_elt *elt,
+				    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->fields[i];
+		hist_val = hist_field->fn(hist_field, rec);
+		tracing_map_update_sum(elt, i, hist_val);
+	}
+}
+
+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 stack_trace stacktrace;
+	struct hist_field *key_field;
+	struct tracing_map_elt *elt;
+	u64 field_contents;
+	void *key;
+
+	key_field = hist_data->fields[hist_data->n_vals];
+
+	if (atomic64_read(&hist_data->drops)) {
+		atomic64_inc(&hist_data->drops);
+		return;
+	}
+
+	if (key_field->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 = key_field->fn(key_field, rec);
+		if (key_field->flags & HIST_FIELD_STRING)
+			key = (void *)field_contents;
+		else
+			key = (void *)&field_contents;
+	}
+
+	elt = tracing_map_insert(hist_data->map, key);
+	if (elt)
+		hist_trigger_elt_update(hist_data, elt, 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 tracing_map_elt *elt)
+{
+	struct hist_field *key_field;
+	char str[KSYM_SYMBOL_LEN];
+	unsigned int i;
+	u64 uval;
+
+	key_field = hist_data->fields[hist_data->n_vals];
+
+	if (key_field->flags & HIST_FIELD_SYM) {
+		uval = *(u64 *)key;
+		kallsyms_lookup(uval, NULL, NULL, NULL, str);
+		seq_printf(m, "%s: [%llx] %-35s", key_field->field->name,
+			   uval, str);
+	} else if (key_field->flags & HIST_FIELD_HEX) {
+		uval = *(u64 *)key;
+		seq_printf(m, "%s: %llx", key_field->field->name, uval);
+	} else if (key_field->flags & HIST_FIELD_STACKTRACE) {
+		seq_puts(m, "stacktrace:\n");
+		hist_trigger_stacktrace_print(m, key, HIST_STACKTRACE_DEPTH);
+	} else if (key_field->flags & HIST_FIELD_STRING) {
+		seq_printf(m, "%s: %-35s", key_field->field->name,
+			   (char *)key);
+	} else if (key_field->flags & HIST_FIELD_EXECNAME) {
+		char *comm = elt->private_data;
+
+		uval = *(u64 *)key;
+		seq_printf(m, "%s: %-16s[%10llu]", key_field->field->name,
+			   comm, uval);
+	} else if (key_field->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", key_field->field->name,
+			   syscall_name);
+	} else {
+		uval = *(u64 *)key;
+		seq_printf(m, "%s: %10llu", key_field->field->name, uval);
+	}
+	seq_printf(m, " hitcount: %10llu",
+		   tracing_map_read_sum(elt, HITCOUNT_IDX));
+
+	for (i = 1; i < hist_data->n_vals; i++) {
+		seq_printf(m, "  %s: %10llu",
+			   hist_data->fields[i]->field->name,
+			   tracing_map_read_sum(elt, i));
+	}
+
+	seq_puts(m, "\n");
+}
+
+static int print_entries(struct seq_file *m,
+			 struct hist_trigger_data *hist_data)
+{
+	struct tracing_map_sort_entry **sort_entries = NULL;
+	struct tracing_map *map = hist_data->map;
+	unsigned int i, n_entries;
+
+	n_entries = tracing_map_sort_entries(map, &hist_data->sort_key,
+					     &sort_entries);
+	if (n_entries < 0)
+		return n_entries;
+
+	for (i = 0; i < n_entries; i++)
+		hist_trigger_entry_print(m, hist_data,
+					 sort_entries[i]->key,
+					 sort_entries[i]->elt);
+
+	tracing_map_destroy_sort_entries(sort_entries, n_entries);
+
+	return n_entries;
+}
+
+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 n_entries, 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;
+	n_entries = print_entries(m, hist_data);
+	if (n_entries < 0) {
+		ret = n_entries;
+		n_entries = 0;
+	}
+
+	seq_printf(m, "\nTotals:\n    Hits: %lu\n    Entries: %u\n    Dropped: %lu\n",
+		   atomic64_read(&hist_data->total_hits),
+		   n_entries, 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;
+	struct hist_field *key_field;
+	unsigned int i;
+
+	key_field = hist_data->fields[hist_data->n_vals];
+
+	seq_puts(m, "hist:keys=");
+
+	if (key_field->flags & HIST_FIELD_STACKTRACE)
+		seq_puts(m, "stacktrace");
+	else
+		hist_field_print(m, key_field);
+
+	seq_puts(m, ":vals=");
+
+	if (hist_data->n_vals == 1)
+		seq_puts(m, "hitcount");
+	else {
+		for (i = 1; i < hist_data->n_vals; i++) {
+			if (i > 1)
+				seq_puts(m, ",");
+			hist_field_print(m, hist_data->fields[i]);
+		}
+	}
+
+	seq_puts(m, ":sort=");
+
+	if (hist_data->sort_key.idx == HITCOUNT_IDX)
+		seq_puts(m, "hitcount");
+	else {
+		unsigned int idx = hist_data->sort_key.idx;
+
+		hist_field_print(m, hist_data->fields[idx]);
+	}
+	if (hist_data->sort_key.descending)
+		seq_puts(m, ".descending");
+
+	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++;
+
+	update_cond_flag(file);
+	if (trace_event_trigger_enable_disable(file, 1) < 0) {
+		list_del_rcu(&data->list);
+		update_cond_flag(file);
+		ret--;
+	}
+ 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 = TRACING_MAP_BITS_DEFAULT;
+	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(&param, " \t");
+	if (!trigger)
+		return -EINVAL;
+
+	attrs = parse_hist_trigger_attrs(trigger);
+	if (IS_ERR(attrs))
+		return PTR_ERR(attrs);
+
+	if (!attrs->keys_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 9438abc..3b7efde 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;
@@ -570,9 +568,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;
@@ -706,9 +704,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;
@@ -1439,6 +1437,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

[PATCH v5 08/10] tracing: Add enable_hist/disable_hist triggers

[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 3ce364c..78045f6 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -411,6 +411,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 cb45dab..bca73e7 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -3761,6 +3761,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
@@ -3825,6 +3829,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 38074b7..0f016dc 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 1b2e5b7..56ee93c 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -1121,3 +1121,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 3b7efde..108e46c 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;
@@ -1052,15 +1052,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)
 {
@@ -1090,14 +1081,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));
 
@@ -1114,9 +1107,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;
 
@@ -1161,10 +1153,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;
@@ -1173,6 +1164,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;
@@ -1197,8 +1189,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;
@@ -1218,6 +1217,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;
@@ -1295,10 +1295,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;
@@ -1308,6 +1308,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;
@@ -1333,10 +1335,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;
@@ -1346,6 +1348,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);
@@ -1365,8 +1369,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;
@@ -1437,6 +1445,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

[PATCH v5 09/10] tracing: Add 'hist' trigger Documentation

[Tom Zanussi]

Add documentation and usage examples for 'hist' triggers.

Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
 Documentation/trace/events.txt | 872 +++++++++++++++++++++++++++++++++++++++++
 1 file changed, 872 insertions(+)

diff --git a/Documentation/trace/events.txt b/Documentation/trace/events.txt
index 75d25a1..29dc9bf 100644
--- a/Documentation/trace/events.txt
+++ b/Documentation/trace/events.txt
@@ -494,3 +494,875 @@ 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.  If 'values' isn't specified, an implicit 'hitcount'
+  value will be automatically created and used as the only value.
+  Keys can be any field, or the special string 'stacktrace', which
+  will use the event's kernel stacktrace as the key.  The keywords
+  'keys' or 'key' can be used to specify keys, and the 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

[PATCH 10/10][RFC] ftrace: Add function_hist tracer

[Tom Zanussi]

Add a new tracer named function_hist:

  # cat /sys/kernel/debug/tracing/available_tracers

  blk mmiotrace function_hist function_graph wakeup_dl wakeup_rt wakeup
  irqsoff function nop

  # echo function_hist > /sys/kernel/debug/tracing/current_tracer
  # cat /sys/kernel/debug/tracing/function_hist

This is essentially the same as the kernel function tracer, but
instead of logging every function call into the trace buffer, it
continually updates a tracing map which keeps a running count for each
function.

As such, it provides an exhaustive enumeration of every traceable
function called in the kernel since the tracer was enabled, along with
the number of times it was called.

Example output from an overnight run:

  # cat /sys/kernel/debug/tracing/function_hist

ip: [ffffffff812002d0] inotify_release                     hitcount:          1
ip: [ffffffff81078c40] param_attr_show                     hitcount:          1
ip: [ffffffff816e2f20] inet6_csk_bind_conflict             hitcount:          1
ip: [ffffffffa04bdf50] intel_modeset_preclose              hitcount:          1
ip: [ffffffff812001f0] inotify_free_group_priv             hitcount:          1
ip: [ffffffffa04641d0] i915_gem_context_create_ioctl       hitcount:          1
ip: [ffffffffa026b100] drm_modeset_lock_all_crtcs          hitcount:          1
ip: [ffffffff811fe410] fsnotify_destroy_group              hitcount:          1
ip: [ffffffff810785e0] module_attr_show                    hitcount:          1
 .
 .
 .
ip: [ffffffff8109a3e0] add_wait_queue                      hitcount:  235927661
ip: [ffffffff81716930] _raw_spin_lock                      hitcount:  345398436
ip: [ffffffff81713150] _cond_resched                       hitcount:  378571372
ip: [ffffffff816abe90] unix_poll                           hitcount:  413026161
ip: [ffffffff815f4510] sock_poll                           hitcount:  438658385
ip: [ffffffff811dc040] __fdget                             hitcount:  640844197
ip: [ffffffff811dba90] __fget                              hitcount:  657582124
ip: [ffffffff811dbfd0] __fget_light                        hitcount:  662386005
ip: [ffffffff817164f0] _raw_spin_unlock_irqrestore         hitcount:  848890816
ip: [ffffffff817168e0] _raw_spin_lock_irqsave              hitcount:  849815447
ip: [ffffffff811c09c0] fput                                hitcount:  892233261

Totals:
    Hits: 17981015194
    Entries: 5527
    Dropped: 0

Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
 kernel/trace/Makefile               |   1 +
 kernel/trace/trace.c                |   3 +
 kernel/trace/trace.h                |  11 ++
 kernel/trace/trace_functions_hist.c | 345 ++++++++++++++++++++++++++++++++++++
 4 files changed, 360 insertions(+)
 create mode 100644 kernel/trace/trace_functions_hist.c

diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 7faace3..eb2bb50 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -34,6 +34,7 @@ obj-$(CONFIG_TRACING) += trace_printk.o
 obj-$(CONFIG_TRACING) += tracing_map.o
 obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o
 obj-$(CONFIG_FUNCTION_TRACER) += trace_functions.o
+obj-$(CONFIG_FUNCTION_TRACER) += trace_functions_hist.o
 obj-$(CONFIG_IRQSOFF_TRACER) += trace_irqsoff.o
 obj-$(CONFIG_PREEMPT_TRACER) += trace_irqsoff.o
 obj-$(CONFIG_SCHED_TRACER) += trace_sched_wakeup.o
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index bca73e7..858ee45 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -6729,6 +6729,9 @@ init_tracer_tracefs(struct trace_array *tr, struct dentry *d_tracer)
 	if (ftrace_create_function_files(tr, d_tracer))
 		WARN(1, "Could not allocate function filter files");
 
+	if (ftrace_create_function_hist_files(tr, d_tracer))
+		WARN(1, "Could not allocate function_hist filter files");
+
 #ifdef CONFIG_TRACER_SNAPSHOT
 	trace_create_file("snapshot", 0644, d_tracer,
 			  tr, &snapshot_fops);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 0f016dc..eb3d632 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -820,7 +820,10 @@ static inline int ftrace_trace_task(struct task_struct *task)
 extern int ftrace_is_dead(void);
 int ftrace_create_function_files(struct trace_array *tr,
 				 struct dentry *parent);
+int ftrace_create_function_hist_files(struct trace_array *tr,
+				      struct dentry *parent);
 void ftrace_destroy_function_files(struct trace_array *tr);
+void ftrace_destroy_function_hist_files(struct trace_array *tr);
 void ftrace_init_global_array_ops(struct trace_array *tr);
 void ftrace_init_array_ops(struct trace_array *tr, ftrace_func_t func);
 void ftrace_reset_array_ops(struct trace_array *tr);
@@ -837,7 +840,15 @@ ftrace_create_function_files(struct trace_array *tr,
 {
 	return 0;
 }
+static inline int
+ftrace_create_function_hist_files(struct trace_array *tr,
+				  struct dentry *parent)
+{
+	return 0;
+}
 static inline void ftrace_destroy_function_files(struct trace_array *tr) { }
+static inline void
+ftrace_destroy_function_hist_files(struct trace_array *tr) { }
 static inline __init void
 ftrace_init_global_array_ops(struct trace_array *tr) { }
 static inline void ftrace_reset_array_ops(struct trace_array *tr) { }
diff --git a/kernel/trace/trace_functions_hist.c b/kernel/trace/trace_functions_hist.c
new file mode 100644
index 0000000..f3c0d5d
--- /dev/null
+++ b/kernel/trace/trace_functions_hist.c
@@ -0,0 +1,345 @@
+/*
+ * histogram-based function tracer
+ *
+ * Copyright (C) 2015 Tom Zanussi <tom.zanussi@linux.intel.com>
+ *
+ * Based on code from the function_tracer, that is:
+ *
+ * Copyright (C) 2007-2008 Steven Rostedt <srostedt@redhat.com>
+ * Copyright (C) 2008 Ingo Molnar <mingo@redhat.com>
+ */
+#include <linux/kallsyms.h>
+#include <linux/module.h>
+#include <linux/ftrace.h>
+#include <linux/slab.h>
+
+#include "tracing_map.h"
+#include "trace.h"
+
+static void tracing_start_function_hist(struct trace_array *tr);
+static void tracing_stop_function_hist(struct trace_array *tr);
+static void
+function_hist_call(unsigned long ip, unsigned long parent_ip,
+		   struct ftrace_ops *op, struct pt_regs *pt_regs);
+
+enum hist_key_flags {
+	HIST_FIELD_SYM		= 1,
+	HIST_FIELD_HEX		= 2,
+};
+
+struct function_hist_data {
+	atomic64_t			total_hits;
+	atomic64_t			drops;
+	unsigned long			key_flags;
+	struct tracing_map_sort_key	sort_key;
+	struct tracing_map		*map;
+};
+
+#define FUNCTION_HIST_BITS_DEFAULT	16
+#define HITCOUNT_IDX			0
+
+static struct function_hist_data *function_hist_data;
+
+static int allocate_ftrace_ops(struct trace_array *tr)
+{
+	struct ftrace_ops *ops;
+
+	ops = kzalloc(sizeof(*ops), GFP_KERNEL);
+	if (!ops)
+		return -ENOMEM;
+
+	ops->func = function_hist_call;
+	ops->flags = FTRACE_OPS_FL_RECURSION_SAFE;
+
+	tr->ops = ops;
+	ops->private = tr;
+
+	return 0;
+}
+
+static int function_hist_init(struct trace_array *tr)
+{
+	ftrace_func_t func;
+
+	/*
+	 * Instance trace_arrays get their ops allocated
+	 * at instance creation. Unless it failed
+	 * the allocation.
+	 */
+	if (!tr->ops)
+		return -ENOMEM;
+
+	func = function_hist_call;
+
+	ftrace_init_array_ops(tr, func);
+
+	tracing_start_function_hist(tr);
+
+	return 0;
+}
+
+static void function_hist_reset(struct trace_array *tr)
+{
+	tracing_stop_function_hist(tr);
+	ftrace_reset_array_ops(tr);
+}
+
+static void
+function_hist_call(unsigned long ip, unsigned long parent_ip,
+		   struct ftrace_ops *op, struct pt_regs *pt_regs)
+{
+	struct trace_array *tr = op->private;
+	struct tracing_map_elt *elt;
+	void *key;
+	int bit;
+
+	if (unlikely(!tr->function_enabled))
+		return;
+
+	preempt_disable_notrace();
+
+	bit = trace_test_and_set_recursion(TRACE_FTRACE_START,
+					   TRACE_FTRACE_MAX);
+	if (bit < 0)
+		goto out;
+
+	if (atomic64_read(&function_hist_data->drops)) {
+		atomic64_inc(&function_hist_data->drops);
+		goto out_clear;
+	}
+
+	key = (void *)&ip;
+	elt = tracing_map_insert(function_hist_data->map, key);
+	if (elt)
+		tracing_map_update_sum(elt, HITCOUNT_IDX, 1);
+	else
+		atomic64_inc(&function_hist_data->drops);
+
+	atomic64_inc(&function_hist_data->total_hits);
+ out_clear:
+	trace_clear_recursion(bit);
+ out:
+	preempt_enable_notrace();
+}
+
+static void destroy_hist_data(struct function_hist_data *hist_data)
+{
+	tracing_map_destroy(hist_data->map);
+	kfree(hist_data);
+}
+
+static inline void create_sort_key(struct function_hist_data *hist_data)
+{
+	hist_data->sort_key.idx = HITCOUNT_IDX;
+	hist_data->sort_key.descending = false;
+}
+
+static int create_tracing_map_fields(struct function_hist_data *hist_data)
+{
+	struct tracing_map *map = hist_data->map;
+	unsigned int idx;
+
+	idx = tracing_map_add_sum_field(map);
+	if (idx < 0)
+		return idx;
+
+	idx = tracing_map_add_key_field(map, tracing_map_cmp_none);
+	if (idx < 0)
+		return idx;
+
+	return 0;
+}
+
+static struct function_hist_data *create_hist_data(unsigned int map_bits)
+{
+	struct function_hist_data *hist_data;
+	unsigned int key_size;
+	int ret = 0;
+
+	hist_data = kzalloc(sizeof(*hist_data), GFP_KERNEL);
+	if (!hist_data)
+		return NULL;
+
+	create_sort_key(hist_data);
+
+	key_size = sizeof(unsigned long); /* ip */
+	hist_data->map = tracing_map_create(map_bits, key_size,
+					    NULL, hist_data);
+	if (IS_ERR(hist_data->map)) {
+		ret = PTR_ERR(hist_data->map);
+		hist_data->map = NULL;
+		goto free;
+	}
+
+	ret = create_tracing_map_fields(hist_data);
+	if (ret)
+		goto free;
+
+	ret = tracing_map_init(hist_data->map);
+	if (ret)
+		goto free;
+ 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 tracing_start_function_hist(struct trace_array *tr)
+{
+	unsigned int hist_trigger_bits = FUNCTION_HIST_BITS_DEFAULT;
+	struct function_hist_data *hist_data;
+
+	if (function_hist_data) {
+		destroy_hist_data(function_hist_data);
+		function_hist_data = NULL;
+	}
+
+	hist_data = create_hist_data(hist_trigger_bits);
+	if (IS_ERR(hist_data))
+		return;
+
+	hist_data->key_flags |= HIST_FIELD_SYM;
+
+	function_hist_data = hist_data;
+
+	tr->function_enabled = 0;
+	register_ftrace_function(tr->ops);
+	tr->function_enabled = 1;
+}
+
+static void tracing_stop_function_hist(struct trace_array *tr)
+{
+	tr->function_enabled = 0;
+	unregister_ftrace_function(tr->ops);
+}
+
+static void function_hist_entry_print(struct seq_file *m,
+				      struct function_hist_data *hist_data,
+				      void *key, struct tracing_map_elt *elt)
+{
+	char str[KSYM_SYMBOL_LEN];
+	u64 uval;
+
+	if (hist_data->key_flags & HIST_FIELD_SYM) {
+		uval = *(u64 *)key;
+		kallsyms_lookup(uval, NULL, NULL, NULL, str);
+		seq_printf(m, "ip: [%llx] %-35s", uval, str);
+	} else if (hist_data->key_flags & HIST_FIELD_HEX) {
+		uval = *(u64 *)key;
+		seq_printf(m, "ip: %llx", uval);
+	} else {
+		uval = *(u64 *)key;
+		seq_printf(m, "ip: %10llu", uval);
+	}
+
+	seq_printf(m, " hitcount: %10llu",
+		   tracing_map_read_sum(elt, HITCOUNT_IDX));
+
+	seq_puts(m, "\n");
+}
+
+static int print_entries(struct seq_file *m,
+			 struct function_hist_data *hist_data)
+{
+	struct tracing_map_sort_entry **sort_entries = NULL;
+	struct tracing_map *map = hist_data->map;
+	unsigned int i, n_entries;
+
+	n_entries = tracing_map_sort_entries(map, &hist_data->sort_key,
+					     &sort_entries);
+	if (n_entries < 0)
+		return n_entries;
+
+	for (i = 0; i < n_entries; i++)
+		function_hist_entry_print(m, hist_data,
+					  sort_entries[i]->key,
+					  sort_entries[i]->elt);
+
+	tracing_map_destroy_sort_entries(sort_entries, n_entries);
+
+	return n_entries;
+}
+
+static int hist_show(struct seq_file *m, void *v)
+{
+	int n_entries, ret = 0;
+
+	mutex_lock(&trace_types_lock);
+
+	if (!function_hist_data)
+		goto out_unlock;
+
+	n_entries = print_entries(m, function_hist_data);
+	if (n_entries < 0) {
+		ret = n_entries;
+		n_entries = 0;
+	}
+
+	seq_printf(m, "\nTotals:\n    Hits: %lu\n    Entries: %u\n    Dropped: %lu\n",
+		   atomic64_read(&function_hist_data->total_hits),
+		   n_entries, atomic64_read(&function_hist_data->drops));
+ out_unlock:
+	mutex_unlock(&trace_types_lock);
+
+	return ret;
+}
+
+static int function_hist_open(struct inode *inode, struct file *file)
+{
+	return single_open(file, hist_show, file);
+}
+
+const struct file_operations function_hist_fops = {
+	.open = function_hist_open,
+	.read = seq_read,
+	.llseek = seq_lseek,
+	.release = single_release,
+};
+
+int ftrace_create_function_hist_files(struct trace_array *tr,
+				      struct dentry *parent)
+{
+	struct dentry *d_tracer;
+	int ret;
+
+	d_tracer = tracing_init_dentry();
+	if (IS_ERR(d_tracer))
+		return 0;
+
+	trace_create_file("function_hist", 0444, d_tracer,
+			NULL, &function_hist_fops);
+
+	ret = allocate_ftrace_ops(tr);
+	if (ret)
+		return ret;
+
+	return 0;
+}
+
+void ftrace_destroy_function_hist_files(struct trace_array *tr)
+{
+	kfree(tr->ops);
+	tr->ops = NULL;
+}
+
+static struct tracer function_hist __tracer_data = {
+	.name		= "function_hist",
+	.init		= function_hist_init,
+	.reset		= function_hist_reset,
+	.allow_instances = true,
+#ifdef CONFIG_FTRACE_SELFTEST
+	.selftest	= trace_selftest_startup_function,
+#endif
+};
+
+static __init int init_function_hist(void)
+{
+	return register_tracer(&function_hist);
+}
+fs_initcall(init_function_hist);
-- 
1.9.3

Re: [PATCH 01/10] tracing: Update cond flag when enabling or disabling a trigger

[Masami Hiramatsu]

On 2015/05/21 6:19, Tom Zanussi wrote:
> When a trigger is enabled, the cond flag should be set beforehand,
> otherwise a 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>
> Signed-off-by: Daniel Wagner <daniel.wagner@bmw-carit.de>

Reviewed-by: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>

Thank you!

> ---
>  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 8712df9..51e2664 100644
> --- a/kernel/trace/trace_events_trigger.c
> +++ b/kernel/trace/trace_events_trigger.c
> @@ -543,11 +543,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;
>  }
> @@ -575,8 +576,8 @@ static 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;
>  		}
>  	}
> @@ -1319,11 +1320,12 @@ static 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;
>  }
> @@ -1344,8 +1346,8 @@ static 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;
>  		}
>  	}
> 


-- 
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: masami.hiramatsu.pt@hitachi.com

Re: [PATCH v5 00/10] tracing: 'hist' triggers

[Masami Hiramatsu]

Hi Tom,

On 2015/05/21 6:19, Tom Zanussi wrote:
> This is v5 of the 'hist triggers' patchset, following feedback from
> v4.
> 
> Changes from v4:
> 
> This version addresses some problems and suggestions made by Daniel
> Wagner - a lot of the code was reworked to get rid of the distinction
> between keys and values, and as a result, both keys and values can be
> used as sort keys.  As suggested, it also allows 'val=' to be absent
> in a trigger command - if no 'val' is specified, hitcount is assumed
> and automatically used as the only val.

Thank you for this amazing work! :)
Here is an example how I've used it.

---------
[root@localhost perf]# ./perf probe -a '__kmalloc caller=$stack0 size'
Added new event:
  probe:__kmalloc      (on __kmalloc with caller=$stack0 size)

You can now use it in all perf tools, such as:

        perf record -e probe:__kmalloc -aR sleep 1

[root@localhost perf]# cd /sys/kernel/debug/tracing
[root@localhost tracing]# echo hist:keys=caller.sym > events/probe/__kmalloc/trigger
[root@localhost tracing]# echo 1 > events/probe/__kmalloc/enable
[root@localhost tracing]# cat events/probe/__kmalloc/hist
# trigger info: hist:keys=caller.sym:vals=hitcount:sort=hitcount:size=2048 [active]

caller: [ffffffff811964d7] tracing_map_sort_entries            hitcount:          1
caller: [ffffffff81296120] load_elf_binary                     hitcount:          1
caller: [ffffffff813eb98c] context_struct_to_string            hitcount:          1
caller: [ffffffff81264c8c] simple_xattr_alloc                  hitcount:          1
caller: [ffffffff811e0a02] shmem_initxattrs                    hitcount:          1
caller: [ffffffff81295eb6] load_elf_phdrs                      hitcount:          2
caller: [ffffffff8169c49b] sk_prot_alloc                       hitcount:          2
caller: [ffffffff81395567] kmem_alloc                          hitcount:          6
caller: [ffffffff8125b844] alloc_fdmem                         hitcount:          6
caller: [ffffffff81415918] bio_alloc_bioset                    hitcount:          8
caller: [ffffffff813ecc44] security_context_to_sid_core        hitcount:         17
caller: [ffffffff812621bb] seq_buf_alloc                       hitcount:         18

Totals:
    Hits: 64
    Entries: 12
    Dropped: 0
----------
Good! Just one more, I also want to see the offset of the symbols. :)

And this can dig deeper to investigate the size histogram, with filtering by caller.
----------
[root@localhost tracing]# echo \!hist:keys=caller.sym > events/probe/__kmalloc/trigger
[root@localhost tracing]# echo hist:keys=size if caller==0xffffffff812621bb > events/probe/__kmalloc/trigger
[root@localhost tracing]# cat events/probe/__kmalloc/hist
# trigger info: hist:keys=size:vals=hitcount:sort=hitcount:size=2048 if caller==0xffffffff812621bb [active]

size:       3024 hitcount:          1
size:       4096 hitcount:         12

Totals:
    Hits: 13
    Entries: 2
    Dropped: 0
[root@localhost tracing]#
---------
Yes! This interactivity is what I want :)

Another enhancement ideas what I want are here:
- Named hist instance, which can be shared among several events.
  Since probing an inlined function can make a several probe-events,
  those need to share a histogram among them.
- Multiple hist instances for each event, which allows us to compare
  several histograms which have different filters.

Anyway, without above, this look fine to me :)

> 
> The map code was also separated out into a separate file,
> tracing_map.c, allowing it to be reused.  It also adds a second tracer
> called function_hist that actually does reuse the code, as an RFC
> patch.
> 
> Patch 01/10 [tracing: Update cond flag when enabling or disabling..]
> is a fix for a problem noticed by Daniel and that fixes a problem in
> existing trigger code and should be applied regardless of whether the
> rest of the patchset is merged.

I've reviewed that.

> As mentioned, patch 10/10 is an RFC patch implementing a new tracer
> based on the function tracer code.  It's a fun little tool and is
> useful for a specific problem I'm working on (and is also a nice test
> of the tracing_map code), but is an RFC because first, I'm not sure it
> would really be of general interest and secondly, it's POC-level
> quality and I'd need to spend more time fixing it up to make it
> upstreamable, but I don't want to waste my time if not.

BTW, I've hit a warning while testing:

[ 8431.319668] ------------[ cut here ]------------
[ 8431.319678] WARNING: CPU: 0 PID: 14413 at /home/mhiramat/ksrc/linux-3/kernel/trace/ftrace.c:5080 ftrace_init_array_ops+0x6e/0x90()
[ 8431.319680] Modules linked in: xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ipt_REJECT
nf_reject_ipv4 iptable_filter ip_tables tun bridge stp llc coretemp crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel glue_helper lrw gf128mul ablk_helper cryptd iTCO_wdt
iTCO_vendor_support ipmi_si lpc_ich ipmi_msghandler mfd_core pcspkr i2c_i801 i2c_ismt shpchp acpi_cpufreq uinput sr_mod sd_mod cdrom ast syscopyarea sysfillrect sysimgblt drm_kms_helper ttm drm ahci
igb libahci libata ptp pps_core dca i2c_algo_bit i2c_core dm_mirror dm_region_hash dm_log dm_mod
[ 8431.319736] CPU: 0 PID: 14413 Comm: ftracetest Not tainted 4.1.0-rc3+ #33
[ 8431.319738] Hardware name: Supermicro A1SAi/A1SAi, BIOS 1.0b 11/06/2013
[ 8431.319741]  0000000000000000 0000000037d828fa ffff880467eabc98 ffffffff817d5b48
[ 8431.319745]  0000000000000000 0000000000000000 ffff880467eabcd8 ffffffff810c70ba
[ 8431.319748]  ffff880467eabcb8 ffffffff820a2b80 ffffffff81197330 ffffffff820a2b80
[ 8431.319752] Call Trace:
[ 8431.319760]  [<ffffffff817d5b48>] dump_stack+0x45/0x57
[ 8431.319765]  [<ffffffff810c70ba>] warn_slowpath_common+0x8a/0xc0
[ 8431.319769]  [<ffffffff81197330>] ? function_hist_open+0x20/0x20
[ 8431.319772]  [<ffffffff810c71ea>] warn_slowpath_null+0x1a/0x20
[ 8431.319776]  [<ffffffff81183efe>] ftrace_init_array_ops+0x6e/0x90
[ 8431.319779]  [<ffffffff811976d8>] function_hist_init+0x28/0x160
[ 8431.319783]  [<ffffffff811918ee>] tracing_set_tracer+0x10e/0x1b0
[ 8431.319787]  [<ffffffff8137cd8f>] ? xfs_file_buffered_aio_write+0xaf/0x240
[ 8431.319791]  [<ffffffff81191bc0>] tracing_set_trace_write+0x90/0xd0
[ 8431.319796]  [<ffffffff8123d2d7>] __vfs_write+0x37/0x110
[ 8431.319799]  [<ffffffff81240198>] ? __sb_start_write+0x58/0x100
[ 8431.319804]  [<ffffffff813d5393>] ? security_file_permission+0x23/0xa0
[ 8431.319808]  [<ffffffff8123da09>] vfs_write+0xa9/0x1b0
[ 8431.319812]  [<ffffffff810716fc>] ? do_audit_syscall_entry+0x6c/0x70
[ 8431.319816]  [<ffffffff8123e8b5>] SyS_write+0x55/0xd0
[ 8431.319821]  [<ffffffff817dd26e>] system_call_fastpath+0x12/0x71
[ 8431.319823] ---[ end trace 7f402f6ea6c9516c ]---
[ 8431.319826] ftrace ops had function_hist_call+0x0/0x150 for function

Here is the ftrace.c:5080
-----
void ftrace_init_array_ops(struct trace_array *tr, ftrace_func_t func)
{
        /* If we filter on pids, update to use the pid function */
        if (tr->flags & TRACE_ARRAY_FL_GLOBAL) {
                if (WARN_ON(tr->ops->func != ftrace_stub))		<-- here
                        printk("ftrace ops had %pS for function\n",
                               tr->ops->func);
                /* Only the top level instance does pid tracing */
                if (!list_empty(&ftrace_pids)) {
                        set_ftrace_pid_function(func);
                        func = ftrace_pid_func;
                }
        }
        tr->ops->func = func;
        tr->ops->private = tr;
}
-----

Since function_hist_call was introduced by 10/10, this warning was also
occurred by it.

Thank you,



-- 
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: masami.hiramatsu.pt@hitachi.com

Re: [PATCH v5 00/10] tracing: 'hist' triggers

[Steven Rostedt]

On Wed, 20 May 2015 16:19:47 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:


> There are a couple of important bits of functionality that were
> present in v1 but not yet reimplemented in v5.
> 

I take it that "yet" means they can still be implemented on top of v5
right? Without breaking backward compatibility of the interface?

Thanks for doing this, I'll try to get some time to look closer at the
patches.

-- Steve

Re: [PATCH v5 00/10] tracing: 'hist' triggers

[Tom Zanussi]

On Thu, 2015-05-21 at 09:55 -0400, Steven Rostedt wrote:
> On Wed, 20 May 2015 16:19:47 -0500
> Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> 
> 
> > There are a couple of important bits of functionality that were
> > present in v1 but not yet reimplemented in v5.
> > 
> 
> I take it that "yet" means they can still be implemented on top of v5
> right? Without breaking backward compatibility of the interface?
> 

Yeah, that's referring to compound keys and sorting on multiple keys.

At this point, I'm so close to having that and have previous code to
work from, so I'll just cook up a v6 without those caveats, and we don't
have to worry about it.  Give me a couple of days to get to that..

Tom


> Thanks for doing this, I'll try to get some time to look closer at the
> patches.
> 
> -- Steve

Re: [PATCH v5 00/10] tracing: 'hist' triggers

[Steven Rostedt]

On Thu, 21 May 2015 09:29:15 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> Yeah, that's referring to compound keys and sorting on multiple keys.
> 
> At this point, I'm so close to having that and have previous code to
> work from, so I'll just cook up a v6 without those caveats, and we don't
> have to worry about it.  Give me a couple of days to get to that..
> 

If theses patches are ready, and you can add those on top of this patch
series, then just do that. I'll look into applying this when I get a
chance.

If you plan on updating these patches, I'll hold off to v6 then.

-- Steve

Re: [PATCH v5 00/10] tracing: 'hist' triggers

[Tom Zanussi]

On Thu, 2015-05-21 at 10:31 -0400, Steven Rostedt wrote:
> On Thu, 21 May 2015 09:29:15 -0500
> Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> 
> > Yeah, that's referring to compound keys and sorting on multiple keys.
> > 
> > At this point, I'm so close to having that and have previous code to
> > work from, so I'll just cook up a v6 without those caveats, and we don't
> > have to worry about it.  Give me a couple of days to get to that..
> > 
> 
> If theses patches are ready, and you can add those on top of this patch
> series, then just do that. I'll look into applying this when I get a
> chance.
> 
> If you plan on updating these patches, I'll hold off to v6 then.
> 

I think I will be updating these patches, so better to hold off until v6
for now, thanks.

Tom

> -- Steve

Re: [PATCH v5 00/10] tracing: 'hist' triggers

[Tom Zanussi]

Hi Masami,

On Thu, 2015-05-21 at 17:08 +0900, Masami Hiramatsu wrote:
> Hi Tom,
> 
> On 2015/05/21 6:19, Tom Zanussi wrote:
> > This is v5 of the 'hist triggers' patchset, following feedback from
> > v4.
> > 
> > Changes from v4:
> > 
> > This version addresses some problems and suggestions made by Daniel
> > Wagner - a lot of the code was reworked to get rid of the distinction
> > between keys and values, and as a result, both keys and values can be
> > used as sort keys.  As suggested, it also allows 'val=' to be absent
> > in a trigger command - if no 'val' is specified, hitcount is assumed
> > and automatically used as the only val.
> 
> Thank you for this amazing work! :)
> Here is an example how I've used it.

Nice example - thanks for sharing it!

> 
> ---------
> [root@localhost perf]# ./perf probe -a '__kmalloc caller=$stack0 size'
> Added new event:
>   probe:__kmalloc      (on __kmalloc with caller=$stack0 size)
> 
> You can now use it in all perf tools, such as:
> 
>         perf record -e probe:__kmalloc -aR sleep 1
> 
> [root@localhost perf]# cd /sys/kernel/debug/tracing
> [root@localhost tracing]# echo hist:keys=caller.sym > events/probe/__kmalloc/trigger
> [root@localhost tracing]# echo 1 > events/probe/__kmalloc/enable
> [root@localhost tracing]# cat events/probe/__kmalloc/hist
> # trigger info: hist:keys=caller.sym:vals=hitcount:sort=hitcount:size=2048 [active]
> 
> caller: [ffffffff811964d7] tracing_map_sort_entries            hitcount:          1
> caller: [ffffffff81296120] load_elf_binary                     hitcount:          1
> caller: [ffffffff813eb98c] context_struct_to_string            hitcount:          1
> caller: [ffffffff81264c8c] simple_xattr_alloc                  hitcount:          1
> caller: [ffffffff811e0a02] shmem_initxattrs                    hitcount:          1
> caller: [ffffffff81295eb6] load_elf_phdrs                      hitcount:          2
> caller: [ffffffff8169c49b] sk_prot_alloc                       hitcount:          2
> caller: [ffffffff81395567] kmem_alloc                          hitcount:          6
> caller: [ffffffff8125b844] alloc_fdmem                         hitcount:          6
> caller: [ffffffff81415918] bio_alloc_bioset                    hitcount:          8
> caller: [ffffffff813ecc44] security_context_to_sid_core        hitcount:         17
> caller: [ffffffff812621bb] seq_buf_alloc                       hitcount:         18
> 
> Totals:
>     Hits: 64
>     Entries: 12
>     Dropped: 0
> ----------
> Good! Just one more, I also want to see the offset of the symbols. :)
> 

Sure, I could add a new 'sym-offset' modifier e.g. caller.sym-offset, or
I can just have .sym always include the offset.

> And this can dig deeper to investigate the size histogram, with filtering by caller.
> ----------
> [root@localhost tracing]# echo \!hist:keys=caller.sym > events/probe/__kmalloc/trigger
> [root@localhost tracing]# echo hist:keys=size if caller==0xffffffff812621bb > events/probe/__kmalloc/trigger
> [root@localhost tracing]# cat events/probe/__kmalloc/hist
> # trigger info: hist:keys=size:vals=hitcount:sort=hitcount:size=2048 if caller==0xffffffff812621bb [active]
> 
> size:       3024 hitcount:          1
> size:       4096 hitcount:         12
> 
> Totals:
>     Hits: 13
>     Entries: 2
>     Dropped: 0
> [root@localhost tracing]#
> ---------
> Yes! This interactivity is what I want :)
> 
> Another enhancement ideas what I want are here:
> - Named hist instance, which can be shared among several events.
>   Since probing an inlined function can make a several probe-events,
>   those need to share a histogram among them.

Makes sense - any ideas on how this would work from an interface
perspective?

Would just allowing hist="myname": ... suffice?  i.e. creating a hist
trigger with hist="myname" would look for an existing trigger with that
name - if found would use that, otherwise create a new instance with
that name... 

> - Multiple hist instances for each event, which allows us to compare
>   several histograms which have different filters.
> 

Yeah, that would be a nice enhancement - will do that when I get a
chance.

> Anyway, without above, this look fine to me :)

Great.

> > 
> > The map code was also separated out into a separate file,
> > tracing_map.c, allowing it to be reused.  It also adds a second tracer
> > called function_hist that actually does reuse the code, as an RFC
> > patch.
> > 
> > Patch 01/10 [tracing: Update cond flag when enabling or disabling..]
> > is a fix for a problem noticed by Daniel and that fixes a problem in
> > existing trigger code and should be applied regardless of whether the
> > rest of the patchset is merged.
> 
> I've reviewed that.
> 

Thanks for doing that.

> > As mentioned, patch 10/10 is an RFC patch implementing a new tracer
> > based on the function tracer code.  It's a fun little tool and is
> > useful for a specific problem I'm working on (and is also a nice test
> > of the tracing_map code), but is an RFC because first, I'm not sure it
> > would really be of general interest and secondly, it's POC-level
> > quality and I'd need to spend more time fixing it up to make it
> > upstreamable, but I don't want to waste my time if not.
> 
> BTW, I've hit a warning while testing:
> 
> [ 8431.319668] ------------[ cut here ]------------
> [ 8431.319678] WARNING: CPU: 0 PID: 14413 at /home/mhiramat/ksrc/linux-3/kernel/trace/ftrace.c:5080 ftrace_init_array_ops+0x6e/0x90()
> [ 8431.319680] Modules linked in: xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ipt_REJECT
> nf_reject_ipv4 iptable_filter ip_tables tun bridge stp llc coretemp crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel glue_helper lrw gf128mul ablk_helper cryptd iTCO_wdt
> iTCO_vendor_support ipmi_si lpc_ich ipmi_msghandler mfd_core pcspkr i2c_i801 i2c_ismt shpchp acpi_cpufreq uinput sr_mod sd_mod cdrom ast syscopyarea sysfillrect sysimgblt drm_kms_helper ttm drm ahci
> igb libahci libata ptp pps_core dca i2c_algo_bit i2c_core dm_mirror dm_region_hash dm_log dm_mod
> [ 8431.319736] CPU: 0 PID: 14413 Comm: ftracetest Not tainted 4.1.0-rc3+ #33
> [ 8431.319738] Hardware name: Supermicro A1SAi/A1SAi, BIOS 1.0b 11/06/2013
> [ 8431.319741]  0000000000000000 0000000037d828fa ffff880467eabc98 ffffffff817d5b48
> [ 8431.319745]  0000000000000000 0000000000000000 ffff880467eabcd8 ffffffff810c70ba
> [ 8431.319748]  ffff880467eabcb8 ffffffff820a2b80 ffffffff81197330 ffffffff820a2b80
> [ 8431.319752] Call Trace:
> [ 8431.319760]  [<ffffffff817d5b48>] dump_stack+0x45/0x57
> [ 8431.319765]  [<ffffffff810c70ba>] warn_slowpath_common+0x8a/0xc0
> [ 8431.319769]  [<ffffffff81197330>] ? function_hist_open+0x20/0x20
> [ 8431.319772]  [<ffffffff810c71ea>] warn_slowpath_null+0x1a/0x20
> [ 8431.319776]  [<ffffffff81183efe>] ftrace_init_array_ops+0x6e/0x90
> [ 8431.319779]  [<ffffffff811976d8>] function_hist_init+0x28/0x160
> [ 8431.319783]  [<ffffffff811918ee>] tracing_set_tracer+0x10e/0x1b0
> [ 8431.319787]  [<ffffffff8137cd8f>] ? xfs_file_buffered_aio_write+0xaf/0x240
> [ 8431.319791]  [<ffffffff81191bc0>] tracing_set_trace_write+0x90/0xd0
> [ 8431.319796]  [<ffffffff8123d2d7>] __vfs_write+0x37/0x110
> [ 8431.319799]  [<ffffffff81240198>] ? __sb_start_write+0x58/0x100
> [ 8431.319804]  [<ffffffff813d5393>] ? security_file_permission+0x23/0xa0
> [ 8431.319808]  [<ffffffff8123da09>] vfs_write+0xa9/0x1b0
> [ 8431.319812]  [<ffffffff810716fc>] ? do_audit_syscall_entry+0x6c/0x70
> [ 8431.319816]  [<ffffffff8123e8b5>] SyS_write+0x55/0xd0
> [ 8431.319821]  [<ffffffff817dd26e>] system_call_fastpath+0x12/0x71
> [ 8431.319823] ---[ end trace 7f402f6ea6c9516c ]---
> [ 8431.319826] ftrace ops had function_hist_call+0x0/0x150 for function
> 
> Here is the ftrace.c:5080
> -----
> void ftrace_init_array_ops(struct trace_array *tr, ftrace_func_t func)
> {
>         /* If we filter on pids, update to use the pid function */
>         if (tr->flags & TRACE_ARRAY_FL_GLOBAL) {
>                 if (WARN_ON(tr->ops->func != ftrace_stub))		<-- here
>                         printk("ftrace ops had %pS for function\n",
>                                tr->ops->func);
>                 /* Only the top level instance does pid tracing */
>                 if (!list_empty(&ftrace_pids)) {
>                         set_ftrace_pid_function(func);
>                         func = ftrace_pid_func;
>                 }
>         }
>         tr->ops->func = func;
>         tr->ops->private = tr;
> }
> -----
> 
> Since function_hist_call was introduced by 10/10, this warning was also
> occurred by it.
> 

Right, why it's an RFC ;-)  I need to look some more at the ftrace code
and figure out how to hook it up properly...

Thanks,

Tom

> Thank you,
> 
> 
> 

Re: [PATCH v5 00/10] tracing: 'hist' triggers

[Masami Hiramatsu]

On 2015/05/22 0:26, Tom Zanussi wrote:
> Hi Masami,
> 
> On Thu, 2015-05-21 at 17:08 +0900, Masami Hiramatsu wrote:
>> Hi Tom,
>>
>> On 2015/05/21 6:19, Tom Zanussi wrote:
>>> This is v5 of the 'hist triggers' patchset, following feedback from
>>> v4.
>>>
>>> Changes from v4:
>>>
>>> This version addresses some problems and suggestions made by Daniel
>>> Wagner - a lot of the code was reworked to get rid of the distinction
>>> between keys and values, and as a result, both keys and values can be
>>> used as sort keys.  As suggested, it also allows 'val=' to be absent
>>> in a trigger command - if no 'val' is specified, hitcount is assumed
>>> and automatically used as the only val.
>>
>> Thank you for this amazing work! :)
>> Here is an example how I've used it.
> 
> Nice example - thanks for sharing it!
> 
>>
>> ---------
>> [root@localhost perf]# ./perf probe -a '__kmalloc caller=$stack0 size'
>> Added new event:
>>   probe:__kmalloc      (on __kmalloc with caller=$stack0 size)
>>
>> You can now use it in all perf tools, such as:
>>
>>         perf record -e probe:__kmalloc -aR sleep 1
>>
>> [root@localhost perf]# cd /sys/kernel/debug/tracing
>> [root@localhost tracing]# echo hist:keys=caller.sym > events/probe/__kmalloc/trigger
>> [root@localhost tracing]# echo 1 > events/probe/__kmalloc/enable
>> [root@localhost tracing]# cat events/probe/__kmalloc/hist
>> # trigger info: hist:keys=caller.sym:vals=hitcount:sort=hitcount:size=2048 [active]
>>
>> caller: [ffffffff811964d7] tracing_map_sort_entries            hitcount:          1
>> caller: [ffffffff81296120] load_elf_binary                     hitcount:          1
>> caller: [ffffffff813eb98c] context_struct_to_string            hitcount:          1
>> caller: [ffffffff81264c8c] simple_xattr_alloc                  hitcount:          1
>> caller: [ffffffff811e0a02] shmem_initxattrs                    hitcount:          1
>> caller: [ffffffff81295eb6] load_elf_phdrs                      hitcount:          2
>> caller: [ffffffff8169c49b] sk_prot_alloc                       hitcount:          2
>> caller: [ffffffff81395567] kmem_alloc                          hitcount:          6
>> caller: [ffffffff8125b844] alloc_fdmem                         hitcount:          6
>> caller: [ffffffff81415918] bio_alloc_bioset                    hitcount:          8
>> caller: [ffffffff813ecc44] security_context_to_sid_core        hitcount:         17
>> caller: [ffffffff812621bb] seq_buf_alloc                       hitcount:         18
>>
>> Totals:
>>     Hits: 64
>>     Entries: 12
>>     Dropped: 0
>> ----------
>> Good! Just one more, I also want to see the offset of the symbols. :)
>>
> 
> Sure, I could add a new 'sym-offset' modifier e.g. caller.sym-offset, or
> I can just have .sym always include the offset.

Hmm, can we reuse ftrace's options? We already have options/sym-offset and
options/sym-addr under debugfs/tracing/. E.g.

# options/sym-offset=0 options/sym-addr=0
caller: seq_buf_alloc

# options/sym-offset=0 options/sym-addr=1
caller: [ffffffff812621bb] seq_buf_alloc

# options/sym-offset=1 options/sym-addr=0
caller: seq_buf_alloc+0x1b

# options/sym-offset=1 options/sym-addr=1
caller: [ffffffff812621bb] seq_buf_alloc+0x1b

> 
>> And this can dig deeper to investigate the size histogram, with filtering by caller.
>> ----------
>> [root@localhost tracing]# echo \!hist:keys=caller.sym > events/probe/__kmalloc/trigger
>> [root@localhost tracing]# echo hist:keys=size if caller==0xffffffff812621bb > events/probe/__kmalloc/trigger
>> [root@localhost tracing]# cat events/probe/__kmalloc/hist
>> # trigger info: hist:keys=size:vals=hitcount:sort=hitcount:size=2048 if caller==0xffffffff812621bb [active]
>>
>> size:       3024 hitcount:          1
>> size:       4096 hitcount:         12
>>
>> Totals:
>>     Hits: 13
>>     Entries: 2
>>     Dropped: 0
>> [root@localhost tracing]#
>> ---------
>> Yes! This interactivity is what I want :)
>>
>> Another enhancement ideas what I want are here:
>> - Named hist instance, which can be shared among several events.
>>   Since probing an inlined function can make a several probe-events,
>>   those need to share a histogram among them.
> 
> Makes sense - any ideas on how this would work from an interface
> perspective?
> 
> Would just allowing hist="myname": ... suffice?  i.e. creating a hist
> trigger with hist="myname" would look for an existing trigger with that
> name - if found would use that, otherwise create a new instance with
> that name... 

Yeah, that looks good to me :)

>> - Multiple hist instances for each event, which allows us to compare
>>   several histograms which have different filters.
>>
> 
> Yeah, that would be a nice enhancement - will do that when I get a
> chance.
> 
>> Anyway, without above, this look fine to me :)
> 
> Great.
> 
>>>
>>> The map code was also separated out into a separate file,
>>> tracing_map.c, allowing it to be reused.  It also adds a second tracer
>>> called function_hist that actually does reuse the code, as an RFC
>>> patch.
>>>
>>> Patch 01/10 [tracing: Update cond flag when enabling or disabling..]
>>> is a fix for a problem noticed by Daniel and that fixes a problem in
>>> existing trigger code and should be applied regardless of whether the
>>> rest of the patchset is merged.
>>
>> I've reviewed that.
>>
> 
> Thanks for doing that.
> 
>>> As mentioned, patch 10/10 is an RFC patch implementing a new tracer
>>> based on the function tracer code.  It's a fun little tool and is
>>> useful for a specific problem I'm working on (and is also a nice test
>>> of the tracing_map code), but is an RFC because first, I'm not sure it
>>> would really be of general interest and secondly, it's POC-level
>>> quality and I'd need to spend more time fixing it up to make it
>>> upstreamable, but I don't want to waste my time if not.
>>
>> BTW, I've hit a warning while testing:
>>
>> [ 8431.319668] ------------[ cut here ]------------
>> [ 8431.319678] WARNING: CPU: 0 PID: 14413 at /home/mhiramat/ksrc/linux-3/kernel/trace/ftrace.c:5080 ftrace_init_array_ops+0x6e/0x90()
>> [ 8431.319680] Modules linked in: xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack ipt_REJECT
>> nf_reject_ipv4 iptable_filter ip_tables tun bridge stp llc coretemp crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel glue_helper lrw gf128mul ablk_helper cryptd iTCO_wdt
>> iTCO_vendor_support ipmi_si lpc_ich ipmi_msghandler mfd_core pcspkr i2c_i801 i2c_ismt shpchp acpi_cpufreq uinput sr_mod sd_mod cdrom ast syscopyarea sysfillrect sysimgblt drm_kms_helper ttm drm ahci
>> igb libahci libata ptp pps_core dca i2c_algo_bit i2c_core dm_mirror dm_region_hash dm_log dm_mod
>> [ 8431.319736] CPU: 0 PID: 14413 Comm: ftracetest Not tainted 4.1.0-rc3+ #33
>> [ 8431.319738] Hardware name: Supermicro A1SAi/A1SAi, BIOS 1.0b 11/06/2013
>> [ 8431.319741]  0000000000000000 0000000037d828fa ffff880467eabc98 ffffffff817d5b48
>> [ 8431.319745]  0000000000000000 0000000000000000 ffff880467eabcd8 ffffffff810c70ba
>> [ 8431.319748]  ffff880467eabcb8 ffffffff820a2b80 ffffffff81197330 ffffffff820a2b80
>> [ 8431.319752] Call Trace:
>> [ 8431.319760]  [<ffffffff817d5b48>] dump_stack+0x45/0x57
>> [ 8431.319765]  [<ffffffff810c70ba>] warn_slowpath_common+0x8a/0xc0
>> [ 8431.319769]  [<ffffffff81197330>] ? function_hist_open+0x20/0x20
>> [ 8431.319772]  [<ffffffff810c71ea>] warn_slowpath_null+0x1a/0x20
>> [ 8431.319776]  [<ffffffff81183efe>] ftrace_init_array_ops+0x6e/0x90
>> [ 8431.319779]  [<ffffffff811976d8>] function_hist_init+0x28/0x160
>> [ 8431.319783]  [<ffffffff811918ee>] tracing_set_tracer+0x10e/0x1b0
>> [ 8431.319787]  [<ffffffff8137cd8f>] ? xfs_file_buffered_aio_write+0xaf/0x240
>> [ 8431.319791]  [<ffffffff81191bc0>] tracing_set_trace_write+0x90/0xd0
>> [ 8431.319796]  [<ffffffff8123d2d7>] __vfs_write+0x37/0x110
>> [ 8431.319799]  [<ffffffff81240198>] ? __sb_start_write+0x58/0x100
>> [ 8431.319804]  [<ffffffff813d5393>] ? security_file_permission+0x23/0xa0
>> [ 8431.319808]  [<ffffffff8123da09>] vfs_write+0xa9/0x1b0
>> [ 8431.319812]  [<ffffffff810716fc>] ? do_audit_syscall_entry+0x6c/0x70
>> [ 8431.319816]  [<ffffffff8123e8b5>] SyS_write+0x55/0xd0
>> [ 8431.319821]  [<ffffffff817dd26e>] system_call_fastpath+0x12/0x71
>> [ 8431.319823] ---[ end trace 7f402f6ea6c9516c ]---
>> [ 8431.319826] ftrace ops had function_hist_call+0x0/0x150 for function
>>
>> Here is the ftrace.c:5080
>> -----
>> void ftrace_init_array_ops(struct trace_array *tr, ftrace_func_t func)
>> {
>>         /* If we filter on pids, update to use the pid function */
>>         if (tr->flags & TRACE_ARRAY_FL_GLOBAL) {
>>                 if (WARN_ON(tr->ops->func != ftrace_stub))		<-- here
>>                         printk("ftrace ops had %pS for function\n",
>>                                tr->ops->func);
>>                 /* Only the top level instance does pid tracing */
>>                 if (!list_empty(&ftrace_pids)) {
>>                         set_ftrace_pid_function(func);
>>                         func = ftrace_pid_func;
>>                 }
>>         }
>>         tr->ops->func = func;
>>         tr->ops->private = tr;
>> }
>> -----
>>
>> Since function_hist_call was introduced by 10/10, this warning was also
>> occurred by it.
>>
> 
> Right, why it's an RFC ;-)  I need to look some more at the ftrace code
> and figure out how to hook it up properly...

Thank you!

-- 
Masami HIRAMATSU
Linux Technology Research Center, System Productivity Research Dept.
Center for Technology Innovation - Systems Engineering
Hitachi, Ltd., Research & Development Group
E-mail: masami.hiramatsu.pt@hitachi.com