All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH v3 00/14] tracing: Add triggers to trace_marker writes
@ 2018-05-16 15:00 Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 01/14] tracing: Do not reference event data in post call triggers Steven Rostedt
                   ` (14 more replies)
  0 siblings, 15 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

A few people have asked for this in the past, and I finally got around
to implementing it. What this does is to allow writes into trace_marker
to initiate a trigger.

The trace_marker event is described in:

 tracefs/events/ftrace/print

Thus the trigger file is added there:

 tracefs/events/ftrace/print/trigger

As there's already a "hist" file there, everything appears to work
just like any other trigger to an event. See the last patch for
documentation on how to use the triggers to a trace_marker write.

By the way, the patch:

  tracing: Prevent further users of zero size static arrays in trace events

May prevent your kernel from building if you include Xen. You will need
to add this patch to make it work (or include the git repo below).

 http://lkml.kernel.org/r/20180509144605.5a220327@gandalf.local.home


  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
ftrace/core

Head SHA1: dded7b759602085b4bd2c5581f58f6b179912d89


Steven Rostedt (VMware) (14):
      tracing: Do not reference event data in post call triggers
      tracing: Add __find_event_file() to find event files without restrictions
      tracing: Have event_trace_init() called by trace_init_tracefs()
      tracing: Add brackets in ftrace event dynamic arrays
      tracing: Do not show filter file for ftrace internal events
      tracing: Add trigger file for trace_markers tracefs/ftrace/print
      tracing: Have zero size length in filter logic be full string
      tracing: Prevent further users of zero size static arrays in trace events
      tracing: Allow histogram triggers to access ftrace internal events
      tracing: Document trace_marker triggers
      ftrace/selftest: Have the reset_trigger code be a bit more careful
      ftrace/selftest: Fix reset_trigger() to handle triggers with filters
      tracing/selftest: Add selftests to test trace_marker histogram triggers
      tracing/selftest: Add test to test hist trigger between kernel event and trace_marker

----
Changes since v2:

 - typo fixes in documentation (Tom Zanussi)
 - Rename trigger-trace-marker{-hist} in selftest (Masami Hiramatsu)
 - Fix onmatch(sched.sched_waking) (Namhyung Kim)
 - Rename test to say trace_marker trigger from event trigger (Steven Rostedt)

 Diff from v2 below.

 Documentation/trace/events.rst                     |   6 +-
 Documentation/trace/ftrace.rst                     |   5 +
 Documentation/trace/histogram.txt                  | 546 ++++++++++++++++++++-
 include/linux/trace_events.h                       |   3 +-
 include/trace/trace_events.h                       |   1 +
 kernel/trace/trace.c                               |  19 +
 kernel/trace/trace.h                               |   9 +-
 kernel/trace/trace_entries.h                       |   6 +-
 kernel/trace/trace_events.c                        |  36 +-
 kernel/trace/trace_events_filter.c                 |  23 +-
 kernel/trace/trace_events_hist.c                   |   2 +-
 kernel/trace/trace_events_trigger.c                |   6 +-
 kernel/trace/trace_export.c                        |   9 +-
 tools/testing/selftests/ftrace/test.d/functions    |  23 +-
 .../test.d/trigger/trigger-trace-marker-hist.tc    |  49 ++
 .../trigger/trigger-trace-marker-synthetic.tc      |  88 ++++
 16 files changed, 790 insertions(+), 41 deletions(-)
 create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
 create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc


diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt
index 8c871f0c0e33..ae2d4f9d0a62 100644
--- a/Documentation/trace/histogram.txt
+++ b/Documentation/trace/histogram.txt
@@ -2005,7 +2005,7 @@ and after it wakes up, something like this:
 
 static void traceputs(char *str)
 {
-	/* tracemark_fd is the trace_marker file descripto */
+	/* tracemark_fd is the trace_marker file descriptor */
 	if (tracemark_fd < 0)
 		return;
 	/* write the tracemark message */
@@ -2048,7 +2048,7 @@ Now running cyclictest with:
 
 Note, the -b 1000 is used just to make --tracemark available.
 
-The we can see the histogram created by this with:
+Then we can see the histogram created by this with:
 
  # cat events/synthetic/latency/hist
 # event histogram
@@ -2360,7 +2360,7 @@ kernel with trace_marker.
 
 The difference this time is that instead of using the trace_marker to start
 the latency, the sched_waking event is used, matching the common_pid for the
-trace_marker write with the pid that is being worken by sched_waking.
+trace_marker write with the pid that is being woken by sched_waking.
 
 After running cyclictest again with the same parameters, we now have:
 
@@ -2535,5 +2535,5 @@ Totals:
     Dropped: 0
 
 This doesn't tell us any information about how late cyclictest may have
-worken up, but it does show us a nice histogram of how long it took from
-the time that cyclictest was worken to the time it made it into user space.
+woken up, but it does show us a nice histogram of how long it took from
+the time that cyclictest was woken to the time it made it into user space.
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
similarity index 93%
rename from tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker.tc
rename to tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
index 48e7ac1ccbc1..2acbfe2c0c0c 100644
--- a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker.tc
+++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
@@ -1,6 +1,6 @@
 #!/bin/sh
 # SPDX-License-Identifier: GPL-2.0
-# description: event trigger - test histogram trigger
+# description: trace_marker trigger - test histogram trigger
 # flags: instance
 
 do_reset() {
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
index d8cfc36f228b..b06996ecd5e0 100644
--- a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
+++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
@@ -1,6 +1,6 @@
 #!/bin/sh
 # SPDX-License-Identifier: GPL-2.0
-# description: event trigger - test histogram with synthetic event
+# description: trace_marker trigger - test histogram with synthetic event
 # flags:
 
 do_reset() {
@@ -72,7 +72,7 @@ echo "Test histogram kernel event to trace_marker latency histogram trigger"
 
 echo 'latency u64 lat' > synthetic_events
 echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
-echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat)' > events/ftrace/print/trigger
+echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat)' > events/ftrace/print/trigger
 echo 'hist:keys=common_pid,lat:sort=lat' > events/synthetic/latency/trigger
 sleep 1
 echo "hello" > trace_marker

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 01/14] tracing: Do not reference event data in post call triggers
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 02/14] tracing: Add __find_event_file() to find event files without restrictions Steven Rostedt
                   ` (13 subsequent siblings)
  14 siblings, 0 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

[-- Attachment #1: 0001-tracing-Do-not-reference-event-data-in-post-call-tri.patch --]
[-- Type: text/plain, Size: 3605 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Trace event triggers can be called before or after the event has been
committed. If it has been called after the commit, there's a possibility
that the event no longer exists. Currently, the two post callers is the
trigger to disable tracing (traceoff) and the one that will record a stack
dump (stacktrace). Neither of them reference the trace event entry record,
as that would lead to a race condition that could pass in corrupted data.

To prevent any other users of the post data triggers from using the trace
event record, pass in NULL to the post call trigger functions for the event
record, as they should never need to use them in the first place.

This does not fix any bug, but prevents bugs from happening by new post call
trigger users.

Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 include/linux/trace_events.h        | 3 +--
 kernel/trace/trace.h                | 4 ++--
 kernel/trace/trace_events_trigger.c | 6 ++----
 3 files changed, 5 insertions(+), 8 deletions(-)

diff --git a/include/linux/trace_events.h b/include/linux/trace_events.h
index 2bde3eff564c..d1c442d9bd85 100644
--- a/include/linux/trace_events.h
+++ b/include/linux/trace_events.h
@@ -435,8 +435,7 @@ event_triggers_call(struct trace_event_file *file, void *rec,
 		    struct ring_buffer_event *event);
 extern void
 event_triggers_post_call(struct trace_event_file *file,
-			 enum event_trigger_type tt,
-			 void *rec, struct ring_buffer_event *event);
+			 enum event_trigger_type tt);
 
 bool trace_event_ignore_this_pid(struct trace_event_file *trace_file);
 
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 6fb46a06c9dc..24b666891eaf 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1334,7 +1334,7 @@ event_trigger_unlock_commit(struct trace_event_file *file,
 		trace_buffer_unlock_commit(file->tr, buffer, event, irq_flags, pc);
 
 	if (tt)
-		event_triggers_post_call(file, tt, entry, event);
+		event_triggers_post_call(file, tt);
 }
 
 /**
@@ -1367,7 +1367,7 @@ event_trigger_unlock_commit_regs(struct trace_event_file *file,
 						irq_flags, pc, regs);
 
 	if (tt)
-		event_triggers_post_call(file, tt, entry, event);
+		event_triggers_post_call(file, tt);
 }
 
 #define FILTER_PRED_INVALID	((unsigned short)-1)
diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
index d251cabcf69a..cc4148bfc01a 100644
--- a/kernel/trace/trace_events_trigger.c
+++ b/kernel/trace/trace_events_trigger.c
@@ -97,7 +97,6 @@ EXPORT_SYMBOL_GPL(event_triggers_call);
  * event_triggers_post_call - Call 'post_triggers' for a trace event
  * @file: The trace_event_file associated with the event
  * @tt: enum event_trigger_type containing a set bit for each trigger to invoke
- * @rec: The trace entry for the event
  *
  * For each trigger associated with an event, invoke the trigger
  * function registered with the associated trigger command, if the
@@ -108,8 +107,7 @@ EXPORT_SYMBOL_GPL(event_triggers_call);
  */
 void
 event_triggers_post_call(struct trace_event_file *file,
-			 enum event_trigger_type tt,
-			 void *rec, struct ring_buffer_event *event)
+			 enum event_trigger_type tt)
 {
 	struct event_trigger_data *data;
 
@@ -117,7 +115,7 @@ event_triggers_post_call(struct trace_event_file *file,
 		if (data->paused)
 			continue;
 		if (data->cmd_ops->trigger_type & tt)
-			data->ops->func(data, rec, event);
+			data->ops->func(data, NULL, NULL);
 	}
 }
 EXPORT_SYMBOL_GPL(event_triggers_post_call);
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 02/14] tracing: Add __find_event_file() to find event files without restrictions
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 01/14] tracing: Do not reference event data in post call triggers Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 03/14] tracing: Have event_trace_init() called by trace_init_tracefs() Steven Rostedt
                   ` (12 subsequent siblings)
  14 siblings, 0 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

[-- Attachment #1: 0002-tracing-Add-__find_event_file-to-find-event-files-wi.patch --]
[-- Type: text/plain, Size: 2943 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

By adding the function __find_event_file() that can search for files without
restrictions, such as if the event associated with the file has a reg
function, or if it has the "ignore" flag set, the files that are associated
to ftrace internal events (like trace_marker and function events) can be
found and used.

find_event_file() still returns a "filtered" file, as most callers need a
valid trace event file. One created by the trace_events.h macros and not one
created for parsing ftrace specific events.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/trace.h        |  3 +++
 kernel/trace/trace_events.c | 22 +++++++++++++++++-----
 2 files changed, 20 insertions(+), 5 deletions(-)

diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 24b666891eaf..8ecca43d6aea 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1454,6 +1454,9 @@ extern void trace_event_enable_tgid_record(bool enable);
 extern int event_trace_add_tracer(struct dentry *parent, struct trace_array *tr);
 extern int event_trace_del_tracer(struct trace_array *tr);
 
+extern struct trace_event_file *__find_event_file(struct trace_array *tr,
+						  const char *system,
+						  const char *event);
 extern struct trace_event_file *find_event_file(struct trace_array *tr,
 						const char *system,
 						const char *event);
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 05c7172c6667..caf76355f0a3 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -2473,8 +2473,9 @@ __trace_add_event_dirs(struct trace_array *tr)
 	}
 }
 
+/* Returns any file that matches the system and event */
 struct trace_event_file *
-find_event_file(struct trace_array *tr, const char *system,  const char *event)
+__find_event_file(struct trace_array *tr, const char *system, const char *event)
 {
 	struct trace_event_file *file;
 	struct trace_event_call *call;
@@ -2485,10 +2486,7 @@ find_event_file(struct trace_array *tr, const char *system,  const char *event)
 		call = file->event_call;
 		name = trace_event_name(call);
 
-		if (!name || !call->class || !call->class->reg)
-			continue;
-
-		if (call->flags & TRACE_EVENT_FL_IGNORE_ENABLE)
+		if (!name || !call->class)
 			continue;
 
 		if (strcmp(event, name) == 0 &&
@@ -2498,6 +2496,20 @@ find_event_file(struct trace_array *tr, const char *system,  const char *event)
 	return NULL;
 }
 
+/* Returns valid trace event files that match system and event */
+struct trace_event_file *
+find_event_file(struct trace_array *tr, const char *system, const char *event)
+{
+	struct trace_event_file *file;
+
+	file = __find_event_file(tr, system, event);
+	if (!file || !file->event_call->class->reg ||
+	    file->event_call->flags & TRACE_EVENT_FL_IGNORE_ENABLE)
+		return NULL;
+
+	return file;
+}
+
 #ifdef CONFIG_DYNAMIC_FTRACE
 
 /* Avoid typos */
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 03/14] tracing: Have event_trace_init() called by trace_init_tracefs()
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 01/14] tracing: Do not reference event data in post call triggers Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 02/14] tracing: Add __find_event_file() to find event files without restrictions Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 04/14] tracing: Add brackets in ftrace event dynamic arrays Steven Rostedt
                   ` (11 subsequent siblings)
  14 siblings, 0 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

[-- Attachment #1: 0003-tracing-Have-event_trace_init-called-by-trace_init_t.patch --]
[-- Type: text/plain, Size: 2231 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Instead of having both trace_init_tracefs() and event_trace_init() be called
by fs_initcall() routines, have event_trace_init() called directly by
trace_init_tracefs(). This will guarantee order of how the events are
created with respect to the rest of the ftrace infrastructure. This is
needed to be able to assoctiate event files with ftrace internal events,
such as the trace_marker.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/trace.c        | 2 ++
 kernel/trace/trace.h        | 1 +
 kernel/trace/trace_events.c | 4 +---
 3 files changed, 4 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 414d7210b2ec..e0d6ffb76985 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -8111,6 +8111,8 @@ static __init int tracer_init_tracefs(void)
 	if (IS_ERR(d_tracer))
 		return 0;
 
+	event_trace_init();
+
 	init_tracer_tracefs(&global_trace, d_tracer);
 	ftrace_init_tracefs_toplevel(&global_trace, d_tracer);
 
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 8ecca43d6aea..2414fd72dedd 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1451,6 +1451,7 @@ trace_find_event_field(struct trace_event_call *call, char *name);
 extern void trace_event_enable_cmd_record(bool enable);
 extern void trace_event_enable_tgid_record(bool enable);
 
+extern int event_trace_init(void);
 extern int event_trace_add_tracer(struct dentry *parent, struct trace_array *tr);
 extern int event_trace_del_tracer(struct trace_array *tr);
 
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index caf76355f0a3..5b647904a65b 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -3144,7 +3144,7 @@ static __init int event_trace_enable_again(void)
 
 early_initcall(event_trace_enable_again);
 
-static __init int event_trace_init(void)
+__init int event_trace_init(void)
 {
 	struct trace_array *tr;
 	struct dentry *d_tracer;
@@ -3189,8 +3189,6 @@ void __init trace_event_init(void)
 	event_trace_enable();
 }
 
-fs_initcall(event_trace_init);
-
 #ifdef CONFIG_FTRACE_STARTUP_TEST
 
 static DEFINE_SPINLOCK(test_spinlock);
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 04/14] tracing: Add brackets in ftrace event dynamic arrays
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
                   ` (2 preceding siblings ...)
  2018-05-16 15:00 ` [PATCH v3 03/14] tracing: Have event_trace_init() called by trace_init_tracefs() Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 05/14] tracing: Do not show filter file for ftrace internal events Steven Rostedt
                   ` (10 subsequent siblings)
  14 siblings, 0 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

[-- Attachment #1: 0004-tracing-Add-brackets-in-ftrace-event-dynamic-arrays.patch --]
[-- Type: text/plain, Size: 1121 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

The dynamic arrays defined for ftrace internal events, such as the buf field
for trace_marker (ftrace/print) did not have brackets which makes the filter
code not accept it as a string. This is not currently an issues because the
filter code doesn't do anything for these events, but they will in the
future, and this needs to be fixed for when it does.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/trace_export.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/trace/trace_export.c b/kernel/trace/trace_export.c
index 548e62eb5c46..d842f1eadfe5 100644
--- a/kernel/trace/trace_export.c
+++ b/kernel/trace/trace_export.c
@@ -117,7 +117,7 @@ static void __always_unused ____ftrace_check_##name(void)		\
 
 #undef __dynamic_array
 #define __dynamic_array(type, item)					\
-	ret = trace_define_field(event_call, #type, #item,		\
+	ret = trace_define_field(event_call, #type "[]", #item,  \
 				 offsetof(typeof(field), item),		\
 				 0, is_signed_type(type), filter_type);\
 	if (ret)							\
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 05/14] tracing: Do not show filter file for ftrace internal events
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
                   ` (3 preceding siblings ...)
  2018-05-16 15:00 ` [PATCH v3 04/14] tracing: Add brackets in ftrace event dynamic arrays Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 06/14] tracing: Add trigger file for trace_markers tracefs/ftrace/print Steven Rostedt
                   ` (9 subsequent siblings)
  14 siblings, 0 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

[-- Attachment #1: 0005-tracing-Do-not-show-filter-file-for-ftrace-internal-.patch --]
[-- Type: text/plain, Size: 1394 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

The filter file in the ftrace internal events, like in
/sys/kernel/tracing/events/ftrace/function/filter is not attached to any
functionality. Do not create them as they are meaningless.

In the future, if an ftrace internal event gets filter functionality, then
it will need to create it directly.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/trace_events.c | 10 ++++++----
 1 file changed, 6 insertions(+), 4 deletions(-)

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 5b647904a65b..14ff4ff3caab 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -2007,16 +2007,18 @@ event_create_dir(struct dentry *parent, struct trace_event_file *file)
 			return -1;
 		}
 	}
-	trace_create_file("filter", 0644, file->dir, file,
-			  &ftrace_event_filter_fops);
 
 	/*
 	 * Only event directories that can be enabled should have
-	 * triggers.
+	 * triggers or filters.
 	 */
-	if (!(call->flags & TRACE_EVENT_FL_IGNORE_ENABLE))
+	if (!(call->flags & TRACE_EVENT_FL_IGNORE_ENABLE)) {
+		trace_create_file("filter", 0644, file->dir, file,
+				  &ftrace_event_filter_fops);
+
 		trace_create_file("trigger", 0644, file->dir, file,
 				  &event_trigger_fops);
+	}
 
 #ifdef CONFIG_HIST_TRIGGERS
 	trace_create_file("hist", 0444, file->dir, file,
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 06/14] tracing: Add trigger file for trace_markers tracefs/ftrace/print
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
                   ` (4 preceding siblings ...)
  2018-05-16 15:00 ` [PATCH v3 05/14] tracing: Do not show filter file for ftrace internal events Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 07/14] tracing: Have zero size length in filter logic be full string Steven Rostedt
                   ` (8 subsequent siblings)
  14 siblings, 0 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users,
	Joel Fernandes

[-- Attachment #1: 0006-tracing-Add-trigger-file-for-trace_markers-tracefs-f.patch --]
[-- Type: text/plain, Size: 4820 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Allow writing to the trace_markers file initiate triggers defined in
tracefs/ftrace/print/trigger file. This will allow of user space to trigger
the same type of triggers (including histograms) that the trace events use.

Had to create a ftrace_event_register() function that will become the
trace_marker print event's reg() function. This is required because of how
triggers are enabled:

  event_trigger_write() {
    event_trigger_regex_write() {
      trigger_process_regex() {
        for p in trigger_commands {
          p->func(); /* trigger_snapshot_cmd->func */
            event_trigger_callback() {
              cmd_ops->reg() /* register_trigger() */ {
                trace_event_trigger_enable_disable() {
                  trace_event_enable_disable() {
                    call->class->reg();

Without the reg() function, the trigger code will call a NULL pointer and
crash the system.

Cc: Tom Zanussi <tom.zanussi@linux.intel.com>
Cc: Clark Williams <williams@redhat.com>
Cc: Karim Yaghmour <karim.yaghmour@opersys.com>
Cc: Brendan Gregg <bgregg@netflix.com>
Suggested-by: Joel Fernandes <joelaf@google.com>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/trace.c         | 17 +++++++++++++++++
 kernel/trace/trace.h         |  1 +
 kernel/trace/trace_entries.h |  6 ++++--
 kernel/trace/trace_export.c  |  7 +++++++
 4 files changed, 29 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index e0d6ffb76985..f11b89fa5049 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -6074,6 +6074,7 @@ tracing_mark_write(struct file *filp, const char __user *ubuf,
 {
 	struct trace_array *tr = filp->private_data;
 	struct ring_buffer_event *event;
+	enum event_trigger_type tt = ETT_NONE;
 	struct ring_buffer *buffer;
 	struct print_entry *entry;
 	unsigned long irq_flags;
@@ -6122,6 +6123,12 @@ tracing_mark_write(struct file *filp, const char __user *ubuf,
 		written = cnt;
 	len = cnt;
 
+	if (tr->trace_marker_file && !list_empty(&tr->trace_marker_file->triggers)) {
+		/* do not add \n before testing triggers, but add \0 */
+		entry->buf[cnt] = '\0';
+		tt = event_triggers_call(tr->trace_marker_file, entry, event);
+	}
+
 	if (entry->buf[cnt - 1] != '\n') {
 		entry->buf[cnt] = '\n';
 		entry->buf[cnt + 1] = '\0';
@@ -6130,6 +6137,9 @@ tracing_mark_write(struct file *filp, const char __user *ubuf,
 
 	__buffer_unlock_commit(buffer, event);
 
+	if (tt)
+		event_triggers_post_call(tr->trace_marker_file, tt);
+
 	if (written > 0)
 		*fpos += written;
 
@@ -7896,6 +7906,7 @@ static __init void create_trace_instances(struct dentry *d_tracer)
 static void
 init_tracer_tracefs(struct trace_array *tr, struct dentry *d_tracer)
 {
+	struct trace_event_file *file;
 	int cpu;
 
 	trace_create_file("available_tracers", 0444, d_tracer,
@@ -7928,6 +7939,12 @@ init_tracer_tracefs(struct trace_array *tr, struct dentry *d_tracer)
 	trace_create_file("trace_marker", 0220, d_tracer,
 			  tr, &tracing_mark_fops);
 
+	file = __find_event_file(tr, "ftrace", "print");
+	if (file && file->dir)
+		trace_create_file("trigger", 0644, file->dir, file,
+				  &event_trigger_fops);
+	tr->trace_marker_file = file;
+
 	trace_create_file("trace_marker_raw", 0220, d_tracer,
 			  tr, &tracing_mark_raw_fops);
 
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 2414fd72dedd..c7fa58d31a84 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -259,6 +259,7 @@ struct trace_array {
 	struct trace_options	*topts;
 	struct list_head	systems;
 	struct list_head	events;
+	struct trace_event_file *trace_marker_file;
 	cpumask_var_t		tracing_cpumask; /* only trace on set CPUs */
 	int			ref;
 #ifdef CONFIG_FUNCTION_TRACER
diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h
index e3a658bac10f..1d67464ed95e 100644
--- a/kernel/trace/trace_entries.h
+++ b/kernel/trace/trace_entries.h
@@ -230,7 +230,7 @@ FTRACE_ENTRY(bprint, bprint_entry,
 	FILTER_OTHER
 );
 
-FTRACE_ENTRY(print, print_entry,
+FTRACE_ENTRY_REG(print, print_entry,
 
 	TRACE_PRINT,
 
@@ -242,7 +242,9 @@ FTRACE_ENTRY(print, print_entry,
 	F_printk("%ps: %s",
 		 (void *)__entry->ip, __entry->buf),
 
-	FILTER_OTHER
+	FILTER_OTHER,
+
+	ftrace_event_register
 );
 
 FTRACE_ENTRY(raw_data, raw_data_entry,
diff --git a/kernel/trace/trace_export.c b/kernel/trace/trace_export.c
index d842f1eadfe5..45630a76ed3a 100644
--- a/kernel/trace/trace_export.c
+++ b/kernel/trace/trace_export.c
@@ -14,6 +14,13 @@
 
 #include "trace_output.h"
 
+/* Stub function for events with triggers */
+static int ftrace_event_register(struct trace_event_call *call,
+				 enum trace_reg type, void *data)
+{
+	return 0;
+}
+
 #undef TRACE_SYSTEM
 #define TRACE_SYSTEM	ftrace
 
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 07/14] tracing: Have zero size length in filter logic be full string
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
                   ` (5 preceding siblings ...)
  2018-05-16 15:00 ` [PATCH v3 06/14] tracing: Add trigger file for trace_markers tracefs/ftrace/print Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 08/14] tracing: Prevent further users of zero size static arrays in trace events Steven Rostedt
                   ` (7 subsequent siblings)
  14 siblings, 0 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

[-- Attachment #1: 0007-tracing-Have-zero-size-length-in-filter-logic-be-ful.patch --]
[-- Type: text/plain, Size: 2007 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

As strings in trace events may not have a nul terminating character, the
filter string compares use the defined string length for the field for the
compares.

The trace_marker records data slightly different than do normal events. It's
size is zero, meaning that the string is the rest of the array, and that the
string also ends with '\0'.

If the size is zero, assume that the string is nul terminated and read the
string in question as is.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/trace_events_filter.c | 23 ++++++++++++-----------
 1 file changed, 12 insertions(+), 11 deletions(-)

diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index 7d306b74230f..0171407d231f 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -750,31 +750,32 @@ static int filter_pred_none(struct filter_pred *pred, void *event)
  *
  * Note:
  * - @str might not be NULL-terminated if it's of type DYN_STRING
- *   or STATIC_STRING
+ *   or STATIC_STRING, unless @len is zero.
  */
 
 static int regex_match_full(char *str, struct regex *r, int len)
 {
-	if (strncmp(str, r->pattern, len) == 0)
-		return 1;
-	return 0;
+	/* len of zero means str is dynamic and ends with '\0' */
+	if (!len)
+		return strcmp(str, r->pattern) == 0;
+
+	return strncmp(str, r->pattern, len) == 0;
 }
 
 static int regex_match_front(char *str, struct regex *r, int len)
 {
-	if (len < r->len)
+	if (len && len < r->len)
 		return 0;
 
-	if (strncmp(str, r->pattern, r->len) == 0)
-		return 1;
-	return 0;
+	return strncmp(str, r->pattern, r->len) == 0;
 }
 
 static int regex_match_middle(char *str, struct regex *r, int len)
 {
-	if (strnstr(str, r->pattern, len))
-		return 1;
-	return 0;
+	if (!len)
+		return strstr(str, r->pattern) != NULL;
+
+	return strnstr(str, r->pattern, len) != NULL;
 }
 
 static int regex_match_end(char *str, struct regex *r, int len)
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 08/14] tracing: Prevent further users of zero size static arrays in trace events
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
                   ` (6 preceding siblings ...)
  2018-05-16 15:00 ` [PATCH v3 07/14] tracing: Have zero size length in filter logic be full string Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 09/14] tracing: Allow histogram triggers to access ftrace internal events Steven Rostedt
                   ` (6 subsequent siblings)
  14 siblings, 0 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

[-- Attachment #1: 0008-tracing-Prevent-further-users-of-zero-size-static-ar.patch --]
[-- Type: text/plain, Size: 1111 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

A zero size static array has special meaning in the ftrace infrastructure.
Trace events are for recording data in the trace buffers that is normally
difficult to obtain via probes or function tracing. There is no reason for
any trace event to declare a zero size static array.

If one does, BUILD_BUG_ON() will trigger and prevent the kernel from
compiling.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 include/trace/trace_events.h | 1 +
 1 file changed, 1 insertion(+)

diff --git a/include/trace/trace_events.h b/include/trace/trace_events.h
index bfda803b0a09..4ecdfe2e3580 100644
--- a/include/trace/trace_events.h
+++ b/include/trace/trace_events.h
@@ -422,6 +422,7 @@ static struct trace_event_functions trace_event_type_funcs_##call = {	\
 	do {								\
 		char *type_str = #type"["__stringify(len)"]";		\
 		BUILD_BUG_ON(len > MAX_FILTER_STR_VAL);			\
+		BUILD_BUG_ON(len <= 0);					\
 		ret = trace_define_field(event_call, type_str, #item,	\
 				 offsetof(typeof(field), item),		\
 				 sizeof(field.item),			\
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 09/14] tracing: Allow histogram triggers to access ftrace internal events
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
                   ` (7 preceding siblings ...)
  2018-05-16 15:00 ` [PATCH v3 08/14] tracing: Prevent further users of zero size static arrays in trace events Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 10/14] tracing: Document trace_marker triggers Steven Rostedt
                   ` (5 subsequent siblings)
  14 siblings, 0 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

[-- Attachment #1: 0009-tracing-Allow-histogram-triggers-to-access-ftrace-in.patch --]
[-- Type: text/plain, Size: 948 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Now that trace_marker can have triggers, including a histogram triggers, the
onmatch() and onmax() access the trace event. To do so, the search routine
to find the event file needs to use the raw __find_event_file() that does
not filter out ftrace events.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/trace_events_hist.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index b9061ed59bbd..046c716a6536 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -2865,7 +2865,7 @@ static struct trace_event_file *event_file(struct trace_array *tr,
 {
 	struct trace_event_file *file;
 
-	file = find_event_file(tr, system, event_name);
+	file = __find_event_file(tr, system, event_name);
 	if (!file)
 		return ERR_PTR(-EINVAL);
 
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 10/14] tracing: Document trace_marker triggers
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
                   ` (8 preceding siblings ...)
  2018-05-16 15:00 ` [PATCH v3 09/14] tracing: Allow histogram triggers to access ftrace internal events Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-16 15:42   ` [PATCH v3.5 " Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 11/14] ftrace/selftest: Have the reset_trigger code be a bit more careful Steven Rostedt
                   ` (4 subsequent siblings)
  14 siblings, 1 reply; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

[-- Attachment #1: 0010-tracing-Document-trace_marker-triggers.patch --]
[-- Type: text/plain, Size: 35562 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Add documentation and an example on how to use trace_marker triggers.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 Documentation/trace/events.rst    |   6 +-
 Documentation/trace/ftrace.rst    |   5 +
 Documentation/trace/histogram.txt | 546 +++++++++++++++++++++++++++++-
 3 files changed, 555 insertions(+), 2 deletions(-)

diff --git a/Documentation/trace/events.rst b/Documentation/trace/events.rst
index a5ea2cb0082b..1afae55dc55c 100644
--- a/Documentation/trace/events.rst
+++ b/Documentation/trace/events.rst
@@ -338,10 +338,14 @@ used for conditionally invoking triggers.
 
 The syntax for event triggers is roughly based on the syntax for
 set_ftrace_filter 'ftrace filter commands' (see the 'Filter commands'
-section of Documentation/trace/ftrace.txt), but there are major
+section of Documentation/trace/ftrace.rst), but there are major
 differences and the implementation isn't currently tied to it in any
 way, so beware about making generalizations between the two.
 
+Note: Writing into trace_marker (See Documentation/trace/ftrace.rst)
+     can also enable triggers that are written into
+     /sys/kernel/tracing/events/ftrace/print/trigger
+
 6.1 Expression syntax
 ---------------------
 
diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst
index 67d9c38e95eb..aad4776c0f5d 100644
--- a/Documentation/trace/ftrace.rst
+++ b/Documentation/trace/ftrace.rst
@@ -507,6 +507,11 @@ of ftrace. Here is a list of some of the key files:
 
 		trace_fd = open("trace_marker", WR_ONLY);
 
+	Note: Writing into the trace_marker file can also initiate triggers
+	      that are written into /sys/kernel/tracing/events/ftrace/print/trigger
+	      See "Event triggers" in Documentation/trace/events.rst and an
+              example in Documentation/trace/histogram.rst (Section 3.)
+
   trace_marker_raw:
 
 	This is similar to trace_marker above, but is meant for for binary data
diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt
index 6e05510afc28..ae2d4f9d0a62 100644
--- a/Documentation/trace/histogram.txt
+++ b/Documentation/trace/histogram.txt
@@ -1604,7 +1604,6 @@
         Entries: 7
         Dropped: 0
 
-
 2.2 Inter-event hist triggers
 -----------------------------
 
@@ -1993,3 +1992,548 @@ hist trigger specification.
           Hits: 12970
           Entries: 2
           Dropped: 0
+
+3. User space creating a trigger
+--------------------------------
+
+Writing into /sys/kernel/tracing/trace_marker writes into the ftrace
+ring buffer. This can also act like an event, by writing into the trigger
+file located in /sys/kernel/tracing/events/ftrace/print/
+
+Modifying cyclictest to write into the trace_marker file before it sleeps
+and after it wakes up, something like this:
+
+static void traceputs(char *str)
+{
+	/* tracemark_fd is the trace_marker file descriptor */
+	if (tracemark_fd < 0)
+		return;
+	/* write the tracemark message */
+	write(tracemark_fd, str, strlen(str));
+}
+
+And later add something like:
+
+	traceputs("start");
+	clock_nanosleep(...);
+	traceputs("end");
+
+We can make a histogram from this:
+
+ # cd /sys/kernel/tracing
+ # echo 'latency u64 lat' > synthetic_events
+ # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger
+ # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger
+ # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
+
+The above created a synthetic event called "latency" and two histograms
+against the trace_marker, one gets triggered when "start" is written into the
+trace_marker file and the other when "end" is written. If the pids match, then
+it will call the "latency" synthetic event with the calculated latency as its
+parameter. Finally, a histogram is added to the latency synthetic event to
+record the calculated latency along with the pid.
+
+Now running cyclictest with:
+
+ # ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000
+
+ -p80  : run threads at priority 80
+ -d0   : have all threads run at the same interval
+ -i250 : start the interval at 250 microseconds (all threads will do this)
+ -n    : sleep with nanosleep
+ -a    : affine all threads to a separate CPU
+ -t    : one thread per available CPU
+ --tracemark : enable trace mark writing
+ -b 1000 : stop if any latency is greater than 1000 microseconds
+
+Note, the -b 1000 is used just to make --tracemark available.
+
+Then we can see the histogram created by this with:
+
+ # cat events/synthetic/latency/hist
+# event histogram
+#
+# trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
+#
+
+{ lat:        107, common_pid:       2039 } hitcount:          1
+{ lat:        122, common_pid:       2041 } hitcount:          1
+{ lat:        166, common_pid:       2039 } hitcount:          1
+{ lat:        174, common_pid:       2039 } hitcount:          1
+{ lat:        194, common_pid:       2041 } hitcount:          1
+{ lat:        196, common_pid:       2036 } hitcount:          1
+{ lat:        197, common_pid:       2038 } hitcount:          1
+{ lat:        198, common_pid:       2039 } hitcount:          1
+{ lat:        199, common_pid:       2039 } hitcount:          1
+{ lat:        200, common_pid:       2041 } hitcount:          1
+{ lat:        201, common_pid:       2039 } hitcount:          2
+{ lat:        202, common_pid:       2038 } hitcount:          1
+{ lat:        202, common_pid:       2043 } hitcount:          1
+{ lat:        203, common_pid:       2039 } hitcount:          1
+{ lat:        203, common_pid:       2036 } hitcount:          1
+{ lat:        203, common_pid:       2041 } hitcount:          1
+{ lat:        206, common_pid:       2038 } hitcount:          2
+{ lat:        207, common_pid:       2039 } hitcount:          1
+{ lat:        207, common_pid:       2036 } hitcount:          1
+{ lat:        208, common_pid:       2040 } hitcount:          1
+{ lat:        209, common_pid:       2043 } hitcount:          1
+{ lat:        210, common_pid:       2039 } hitcount:          1
+{ lat:        211, common_pid:       2039 } hitcount:          4
+{ lat:        212, common_pid:       2043 } hitcount:          1
+{ lat:        212, common_pid:       2039 } hitcount:          2
+{ lat:        213, common_pid:       2039 } hitcount:          1
+{ lat:        214, common_pid:       2038 } hitcount:          1
+{ lat:        214, common_pid:       2039 } hitcount:          2
+{ lat:        214, common_pid:       2042 } hitcount:          1
+{ lat:        215, common_pid:       2039 } hitcount:          1
+{ lat:        217, common_pid:       2036 } hitcount:          1
+{ lat:        217, common_pid:       2040 } hitcount:          1
+{ lat:        217, common_pid:       2039 } hitcount:          1
+{ lat:        218, common_pid:       2039 } hitcount:          6
+{ lat:        219, common_pid:       2039 } hitcount:          9
+{ lat:        220, common_pid:       2039 } hitcount:         11
+{ lat:        221, common_pid:       2039 } hitcount:          5
+{ lat:        221, common_pid:       2042 } hitcount:          1
+{ lat:        222, common_pid:       2039 } hitcount:          7
+{ lat:        223, common_pid:       2036 } hitcount:          1
+{ lat:        223, common_pid:       2039 } hitcount:          3
+{ lat:        224, common_pid:       2039 } hitcount:          4
+{ lat:        224, common_pid:       2037 } hitcount:          1
+{ lat:        224, common_pid:       2036 } hitcount:          2
+{ lat:        225, common_pid:       2039 } hitcount:          5
+{ lat:        225, common_pid:       2042 } hitcount:          1
+{ lat:        226, common_pid:       2039 } hitcount:          7
+{ lat:        226, common_pid:       2036 } hitcount:          4
+{ lat:        227, common_pid:       2039 } hitcount:          6
+{ lat:        227, common_pid:       2036 } hitcount:         12
+{ lat:        227, common_pid:       2043 } hitcount:          1
+{ lat:        228, common_pid:       2039 } hitcount:          7
+{ lat:        228, common_pid:       2036 } hitcount:         14
+{ lat:        229, common_pid:       2039 } hitcount:          9
+{ lat:        229, common_pid:       2036 } hitcount:          8
+{ lat:        229, common_pid:       2038 } hitcount:          1
+{ lat:        230, common_pid:       2039 } hitcount:         11
+{ lat:        230, common_pid:       2036 } hitcount:          6
+{ lat:        230, common_pid:       2043 } hitcount:          1
+{ lat:        230, common_pid:       2042 } hitcount:          2
+{ lat:        231, common_pid:       2041 } hitcount:          1
+{ lat:        231, common_pid:       2036 } hitcount:          6
+{ lat:        231, common_pid:       2043 } hitcount:          1
+{ lat:        231, common_pid:       2039 } hitcount:          8
+{ lat:        232, common_pid:       2037 } hitcount:          1
+{ lat:        232, common_pid:       2039 } hitcount:          6
+{ lat:        232, common_pid:       2040 } hitcount:          2
+{ lat:        232, common_pid:       2036 } hitcount:          5
+{ lat:        232, common_pid:       2043 } hitcount:          1
+{ lat:        233, common_pid:       2036 } hitcount:          5
+{ lat:        233, common_pid:       2039 } hitcount:         11
+{ lat:        234, common_pid:       2039 } hitcount:          4
+{ lat:        234, common_pid:       2038 } hitcount:          2
+{ lat:        234, common_pid:       2043 } hitcount:          2
+{ lat:        234, common_pid:       2036 } hitcount:         11
+{ lat:        234, common_pid:       2040 } hitcount:          1
+{ lat:        235, common_pid:       2037 } hitcount:          2
+{ lat:        235, common_pid:       2036 } hitcount:          8
+{ lat:        235, common_pid:       2043 } hitcount:          2
+{ lat:        235, common_pid:       2039 } hitcount:          5
+{ lat:        235, common_pid:       2042 } hitcount:          2
+{ lat:        235, common_pid:       2040 } hitcount:          4
+{ lat:        235, common_pid:       2041 } hitcount:          1
+{ lat:        236, common_pid:       2036 } hitcount:          7
+{ lat:        236, common_pid:       2037 } hitcount:          1
+{ lat:        236, common_pid:       2041 } hitcount:          5
+{ lat:        236, common_pid:       2039 } hitcount:          3
+{ lat:        236, common_pid:       2043 } hitcount:          9
+{ lat:        236, common_pid:       2040 } hitcount:          7
+{ lat:        237, common_pid:       2037 } hitcount:          1
+{ lat:        237, common_pid:       2040 } hitcount:          1
+{ lat:        237, common_pid:       2036 } hitcount:          9
+{ lat:        237, common_pid:       2039 } hitcount:          3
+{ lat:        237, common_pid:       2043 } hitcount:          8
+{ lat:        237, common_pid:       2042 } hitcount:          2
+{ lat:        237, common_pid:       2041 } hitcount:          2
+{ lat:        238, common_pid:       2043 } hitcount:         10
+{ lat:        238, common_pid:       2040 } hitcount:          1
+{ lat:        238, common_pid:       2037 } hitcount:          9
+{ lat:        238, common_pid:       2038 } hitcount:          1
+{ lat:        238, common_pid:       2039 } hitcount:          1
+{ lat:        238, common_pid:       2042 } hitcount:          3
+{ lat:        238, common_pid:       2036 } hitcount:          7
+{ lat:        239, common_pid:       2041 } hitcount:          1
+{ lat:        239, common_pid:       2043 } hitcount:         11
+{ lat:        239, common_pid:       2037 } hitcount:         11
+{ lat:        239, common_pid:       2038 } hitcount:          6
+{ lat:        239, common_pid:       2036 } hitcount:          7
+{ lat:        239, common_pid:       2040 } hitcount:          1
+{ lat:        239, common_pid:       2042 } hitcount:          9
+{ lat:        240, common_pid:       2037 } hitcount:         29
+{ lat:        240, common_pid:       2043 } hitcount:         15
+{ lat:        240, common_pid:       2040 } hitcount:         44
+{ lat:        240, common_pid:       2039 } hitcount:          1
+{ lat:        240, common_pid:       2041 } hitcount:          2
+{ lat:        240, common_pid:       2038 } hitcount:          1
+{ lat:        240, common_pid:       2036 } hitcount:         10
+{ lat:        240, common_pid:       2042 } hitcount:         13
+{ lat:        241, common_pid:       2036 } hitcount:         21
+{ lat:        241, common_pid:       2041 } hitcount:         36
+{ lat:        241, common_pid:       2037 } hitcount:         34
+{ lat:        241, common_pid:       2042 } hitcount:         14
+{ lat:        241, common_pid:       2040 } hitcount:         94
+{ lat:        241, common_pid:       2039 } hitcount:         12
+{ lat:        241, common_pid:       2038 } hitcount:          2
+{ lat:        241, common_pid:       2043 } hitcount:         28
+{ lat:        242, common_pid:       2040 } hitcount:        109
+{ lat:        242, common_pid:       2041 } hitcount:        506
+{ lat:        242, common_pid:       2039 } hitcount:        155
+{ lat:        242, common_pid:       2042 } hitcount:         21
+{ lat:        242, common_pid:       2037 } hitcount:         52
+{ lat:        242, common_pid:       2043 } hitcount:         21
+{ lat:        242, common_pid:       2036 } hitcount:         16
+{ lat:        242, common_pid:       2038 } hitcount:        156
+{ lat:        243, common_pid:       2037 } hitcount:         46
+{ lat:        243, common_pid:       2039 } hitcount:         40
+{ lat:        243, common_pid:       2042 } hitcount:        119
+{ lat:        243, common_pid:       2041 } hitcount:        611
+{ lat:        243, common_pid:       2036 } hitcount:         69
+{ lat:        243, common_pid:       2038 } hitcount:        784
+{ lat:        243, common_pid:       2040 } hitcount:        323
+{ lat:        243, common_pid:       2043 } hitcount:         14
+{ lat:        244, common_pid:       2043 } hitcount:         35
+{ lat:        244, common_pid:       2042 } hitcount:        305
+{ lat:        244, common_pid:       2039 } hitcount:          8
+{ lat:        244, common_pid:       2040 } hitcount:       4515
+{ lat:        244, common_pid:       2038 } hitcount:        371
+{ lat:        244, common_pid:       2037 } hitcount:         31
+{ lat:        244, common_pid:       2036 } hitcount:        114
+{ lat:        244, common_pid:       2041 } hitcount:       3396
+{ lat:        245, common_pid:       2036 } hitcount:        700
+{ lat:        245, common_pid:       2041 } hitcount:       2772
+{ lat:        245, common_pid:       2037 } hitcount:        268
+{ lat:        245, common_pid:       2039 } hitcount:        472
+{ lat:        245, common_pid:       2038 } hitcount:       2758
+{ lat:        245, common_pid:       2042 } hitcount:       3833
+{ lat:        245, common_pid:       2040 } hitcount:       3105
+{ lat:        245, common_pid:       2043 } hitcount:        645
+{ lat:        246, common_pid:       2038 } hitcount:       3451
+{ lat:        246, common_pid:       2041 } hitcount:        142
+{ lat:        246, common_pid:       2037 } hitcount:       5101
+{ lat:        246, common_pid:       2040 } hitcount:         68
+{ lat:        246, common_pid:       2043 } hitcount:       5099
+{ lat:        246, common_pid:       2039 } hitcount:       5608
+{ lat:        246, common_pid:       2042 } hitcount:       3723
+{ lat:        246, common_pid:       2036 } hitcount:       4738
+{ lat:        247, common_pid:       2042 } hitcount:        312
+{ lat:        247, common_pid:       2043 } hitcount:       2385
+{ lat:        247, common_pid:       2041 } hitcount:        452
+{ lat:        247, common_pid:       2038 } hitcount:        792
+{ lat:        247, common_pid:       2040 } hitcount:         78
+{ lat:        247, common_pid:       2036 } hitcount:       2375
+{ lat:        247, common_pid:       2039 } hitcount:       1834
+{ lat:        247, common_pid:       2037 } hitcount:       2655
+{ lat:        248, common_pid:       2037 } hitcount:         36
+{ lat:        248, common_pid:       2042 } hitcount:         11
+{ lat:        248, common_pid:       2038 } hitcount:        122
+{ lat:        248, common_pid:       2036 } hitcount:        135
+{ lat:        248, common_pid:       2039 } hitcount:         26
+{ lat:        248, common_pid:       2041 } hitcount:        503
+{ lat:        248, common_pid:       2043 } hitcount:         66
+{ lat:        248, common_pid:       2040 } hitcount:         46
+{ lat:        249, common_pid:       2037 } hitcount:         29
+{ lat:        249, common_pid:       2038 } hitcount:          1
+{ lat:        249, common_pid:       2043 } hitcount:         29
+{ lat:        249, common_pid:       2039 } hitcount:          8
+{ lat:        249, common_pid:       2042 } hitcount:         56
+{ lat:        249, common_pid:       2040 } hitcount:         27
+{ lat:        249, common_pid:       2041 } hitcount:         11
+{ lat:        249, common_pid:       2036 } hitcount:         27
+{ lat:        250, common_pid:       2038 } hitcount:          1
+{ lat:        250, common_pid:       2036 } hitcount:         30
+{ lat:        250, common_pid:       2040 } hitcount:         19
+{ lat:        250, common_pid:       2043 } hitcount:         22
+{ lat:        250, common_pid:       2042 } hitcount:         20
+{ lat:        250, common_pid:       2041 } hitcount:          1
+{ lat:        250, common_pid:       2039 } hitcount:          6
+{ lat:        250, common_pid:       2037 } hitcount:         48
+{ lat:        251, common_pid:       2037 } hitcount:         43
+{ lat:        251, common_pid:       2039 } hitcount:          1
+{ lat:        251, common_pid:       2036 } hitcount:         12
+{ lat:        251, common_pid:       2042 } hitcount:          2
+{ lat:        251, common_pid:       2041 } hitcount:          1
+{ lat:        251, common_pid:       2043 } hitcount:         15
+{ lat:        251, common_pid:       2040 } hitcount:          3
+{ lat:        252, common_pid:       2040 } hitcount:          1
+{ lat:        252, common_pid:       2036 } hitcount:         12
+{ lat:        252, common_pid:       2037 } hitcount:         21
+{ lat:        252, common_pid:       2043 } hitcount:         14
+{ lat:        253, common_pid:       2037 } hitcount:         21
+{ lat:        253, common_pid:       2039 } hitcount:          2
+{ lat:        253, common_pid:       2036 } hitcount:          9
+{ lat:        253, common_pid:       2043 } hitcount:          6
+{ lat:        253, common_pid:       2040 } hitcount:          1
+{ lat:        254, common_pid:       2036 } hitcount:          8
+{ lat:        254, common_pid:       2043 } hitcount:          3
+{ lat:        254, common_pid:       2041 } hitcount:          1
+{ lat:        254, common_pid:       2042 } hitcount:          1
+{ lat:        254, common_pid:       2039 } hitcount:          1
+{ lat:        254, common_pid:       2037 } hitcount:         12
+{ lat:        255, common_pid:       2043 } hitcount:          1
+{ lat:        255, common_pid:       2037 } hitcount:          2
+{ lat:        255, common_pid:       2036 } hitcount:          2
+{ lat:        255, common_pid:       2039 } hitcount:          8
+{ lat:        256, common_pid:       2043 } hitcount:          1
+{ lat:        256, common_pid:       2036 } hitcount:          4
+{ lat:        256, common_pid:       2039 } hitcount:          6
+{ lat:        257, common_pid:       2039 } hitcount:          5
+{ lat:        257, common_pid:       2036 } hitcount:          4
+{ lat:        258, common_pid:       2039 } hitcount:          5
+{ lat:        258, common_pid:       2036 } hitcount:          2
+{ lat:        259, common_pid:       2036 } hitcount:          7
+{ lat:        259, common_pid:       2039 } hitcount:          7
+{ lat:        260, common_pid:       2036 } hitcount:          8
+{ lat:        260, common_pid:       2039 } hitcount:          6
+{ lat:        261, common_pid:       2036 } hitcount:          5
+{ lat:        261, common_pid:       2039 } hitcount:          7
+{ lat:        262, common_pid:       2039 } hitcount:          5
+{ lat:        262, common_pid:       2036 } hitcount:          5
+{ lat:        263, common_pid:       2039 } hitcount:          7
+{ lat:        263, common_pid:       2036 } hitcount:          7
+{ lat:        264, common_pid:       2039 } hitcount:          9
+{ lat:        264, common_pid:       2036 } hitcount:          9
+{ lat:        265, common_pid:       2036 } hitcount:          5
+{ lat:        265, common_pid:       2039 } hitcount:          1
+{ lat:        266, common_pid:       2036 } hitcount:          1
+{ lat:        266, common_pid:       2039 } hitcount:          3
+{ lat:        267, common_pid:       2036 } hitcount:          1
+{ lat:        267, common_pid:       2039 } hitcount:          3
+{ lat:        268, common_pid:       2036 } hitcount:          1
+{ lat:        268, common_pid:       2039 } hitcount:          6
+{ lat:        269, common_pid:       2036 } hitcount:          1
+{ lat:        269, common_pid:       2043 } hitcount:          1
+{ lat:        269, common_pid:       2039 } hitcount:          2
+{ lat:        270, common_pid:       2040 } hitcount:          1
+{ lat:        270, common_pid:       2039 } hitcount:          6
+{ lat:        271, common_pid:       2041 } hitcount:          1
+{ lat:        271, common_pid:       2039 } hitcount:          5
+{ lat:        272, common_pid:       2039 } hitcount:         10
+{ lat:        273, common_pid:       2039 } hitcount:          8
+{ lat:        274, common_pid:       2039 } hitcount:          2
+{ lat:        275, common_pid:       2039 } hitcount:          1
+{ lat:        276, common_pid:       2039 } hitcount:          2
+{ lat:        276, common_pid:       2037 } hitcount:          1
+{ lat:        276, common_pid:       2038 } hitcount:          1
+{ lat:        277, common_pid:       2039 } hitcount:          1
+{ lat:        277, common_pid:       2042 } hitcount:          1
+{ lat:        278, common_pid:       2039 } hitcount:          1
+{ lat:        279, common_pid:       2039 } hitcount:          4
+{ lat:        279, common_pid:       2043 } hitcount:          1
+{ lat:        280, common_pid:       2039 } hitcount:          3
+{ lat:        283, common_pid:       2036 } hitcount:          2
+{ lat:        284, common_pid:       2039 } hitcount:          1
+{ lat:        284, common_pid:       2043 } hitcount:          1
+{ lat:        288, common_pid:       2039 } hitcount:          1
+{ lat:        289, common_pid:       2039 } hitcount:          1
+{ lat:        300, common_pid:       2039 } hitcount:          1
+{ lat:        384, common_pid:       2039 } hitcount:          1
+
+Totals:
+    Hits: 67625
+    Entries: 278
+    Dropped: 0
+
+Note, the writes are around the sleep, so ideally they will all be of 250
+microseconds. If you are wondering how there are several that are under
+250 microseconds, that is because the way cyclictest works, is if one
+iteration comes in late, the next one will set the timer to wake up less that
+250. That is, if an iteration came in 50 microseconds late, the next wake up
+will be at 200 microseconds.
+
+But this could easily be done in userspace. To make this even more
+interesting, we can mix the histogram between events that happened in the
+kernel with trace_marker.
+
+ # cd /sys/kernel/tracing
+ # echo 'latency u64 lat' > synthetic_events
+ # echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
+ # echo '!hist:keys=common_pid:vals=hitcount:lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global:onmatch(sched.sched_switch).latency($lat) if buf == "end"' > events/ftrace/print/trigger
+ # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat) if buf == "end"' > events/ftrace/print/trigger
+ # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
+
+The difference this time is that instead of using the trace_marker to start
+the latency, the sched_waking event is used, matching the common_pid for the
+trace_marker write with the pid that is being woken by sched_waking.
+
+After running cyclictest again with the same parameters, we now have:
+
+ # cat events/synthetic/latency/hist
+# event histogram
+#
+# trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
+#
+
+{ lat:          7, common_pid:       2302 } hitcount:        640
+{ lat:          7, common_pid:       2299 } hitcount:         42
+{ lat:          7, common_pid:       2303 } hitcount:         18
+{ lat:          7, common_pid:       2305 } hitcount:        166
+{ lat:          7, common_pid:       2306 } hitcount:          1
+{ lat:          7, common_pid:       2301 } hitcount:         91
+{ lat:          7, common_pid:       2300 } hitcount:         17
+{ lat:          8, common_pid:       2303 } hitcount:       8296
+{ lat:          8, common_pid:       2304 } hitcount:       6864
+{ lat:          8, common_pid:       2305 } hitcount:       9464
+{ lat:          8, common_pid:       2301 } hitcount:       9213
+{ lat:          8, common_pid:       2306 } hitcount:       6246
+{ lat:          8, common_pid:       2302 } hitcount:       8797
+{ lat:          8, common_pid:       2299 } hitcount:       8771
+{ lat:          8, common_pid:       2300 } hitcount:       8119
+{ lat:          9, common_pid:       2305 } hitcount:       1519
+{ lat:          9, common_pid:       2299 } hitcount:       2346
+{ lat:          9, common_pid:       2303 } hitcount:       2841
+{ lat:          9, common_pid:       2301 } hitcount:       1846
+{ lat:          9, common_pid:       2304 } hitcount:       3861
+{ lat:          9, common_pid:       2302 } hitcount:       1210
+{ lat:          9, common_pid:       2300 } hitcount:       2762
+{ lat:          9, common_pid:       2306 } hitcount:       4247
+{ lat:         10, common_pid:       2299 } hitcount:         16
+{ lat:         10, common_pid:       2306 } hitcount:        333
+{ lat:         10, common_pid:       2303 } hitcount:         16
+{ lat:         10, common_pid:       2304 } hitcount:        168
+{ lat:         10, common_pid:       2302 } hitcount:        240
+{ lat:         10, common_pid:       2301 } hitcount:         28
+{ lat:         10, common_pid:       2300 } hitcount:         95
+{ lat:         10, common_pid:       2305 } hitcount:         18
+{ lat:         11, common_pid:       2303 } hitcount:          5
+{ lat:         11, common_pid:       2305 } hitcount:          8
+{ lat:         11, common_pid:       2306 } hitcount:        221
+{ lat:         11, common_pid:       2302 } hitcount:         76
+{ lat:         11, common_pid:       2304 } hitcount:         26
+{ lat:         11, common_pid:       2300 } hitcount:        125
+{ lat:         11, common_pid:       2299 } hitcount:          2
+{ lat:         12, common_pid:       2305 } hitcount:          3
+{ lat:         12, common_pid:       2300 } hitcount:          6
+{ lat:         12, common_pid:       2306 } hitcount:         90
+{ lat:         12, common_pid:       2302 } hitcount:          4
+{ lat:         12, common_pid:       2303 } hitcount:          1
+{ lat:         12, common_pid:       2304 } hitcount:        122
+{ lat:         13, common_pid:       2300 } hitcount:         12
+{ lat:         13, common_pid:       2301 } hitcount:          1
+{ lat:         13, common_pid:       2306 } hitcount:         32
+{ lat:         13, common_pid:       2302 } hitcount:          5
+{ lat:         13, common_pid:       2305 } hitcount:          1
+{ lat:         13, common_pid:       2303 } hitcount:          1
+{ lat:         13, common_pid:       2304 } hitcount:         61
+{ lat:         14, common_pid:       2303 } hitcount:          4
+{ lat:         14, common_pid:       2306 } hitcount:          5
+{ lat:         14, common_pid:       2305 } hitcount:          4
+{ lat:         14, common_pid:       2304 } hitcount:         62
+{ lat:         14, common_pid:       2302 } hitcount:         19
+{ lat:         14, common_pid:       2300 } hitcount:         33
+{ lat:         14, common_pid:       2299 } hitcount:          1
+{ lat:         14, common_pid:       2301 } hitcount:          4
+{ lat:         15, common_pid:       2305 } hitcount:          1
+{ lat:         15, common_pid:       2302 } hitcount:         25
+{ lat:         15, common_pid:       2300 } hitcount:         11
+{ lat:         15, common_pid:       2299 } hitcount:          5
+{ lat:         15, common_pid:       2301 } hitcount:          1
+{ lat:         15, common_pid:       2304 } hitcount:          8
+{ lat:         15, common_pid:       2303 } hitcount:          1
+{ lat:         15, common_pid:       2306 } hitcount:          6
+{ lat:         16, common_pid:       2302 } hitcount:         31
+{ lat:         16, common_pid:       2306 } hitcount:          3
+{ lat:         16, common_pid:       2300 } hitcount:          5
+{ lat:         17, common_pid:       2302 } hitcount:          6
+{ lat:         17, common_pid:       2303 } hitcount:          1
+{ lat:         18, common_pid:       2304 } hitcount:          1
+{ lat:         18, common_pid:       2302 } hitcount:          8
+{ lat:         18, common_pid:       2299 } hitcount:          1
+{ lat:         18, common_pid:       2301 } hitcount:          1
+{ lat:         19, common_pid:       2303 } hitcount:          4
+{ lat:         19, common_pid:       2304 } hitcount:          5
+{ lat:         19, common_pid:       2302 } hitcount:          4
+{ lat:         19, common_pid:       2299 } hitcount:          3
+{ lat:         19, common_pid:       2306 } hitcount:          1
+{ lat:         19, common_pid:       2300 } hitcount:          4
+{ lat:         19, common_pid:       2305 } hitcount:          5
+{ lat:         20, common_pid:       2299 } hitcount:          2
+{ lat:         20, common_pid:       2302 } hitcount:          3
+{ lat:         20, common_pid:       2305 } hitcount:          1
+{ lat:         20, common_pid:       2300 } hitcount:          2
+{ lat:         20, common_pid:       2301 } hitcount:          2
+{ lat:         20, common_pid:       2303 } hitcount:          3
+{ lat:         21, common_pid:       2305 } hitcount:          1
+{ lat:         21, common_pid:       2299 } hitcount:          5
+{ lat:         21, common_pid:       2303 } hitcount:          4
+{ lat:         21, common_pid:       2302 } hitcount:          7
+{ lat:         21, common_pid:       2300 } hitcount:          1
+{ lat:         21, common_pid:       2301 } hitcount:          5
+{ lat:         21, common_pid:       2304 } hitcount:          2
+{ lat:         22, common_pid:       2302 } hitcount:          5
+{ lat:         22, common_pid:       2303 } hitcount:          1
+{ lat:         22, common_pid:       2306 } hitcount:          3
+{ lat:         22, common_pid:       2301 } hitcount:          2
+{ lat:         22, common_pid:       2300 } hitcount:          1
+{ lat:         22, common_pid:       2299 } hitcount:          1
+{ lat:         22, common_pid:       2305 } hitcount:          1
+{ lat:         22, common_pid:       2304 } hitcount:          1
+{ lat:         23, common_pid:       2299 } hitcount:          1
+{ lat:         23, common_pid:       2306 } hitcount:          2
+{ lat:         23, common_pid:       2302 } hitcount:          6
+{ lat:         24, common_pid:       2302 } hitcount:          3
+{ lat:         24, common_pid:       2300 } hitcount:          1
+{ lat:         24, common_pid:       2306 } hitcount:          2
+{ lat:         24, common_pid:       2305 } hitcount:          1
+{ lat:         24, common_pid:       2299 } hitcount:          1
+{ lat:         25, common_pid:       2300 } hitcount:          1
+{ lat:         25, common_pid:       2302 } hitcount:          4
+{ lat:         26, common_pid:       2302 } hitcount:          2
+{ lat:         27, common_pid:       2305 } hitcount:          1
+{ lat:         27, common_pid:       2300 } hitcount:          1
+{ lat:         27, common_pid:       2302 } hitcount:          3
+{ lat:         28, common_pid:       2306 } hitcount:          1
+{ lat:         28, common_pid:       2302 } hitcount:          4
+{ lat:         29, common_pid:       2302 } hitcount:          1
+{ lat:         29, common_pid:       2300 } hitcount:          2
+{ lat:         29, common_pid:       2306 } hitcount:          1
+{ lat:         29, common_pid:       2304 } hitcount:          1
+{ lat:         30, common_pid:       2302 } hitcount:          4
+{ lat:         31, common_pid:       2302 } hitcount:          6
+{ lat:         32, common_pid:       2302 } hitcount:          1
+{ lat:         33, common_pid:       2299 } hitcount:          1
+{ lat:         33, common_pid:       2302 } hitcount:          3
+{ lat:         34, common_pid:       2302 } hitcount:          2
+{ lat:         35, common_pid:       2302 } hitcount:          1
+{ lat:         35, common_pid:       2304 } hitcount:          1
+{ lat:         36, common_pid:       2302 } hitcount:          4
+{ lat:         37, common_pid:       2302 } hitcount:          6
+{ lat:         38, common_pid:       2302 } hitcount:          2
+{ lat:         39, common_pid:       2302 } hitcount:          2
+{ lat:         39, common_pid:       2304 } hitcount:          1
+{ lat:         40, common_pid:       2304 } hitcount:          2
+{ lat:         40, common_pid:       2302 } hitcount:          5
+{ lat:         41, common_pid:       2304 } hitcount:          1
+{ lat:         41, common_pid:       2302 } hitcount:          8
+{ lat:         42, common_pid:       2302 } hitcount:          6
+{ lat:         42, common_pid:       2304 } hitcount:          1
+{ lat:         43, common_pid:       2302 } hitcount:          3
+{ lat:         43, common_pid:       2304 } hitcount:          4
+{ lat:         44, common_pid:       2302 } hitcount:          6
+{ lat:         45, common_pid:       2302 } hitcount:          5
+{ lat:         46, common_pid:       2302 } hitcount:          5
+{ lat:         47, common_pid:       2302 } hitcount:          7
+{ lat:         48, common_pid:       2301 } hitcount:          1
+{ lat:         48, common_pid:       2302 } hitcount:          9
+{ lat:         49, common_pid:       2302 } hitcount:          3
+{ lat:         50, common_pid:       2302 } hitcount:          1
+{ lat:         50, common_pid:       2301 } hitcount:          1
+{ lat:         51, common_pid:       2302 } hitcount:          2
+{ lat:         51, common_pid:       2301 } hitcount:          1
+{ lat:         61, common_pid:       2302 } hitcount:          1
+{ lat:        110, common_pid:       2302 } hitcount:          1
+
+Totals:
+    Hits: 89565
+    Entries: 158
+    Dropped: 0
+
+This doesn't tell us any information about how late cyclictest may have
+woken up, but it does show us a nice histogram of how long it took from
+the time that cyclictest was woken to the time it made it into user space.
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 11/14] ftrace/selftest: Have the reset_trigger code be a bit more careful
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
                   ` (9 preceding siblings ...)
  2018-05-16 15:00 ` [PATCH v3 10/14] tracing: Document trace_marker triggers Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 12/14] ftrace/selftest: Fix reset_trigger() to handle triggers with filters Steven Rostedt
                   ` (3 subsequent siblings)
  14 siblings, 0 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users,
	stable

[-- Attachment #1: 0011-ftrace-selftest-Have-the-reset_trigger-code-be-a-bit.patch --]
[-- Type: text/plain, Size: 2068 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

The trigger code is picky in how it can be disabled as there may be
dependencies between different events and synthetic events. Change the order
on how triggers are reset.

 1) Reset triggers of all synthetic events first
 2) Remove triggers with actions attached to them
 3) Remove all other triggers

If this order isn't followed, then some triggers will not be reset, and an
error may happen because a trigger is busy.

Cc: stable@vger.kernel.org
Fixes: cfa0963dc474f ("kselftests/ftrace : Add event trigger testcases")
Acked-by: Masami Hiramatsu <mhiramat@kernel.org>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 .../testing/selftests/ftrace/test.d/functions | 21 ++++++++++++++++---
 1 file changed, 18 insertions(+), 3 deletions(-)

diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions
index 2a4f16fc9819..8393b1c06027 100644
--- a/tools/testing/selftests/ftrace/test.d/functions
+++ b/tools/testing/selftests/ftrace/test.d/functions
@@ -15,14 +15,29 @@ reset_tracer() { # reset the current tracer
     echo nop > current_tracer
 }
 
-reset_trigger() { # reset all current setting triggers
-    grep -v ^# events/*/*/trigger |
+reset_trigger_file() {
+    # remove action triggers first
+    grep -H ':on[^:]*(' $@ |
+    while read line; do
+        cmd=`echo $line | cut -f2- -d: | cut -f1 -d" "`
+	file=`echo $line | cut -f1 -d:`
+	echo "!$cmd" >> $file
+    done
+    grep -Hv ^# $@ |
     while read line; do
         cmd=`echo $line | cut -f2- -d: | cut -f1 -d" "`
-	echo "!$cmd" > `echo $line | cut -f1 -d:`
+	file=`echo $line | cut -f1 -d:`
+	echo "!$cmd" > $file
     done
 }
 
+reset_trigger() { # reset all current setting triggers
+    if [ -d events/synthetic ]; then
+        reset_trigger_file events/synthetic/*/trigger
+    fi
+    reset_trigger_file events/*/*/trigger
+}
+
 reset_events_filter() { # reset all current setting filters
     grep -v ^none events/*/*/filter |
     while read line; do
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 12/14] ftrace/selftest: Fix reset_trigger() to handle triggers with filters
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
                   ` (10 preceding siblings ...)
  2018-05-16 15:00 ` [PATCH v3 11/14] ftrace/selftest: Have the reset_trigger code be a bit more careful Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-16 15:00 ` [PATCH v3 13/14] tracing/selftest: Add selftests to test trace_marker histogram triggers Steven Rostedt
                   ` (2 subsequent siblings)
  14 siblings, 0 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

[-- Attachment #1: 0012-ftrace-selftest-Fix-reset_trigger-to-handle-triggers.patch --]
[-- Type: text/plain, Size: 2623 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

The reset_trigger() function breaks up the command by a space ' '. This is
useful to ignore the '[active]' word for triggers when removing them. But if
the trigger has a filter (ie. "if prio < 10") then the filter needs to be
attached to the line that is written into the trigger file to remove it. But
the truncation removes the filter and the triggers are not cleared properly.

Before, reset_trigger() did this:

 # echo 'hist:keys=common_pid if prev_prio < 10' > events/sched/sched_switch/trigger
 # echo 'hist:keys=common_pid if next_prio < 10' >> events/sched/sched_switch/trigger
 # cat events/sched/sched_switch/trigger
hist:keys=common_pid:vals=hitcount:sort=hitcount:size=2048 if prev_prio < 10 [active]
hist:keys=common_pid:vals=hitcount:sort=hitcount:size=2048 if next_prio < 10 [active]

 reset_trigger() {
   echo '!hist:keys=common_pid:vals=hitcount:sort=hitcount:size=2048' >> events/sched/sched_switch/trigger
 }

 # cat events/sched/sched_switch/trigger
hist:keys=common_pid:vals=hitcount:sort=hitcount:size=2048 if prev_prio < 10 [active]
hist:keys=common_pid:vals=hitcount:sort=hitcount:size=2048 if next_prio < 10 [active]

After, where it includes the filter:

 reset_trigger() {
   echo '!hist:keys=common_pid:vals=hitcount:sort=hitcount:size=2048 if prev_prio < 10' >> events/sched/sched_switch/trigger
 }

 # cat events/sched/sched_switch/trigger
hist:keys=common_pid:vals=hitcount:sort=hitcount:size=2048 if next_prio < 10 [active]

Fixes: cfa0963dc474f ("kselftests/ftrace : Add event trigger testcases")
Acked-by: Masami Hiramatsu <mhiramat@kernel.org>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 tools/testing/selftests/ftrace/test.d/functions | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions
index 8393b1c06027..e4645d5e3126 100644
--- a/tools/testing/selftests/ftrace/test.d/functions
+++ b/tools/testing/selftests/ftrace/test.d/functions
@@ -19,13 +19,13 @@ reset_trigger_file() {
     # remove action triggers first
     grep -H ':on[^:]*(' $@ |
     while read line; do
-        cmd=`echo $line | cut -f2- -d: | cut -f1 -d" "`
+        cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
 	file=`echo $line | cut -f1 -d:`
 	echo "!$cmd" >> $file
     done
     grep -Hv ^# $@ |
     while read line; do
-        cmd=`echo $line | cut -f2- -d: | cut -f1 -d" "`
+        cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
 	file=`echo $line | cut -f1 -d:`
 	echo "!$cmd" > $file
     done
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 13/14] tracing/selftest: Add selftests to test trace_marker histogram triggers
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
                   ` (11 preceding siblings ...)
  2018-05-16 15:00 ` [PATCH v3 12/14] ftrace/selftest: Fix reset_trigger() to handle triggers with filters Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-23 14:13   ` Masami Hiramatsu
  2018-05-16 15:00 ` [PATCH v3 14/14] tracing/selftest: Add test to test hist trigger between kernel event and trace_marker Steven Rostedt
  2018-05-23  5:41 ` [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Namhyung Kim
  14 siblings, 1 reply; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

[-- Attachment #1: 0013-tracing-selftest-Add-selftests-to-test-trace_marker-.patch --]
[-- Type: text/plain, Size: 4143 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Add a couple of tests that test the trace_marker histogram triggers.
One does a straight histogram test, the other will create a synthetic event
and test the latency between two different writes (using filters to
differentiate between them).

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 .../trigger/trigger-trace-marker-hist.tc      | 49 ++++++++++++++
 .../trigger/trigger-trace-marker-synthetic.tc | 66 +++++++++++++++++++
 2 files changed, 115 insertions(+)
 create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
 create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc

diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
new file mode 100644
index 000000000000..2acbfe2c0c0c
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
@@ -0,0 +1,49 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: trace_marker trigger - test histogram trigger
+# flags: instance
+
+do_reset() {
+    reset_trigger
+    echo > set_event
+    clear_trace
+}
+
+fail() { #msg
+    do_reset
+    echo $1
+    exit_fail
+}
+
+if [ ! -f set_event ]; then
+    echo "event tracing is not supported"
+    exit_unsupported
+fi
+
+if [ ! -d events/ftrace/print ]; then
+    echo "event trace_marker is not supported"
+    exit_unsupported
+fi
+
+if [ ! -f events/ftrace/print/trigger ]; then
+    echo "event trigger is not supported"
+    exit_unsupported
+fi
+
+if [ ! -f events/ftrace/print/hist ]; then
+    echo "hist trigger is not supported"
+    exit_unsupported
+fi
+
+do_reset
+
+echo "Test histogram trace_marker tigger"
+
+echo 'hist:keys=common_pid' > events/ftrace/print/trigger
+for i in `seq 1 10` ; do echo "hello" > trace_marker; done
+grep 'hitcount: *10$' events/ftrace/print/hist > /dev/null || \
+    fail "hist trigger did not trigger correct times on trace_marker"
+
+do_reset
+
+exit 0
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
new file mode 100644
index 000000000000..3666dd6ab02a
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
@@ -0,0 +1,66 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: trace_marker trigger - test histogram with synthetic event
+# flags:
+
+do_reset() {
+    reset_trigger
+    echo > set_event
+    echo > synthetic_events
+    clear_trace
+}
+
+fail() { #msg
+    do_reset
+    echo $1
+    exit_fail
+}
+
+if [ ! -f set_event ]; then
+    echo "event tracing is not supported"
+    exit_unsupported
+fi
+
+if [ ! -f synthetic_events ]; then
+    echo "synthetic events not supported"
+    exit_unsupported
+fi
+
+if [ ! -d events/ftrace/print ]; then
+    echo "event trace_marker is not supported"
+    exit_unsupported
+fi
+
+if [ ! -f events/ftrace/print/trigger ]; then
+    echo "event trigger is not supported"
+    exit_unsupported
+fi
+
+if [ ! -f events/ftrace/print/hist ]; then
+    echo "hist trigger is not supported"
+    exit_unsupported
+fi
+
+do_reset
+
+echo "Test histogram trace_marker to trace_marker latency histogram trigger"
+
+echo 'latency u64 lat' > synthetic_events
+echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger
+echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger
+echo 'hist:keys=common_pid,lat:sort=lat' > events/synthetic/latency/trigger
+echo -n "start" > trace_marker
+echo -n "end" > trace_marker
+
+cnt=`grep 'hitcount: *1$' events/ftrace/print/hist | wc -l`
+
+if [ $cnt -ne 2 ]; then
+    fail "hist trace_marker trigger did not trigger correctly"
+fi
+
+grep 'hitcount: *1$' events/synthetic/latency/hist > /dev/null || \
+    fail "hist trigger did not trigger "
+
+do_reset
+
+exit 0
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3 14/14] tracing/selftest: Add test to test hist trigger between kernel event and trace_marker
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
                   ` (12 preceding siblings ...)
  2018-05-16 15:00 ` [PATCH v3 13/14] tracing/selftest: Add selftests to test trace_marker histogram triggers Steven Rostedt
@ 2018-05-16 15:00 ` Steven Rostedt
  2018-05-23 14:15   ` Masami Hiramatsu
  2018-05-23  5:41 ` [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Namhyung Kim
  14 siblings, 1 reply; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:00 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users

[-- Attachment #1: 0014-tracing-selftest-Add-test-to-test-hist-trigger-betwe.patch --]
[-- Type: text/plain, Size: 1901 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Add a test that tests a trigger that is initiated by a kernel event
(sched_waking) and compared to a write to the trace_marker.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 .../trigger/trigger-trace-marker-synthetic.tc | 22 +++++++++++++++++++
 1 file changed, 22 insertions(+)

diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
index 3666dd6ab02a..b06996ecd5e0 100644
--- a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
+++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
@@ -31,6 +31,11 @@ if [ ! -d events/ftrace/print ]; then
     exit_unsupported
 fi
 
+if [ ! -d events/sched/sched_waking ]; then
+    echo "event sched_waking is not supported"
+    exit_unsupported
+fi
+
 if [ ! -f events/ftrace/print/trigger ]; then
     echo "event trigger is not supported"
     exit_unsupported
@@ -63,4 +68,21 @@ grep 'hitcount: *1$' events/synthetic/latency/hist > /dev/null || \
 
 do_reset
 
+echo "Test histogram kernel event to trace_marker latency histogram trigger"
+
+echo 'latency u64 lat' > synthetic_events
+echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
+echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat)' > events/ftrace/print/trigger
+echo 'hist:keys=common_pid,lat:sort=lat' > events/synthetic/latency/trigger
+sleep 1
+echo "hello" > trace_marker
+
+grep 'hitcount: *1$' events/ftrace/print/hist > /dev/null || \
+    fail "hist trigger did not trigger correct times on trace_marker"
+
+grep 'hitcount: *1$' events/synthetic/latency/hist > /dev/null || \
+    fail "hist trigger did not trigger "
+
+do_reset
+
 exit 0
-- 
2.17.0

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* [PATCH v3.5 10/14] tracing: Document trace_marker triggers
  2018-05-16 15:00 ` [PATCH v3 10/14] tracing: Document trace_marker triggers Steven Rostedt
@ 2018-05-16 15:42   ` Steven Rostedt
  0 siblings, 0 replies; 28+ messages in thread
From: Steven Rostedt @ 2018-05-16 15:42 UTC (permalink / raw)
  To: linux-kernel
  Cc: Ingo Molnar, Andrew Morton, Thomas Gleixner, Tom Zanussi,
	Clark Williams, Karim Yaghmour, Brendan Gregg, Joel Fernandes,
	Masami Hiramatsu, Namhyung Kim, Yann Ylavic, linux-rt-users


From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Add documentation and an example on how to use trace_marker triggers.

Reviewed-by: Tom Zanussi <tom.zanussi@linux.intel.com>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
Sending this as 3.5 as I don't want to spam for a simple change.

Changes from v3:

 - Removed cut and paste extra line to remove a histogram trigger (Tom Zanussi)


 Documentation/trace/events.rst    |   6 +-
 Documentation/trace/ftrace.rst    |   5 +
 Documentation/trace/histogram.txt | 545 +++++++++++++++++++++++++++++++++++++-
 3 files changed, 554 insertions(+), 2 deletions(-)

diff --git a/Documentation/trace/events.rst b/Documentation/trace/events.rst
index a5ea2cb0082b..1afae55dc55c 100644
--- a/Documentation/trace/events.rst
+++ b/Documentation/trace/events.rst
@@ -338,10 +338,14 @@ used for conditionally invoking triggers.
 
 The syntax for event triggers is roughly based on the syntax for
 set_ftrace_filter 'ftrace filter commands' (see the 'Filter commands'
-section of Documentation/trace/ftrace.txt), but there are major
+section of Documentation/trace/ftrace.rst), but there are major
 differences and the implementation isn't currently tied to it in any
 way, so beware about making generalizations between the two.
 
+Note: Writing into trace_marker (See Documentation/trace/ftrace.rst)
+     can also enable triggers that are written into
+     /sys/kernel/tracing/events/ftrace/print/trigger
+
 6.1 Expression syntax
 ---------------------
 
diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst
index 67d9c38e95eb..aad4776c0f5d 100644
--- a/Documentation/trace/ftrace.rst
+++ b/Documentation/trace/ftrace.rst
@@ -507,6 +507,11 @@ of ftrace. Here is a list of some of the key files:
 
 		trace_fd = open("trace_marker", WR_ONLY);
 
+	Note: Writing into the trace_marker file can also initiate triggers
+	      that are written into /sys/kernel/tracing/events/ftrace/print/trigger
+	      See "Event triggers" in Documentation/trace/events.rst and an
+              example in Documentation/trace/histogram.rst (Section 3.)
+
   trace_marker_raw:
 
 	This is similar to trace_marker above, but is meant for for binary data
diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt
index 6e05510afc28..b13771cb12c1 100644
--- a/Documentation/trace/histogram.txt
+++ b/Documentation/trace/histogram.txt
@@ -1604,7 +1604,6 @@
         Entries: 7
         Dropped: 0
 
-
 2.2 Inter-event hist triggers
 -----------------------------
 
@@ -1993,3 +1992,547 @@ hist trigger specification.
           Hits: 12970
           Entries: 2
           Dropped: 0
+
+3. User space creating a trigger
+--------------------------------
+
+Writing into /sys/kernel/tracing/trace_marker writes into the ftrace
+ring buffer. This can also act like an event, by writing into the trigger
+file located in /sys/kernel/tracing/events/ftrace/print/
+
+Modifying cyclictest to write into the trace_marker file before it sleeps
+and after it wakes up, something like this:
+
+static void traceputs(char *str)
+{
+	/* tracemark_fd is the trace_marker file descriptor */
+	if (tracemark_fd < 0)
+		return;
+	/* write the tracemark message */
+	write(tracemark_fd, str, strlen(str));
+}
+
+And later add something like:
+
+	traceputs("start");
+	clock_nanosleep(...);
+	traceputs("end");
+
+We can make a histogram from this:
+
+ # cd /sys/kernel/tracing
+ # echo 'latency u64 lat' > synthetic_events
+ # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger
+ # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger
+ # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
+
+The above created a synthetic event called "latency" and two histograms
+against the trace_marker, one gets triggered when "start" is written into the
+trace_marker file and the other when "end" is written. If the pids match, then
+it will call the "latency" synthetic event with the calculated latency as its
+parameter. Finally, a histogram is added to the latency synthetic event to
+record the calculated latency along with the pid.
+
+Now running cyclictest with:
+
+ # ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000
+
+ -p80  : run threads at priority 80
+ -d0   : have all threads run at the same interval
+ -i250 : start the interval at 250 microseconds (all threads will do this)
+ -n    : sleep with nanosleep
+ -a    : affine all threads to a separate CPU
+ -t    : one thread per available CPU
+ --tracemark : enable trace mark writing
+ -b 1000 : stop if any latency is greater than 1000 microseconds
+
+Note, the -b 1000 is used just to make --tracemark available.
+
+Then we can see the histogram created by this with:
+
+ # cat events/synthetic/latency/hist
+# event histogram
+#
+# trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
+#
+
+{ lat:        107, common_pid:       2039 } hitcount:          1
+{ lat:        122, common_pid:       2041 } hitcount:          1
+{ lat:        166, common_pid:       2039 } hitcount:          1
+{ lat:        174, common_pid:       2039 } hitcount:          1
+{ lat:        194, common_pid:       2041 } hitcount:          1
+{ lat:        196, common_pid:       2036 } hitcount:          1
+{ lat:        197, common_pid:       2038 } hitcount:          1
+{ lat:        198, common_pid:       2039 } hitcount:          1
+{ lat:        199, common_pid:       2039 } hitcount:          1
+{ lat:        200, common_pid:       2041 } hitcount:          1
+{ lat:        201, common_pid:       2039 } hitcount:          2
+{ lat:        202, common_pid:       2038 } hitcount:          1
+{ lat:        202, common_pid:       2043 } hitcount:          1
+{ lat:        203, common_pid:       2039 } hitcount:          1
+{ lat:        203, common_pid:       2036 } hitcount:          1
+{ lat:        203, common_pid:       2041 } hitcount:          1
+{ lat:        206, common_pid:       2038 } hitcount:          2
+{ lat:        207, common_pid:       2039 } hitcount:          1
+{ lat:        207, common_pid:       2036 } hitcount:          1
+{ lat:        208, common_pid:       2040 } hitcount:          1
+{ lat:        209, common_pid:       2043 } hitcount:          1
+{ lat:        210, common_pid:       2039 } hitcount:          1
+{ lat:        211, common_pid:       2039 } hitcount:          4
+{ lat:        212, common_pid:       2043 } hitcount:          1
+{ lat:        212, common_pid:       2039 } hitcount:          2
+{ lat:        213, common_pid:       2039 } hitcount:          1
+{ lat:        214, common_pid:       2038 } hitcount:          1
+{ lat:        214, common_pid:       2039 } hitcount:          2
+{ lat:        214, common_pid:       2042 } hitcount:          1
+{ lat:        215, common_pid:       2039 } hitcount:          1
+{ lat:        217, common_pid:       2036 } hitcount:          1
+{ lat:        217, common_pid:       2040 } hitcount:          1
+{ lat:        217, common_pid:       2039 } hitcount:          1
+{ lat:        218, common_pid:       2039 } hitcount:          6
+{ lat:        219, common_pid:       2039 } hitcount:          9
+{ lat:        220, common_pid:       2039 } hitcount:         11
+{ lat:        221, common_pid:       2039 } hitcount:          5
+{ lat:        221, common_pid:       2042 } hitcount:          1
+{ lat:        222, common_pid:       2039 } hitcount:          7
+{ lat:        223, common_pid:       2036 } hitcount:          1
+{ lat:        223, common_pid:       2039 } hitcount:          3
+{ lat:        224, common_pid:       2039 } hitcount:          4
+{ lat:        224, common_pid:       2037 } hitcount:          1
+{ lat:        224, common_pid:       2036 } hitcount:          2
+{ lat:        225, common_pid:       2039 } hitcount:          5
+{ lat:        225, common_pid:       2042 } hitcount:          1
+{ lat:        226, common_pid:       2039 } hitcount:          7
+{ lat:        226, common_pid:       2036 } hitcount:          4
+{ lat:        227, common_pid:       2039 } hitcount:          6
+{ lat:        227, common_pid:       2036 } hitcount:         12
+{ lat:        227, common_pid:       2043 } hitcount:          1
+{ lat:        228, common_pid:       2039 } hitcount:          7
+{ lat:        228, common_pid:       2036 } hitcount:         14
+{ lat:        229, common_pid:       2039 } hitcount:          9
+{ lat:        229, common_pid:       2036 } hitcount:          8
+{ lat:        229, common_pid:       2038 } hitcount:          1
+{ lat:        230, common_pid:       2039 } hitcount:         11
+{ lat:        230, common_pid:       2036 } hitcount:          6
+{ lat:        230, common_pid:       2043 } hitcount:          1
+{ lat:        230, common_pid:       2042 } hitcount:          2
+{ lat:        231, common_pid:       2041 } hitcount:          1
+{ lat:        231, common_pid:       2036 } hitcount:          6
+{ lat:        231, common_pid:       2043 } hitcount:          1
+{ lat:        231, common_pid:       2039 } hitcount:          8
+{ lat:        232, common_pid:       2037 } hitcount:          1
+{ lat:        232, common_pid:       2039 } hitcount:          6
+{ lat:        232, common_pid:       2040 } hitcount:          2
+{ lat:        232, common_pid:       2036 } hitcount:          5
+{ lat:        232, common_pid:       2043 } hitcount:          1
+{ lat:        233, common_pid:       2036 } hitcount:          5
+{ lat:        233, common_pid:       2039 } hitcount:         11
+{ lat:        234, common_pid:       2039 } hitcount:          4
+{ lat:        234, common_pid:       2038 } hitcount:          2
+{ lat:        234, common_pid:       2043 } hitcount:          2
+{ lat:        234, common_pid:       2036 } hitcount:         11
+{ lat:        234, common_pid:       2040 } hitcount:          1
+{ lat:        235, common_pid:       2037 } hitcount:          2
+{ lat:        235, common_pid:       2036 } hitcount:          8
+{ lat:        235, common_pid:       2043 } hitcount:          2
+{ lat:        235, common_pid:       2039 } hitcount:          5
+{ lat:        235, common_pid:       2042 } hitcount:          2
+{ lat:        235, common_pid:       2040 } hitcount:          4
+{ lat:        235, common_pid:       2041 } hitcount:          1
+{ lat:        236, common_pid:       2036 } hitcount:          7
+{ lat:        236, common_pid:       2037 } hitcount:          1
+{ lat:        236, common_pid:       2041 } hitcount:          5
+{ lat:        236, common_pid:       2039 } hitcount:          3
+{ lat:        236, common_pid:       2043 } hitcount:          9
+{ lat:        236, common_pid:       2040 } hitcount:          7
+{ lat:        237, common_pid:       2037 } hitcount:          1
+{ lat:        237, common_pid:       2040 } hitcount:          1
+{ lat:        237, common_pid:       2036 } hitcount:          9
+{ lat:        237, common_pid:       2039 } hitcount:          3
+{ lat:        237, common_pid:       2043 } hitcount:          8
+{ lat:        237, common_pid:       2042 } hitcount:          2
+{ lat:        237, common_pid:       2041 } hitcount:          2
+{ lat:        238, common_pid:       2043 } hitcount:         10
+{ lat:        238, common_pid:       2040 } hitcount:          1
+{ lat:        238, common_pid:       2037 } hitcount:          9
+{ lat:        238, common_pid:       2038 } hitcount:          1
+{ lat:        238, common_pid:       2039 } hitcount:          1
+{ lat:        238, common_pid:       2042 } hitcount:          3
+{ lat:        238, common_pid:       2036 } hitcount:          7
+{ lat:        239, common_pid:       2041 } hitcount:          1
+{ lat:        239, common_pid:       2043 } hitcount:         11
+{ lat:        239, common_pid:       2037 } hitcount:         11
+{ lat:        239, common_pid:       2038 } hitcount:          6
+{ lat:        239, common_pid:       2036 } hitcount:          7
+{ lat:        239, common_pid:       2040 } hitcount:          1
+{ lat:        239, common_pid:       2042 } hitcount:          9
+{ lat:        240, common_pid:       2037 } hitcount:         29
+{ lat:        240, common_pid:       2043 } hitcount:         15
+{ lat:        240, common_pid:       2040 } hitcount:         44
+{ lat:        240, common_pid:       2039 } hitcount:          1
+{ lat:        240, common_pid:       2041 } hitcount:          2
+{ lat:        240, common_pid:       2038 } hitcount:          1
+{ lat:        240, common_pid:       2036 } hitcount:         10
+{ lat:        240, common_pid:       2042 } hitcount:         13
+{ lat:        241, common_pid:       2036 } hitcount:         21
+{ lat:        241, common_pid:       2041 } hitcount:         36
+{ lat:        241, common_pid:       2037 } hitcount:         34
+{ lat:        241, common_pid:       2042 } hitcount:         14
+{ lat:        241, common_pid:       2040 } hitcount:         94
+{ lat:        241, common_pid:       2039 } hitcount:         12
+{ lat:        241, common_pid:       2038 } hitcount:          2
+{ lat:        241, common_pid:       2043 } hitcount:         28
+{ lat:        242, common_pid:       2040 } hitcount:        109
+{ lat:        242, common_pid:       2041 } hitcount:        506
+{ lat:        242, common_pid:       2039 } hitcount:        155
+{ lat:        242, common_pid:       2042 } hitcount:         21
+{ lat:        242, common_pid:       2037 } hitcount:         52
+{ lat:        242, common_pid:       2043 } hitcount:         21
+{ lat:        242, common_pid:       2036 } hitcount:         16
+{ lat:        242, common_pid:       2038 } hitcount:        156
+{ lat:        243, common_pid:       2037 } hitcount:         46
+{ lat:        243, common_pid:       2039 } hitcount:         40
+{ lat:        243, common_pid:       2042 } hitcount:        119
+{ lat:        243, common_pid:       2041 } hitcount:        611
+{ lat:        243, common_pid:       2036 } hitcount:         69
+{ lat:        243, common_pid:       2038 } hitcount:        784
+{ lat:        243, common_pid:       2040 } hitcount:        323
+{ lat:        243, common_pid:       2043 } hitcount:         14
+{ lat:        244, common_pid:       2043 } hitcount:         35
+{ lat:        244, common_pid:       2042 } hitcount:        305
+{ lat:        244, common_pid:       2039 } hitcount:          8
+{ lat:        244, common_pid:       2040 } hitcount:       4515
+{ lat:        244, common_pid:       2038 } hitcount:        371
+{ lat:        244, common_pid:       2037 } hitcount:         31
+{ lat:        244, common_pid:       2036 } hitcount:        114
+{ lat:        244, common_pid:       2041 } hitcount:       3396
+{ lat:        245, common_pid:       2036 } hitcount:        700
+{ lat:        245, common_pid:       2041 } hitcount:       2772
+{ lat:        245, common_pid:       2037 } hitcount:        268
+{ lat:        245, common_pid:       2039 } hitcount:        472
+{ lat:        245, common_pid:       2038 } hitcount:       2758
+{ lat:        245, common_pid:       2042 } hitcount:       3833
+{ lat:        245, common_pid:       2040 } hitcount:       3105
+{ lat:        245, common_pid:       2043 } hitcount:        645
+{ lat:        246, common_pid:       2038 } hitcount:       3451
+{ lat:        246, common_pid:       2041 } hitcount:        142
+{ lat:        246, common_pid:       2037 } hitcount:       5101
+{ lat:        246, common_pid:       2040 } hitcount:         68
+{ lat:        246, common_pid:       2043 } hitcount:       5099
+{ lat:        246, common_pid:       2039 } hitcount:       5608
+{ lat:        246, common_pid:       2042 } hitcount:       3723
+{ lat:        246, common_pid:       2036 } hitcount:       4738
+{ lat:        247, common_pid:       2042 } hitcount:        312
+{ lat:        247, common_pid:       2043 } hitcount:       2385
+{ lat:        247, common_pid:       2041 } hitcount:        452
+{ lat:        247, common_pid:       2038 } hitcount:        792
+{ lat:        247, common_pid:       2040 } hitcount:         78
+{ lat:        247, common_pid:       2036 } hitcount:       2375
+{ lat:        247, common_pid:       2039 } hitcount:       1834
+{ lat:        247, common_pid:       2037 } hitcount:       2655
+{ lat:        248, common_pid:       2037 } hitcount:         36
+{ lat:        248, common_pid:       2042 } hitcount:         11
+{ lat:        248, common_pid:       2038 } hitcount:        122
+{ lat:        248, common_pid:       2036 } hitcount:        135
+{ lat:        248, common_pid:       2039 } hitcount:         26
+{ lat:        248, common_pid:       2041 } hitcount:        503
+{ lat:        248, common_pid:       2043 } hitcount:         66
+{ lat:        248, common_pid:       2040 } hitcount:         46
+{ lat:        249, common_pid:       2037 } hitcount:         29
+{ lat:        249, common_pid:       2038 } hitcount:          1
+{ lat:        249, common_pid:       2043 } hitcount:         29
+{ lat:        249, common_pid:       2039 } hitcount:          8
+{ lat:        249, common_pid:       2042 } hitcount:         56
+{ lat:        249, common_pid:       2040 } hitcount:         27
+{ lat:        249, common_pid:       2041 } hitcount:         11
+{ lat:        249, common_pid:       2036 } hitcount:         27
+{ lat:        250, common_pid:       2038 } hitcount:          1
+{ lat:        250, common_pid:       2036 } hitcount:         30
+{ lat:        250, common_pid:       2040 } hitcount:         19
+{ lat:        250, common_pid:       2043 } hitcount:         22
+{ lat:        250, common_pid:       2042 } hitcount:         20
+{ lat:        250, common_pid:       2041 } hitcount:          1
+{ lat:        250, common_pid:       2039 } hitcount:          6
+{ lat:        250, common_pid:       2037 } hitcount:         48
+{ lat:        251, common_pid:       2037 } hitcount:         43
+{ lat:        251, common_pid:       2039 } hitcount:          1
+{ lat:        251, common_pid:       2036 } hitcount:         12
+{ lat:        251, common_pid:       2042 } hitcount:          2
+{ lat:        251, common_pid:       2041 } hitcount:          1
+{ lat:        251, common_pid:       2043 } hitcount:         15
+{ lat:        251, common_pid:       2040 } hitcount:          3
+{ lat:        252, common_pid:       2040 } hitcount:          1
+{ lat:        252, common_pid:       2036 } hitcount:         12
+{ lat:        252, common_pid:       2037 } hitcount:         21
+{ lat:        252, common_pid:       2043 } hitcount:         14
+{ lat:        253, common_pid:       2037 } hitcount:         21
+{ lat:        253, common_pid:       2039 } hitcount:          2
+{ lat:        253, common_pid:       2036 } hitcount:          9
+{ lat:        253, common_pid:       2043 } hitcount:          6
+{ lat:        253, common_pid:       2040 } hitcount:          1
+{ lat:        254, common_pid:       2036 } hitcount:          8
+{ lat:        254, common_pid:       2043 } hitcount:          3
+{ lat:        254, common_pid:       2041 } hitcount:          1
+{ lat:        254, common_pid:       2042 } hitcount:          1
+{ lat:        254, common_pid:       2039 } hitcount:          1
+{ lat:        254, common_pid:       2037 } hitcount:         12
+{ lat:        255, common_pid:       2043 } hitcount:          1
+{ lat:        255, common_pid:       2037 } hitcount:          2
+{ lat:        255, common_pid:       2036 } hitcount:          2
+{ lat:        255, common_pid:       2039 } hitcount:          8
+{ lat:        256, common_pid:       2043 } hitcount:          1
+{ lat:        256, common_pid:       2036 } hitcount:          4
+{ lat:        256, common_pid:       2039 } hitcount:          6
+{ lat:        257, common_pid:       2039 } hitcount:          5
+{ lat:        257, common_pid:       2036 } hitcount:          4
+{ lat:        258, common_pid:       2039 } hitcount:          5
+{ lat:        258, common_pid:       2036 } hitcount:          2
+{ lat:        259, common_pid:       2036 } hitcount:          7
+{ lat:        259, common_pid:       2039 } hitcount:          7
+{ lat:        260, common_pid:       2036 } hitcount:          8
+{ lat:        260, common_pid:       2039 } hitcount:          6
+{ lat:        261, common_pid:       2036 } hitcount:          5
+{ lat:        261, common_pid:       2039 } hitcount:          7
+{ lat:        262, common_pid:       2039 } hitcount:          5
+{ lat:        262, common_pid:       2036 } hitcount:          5
+{ lat:        263, common_pid:       2039 } hitcount:          7
+{ lat:        263, common_pid:       2036 } hitcount:          7
+{ lat:        264, common_pid:       2039 } hitcount:          9
+{ lat:        264, common_pid:       2036 } hitcount:          9
+{ lat:        265, common_pid:       2036 } hitcount:          5
+{ lat:        265, common_pid:       2039 } hitcount:          1
+{ lat:        266, common_pid:       2036 } hitcount:          1
+{ lat:        266, common_pid:       2039 } hitcount:          3
+{ lat:        267, common_pid:       2036 } hitcount:          1
+{ lat:        267, common_pid:       2039 } hitcount:          3
+{ lat:        268, common_pid:       2036 } hitcount:          1
+{ lat:        268, common_pid:       2039 } hitcount:          6
+{ lat:        269, common_pid:       2036 } hitcount:          1
+{ lat:        269, common_pid:       2043 } hitcount:          1
+{ lat:        269, common_pid:       2039 } hitcount:          2
+{ lat:        270, common_pid:       2040 } hitcount:          1
+{ lat:        270, common_pid:       2039 } hitcount:          6
+{ lat:        271, common_pid:       2041 } hitcount:          1
+{ lat:        271, common_pid:       2039 } hitcount:          5
+{ lat:        272, common_pid:       2039 } hitcount:         10
+{ lat:        273, common_pid:       2039 } hitcount:          8
+{ lat:        274, common_pid:       2039 } hitcount:          2
+{ lat:        275, common_pid:       2039 } hitcount:          1
+{ lat:        276, common_pid:       2039 } hitcount:          2
+{ lat:        276, common_pid:       2037 } hitcount:          1
+{ lat:        276, common_pid:       2038 } hitcount:          1
+{ lat:        277, common_pid:       2039 } hitcount:          1
+{ lat:        277, common_pid:       2042 } hitcount:          1
+{ lat:        278, common_pid:       2039 } hitcount:          1
+{ lat:        279, common_pid:       2039 } hitcount:          4
+{ lat:        279, common_pid:       2043 } hitcount:          1
+{ lat:        280, common_pid:       2039 } hitcount:          3
+{ lat:        283, common_pid:       2036 } hitcount:          2
+{ lat:        284, common_pid:       2039 } hitcount:          1
+{ lat:        284, common_pid:       2043 } hitcount:          1
+{ lat:        288, common_pid:       2039 } hitcount:          1
+{ lat:        289, common_pid:       2039 } hitcount:          1
+{ lat:        300, common_pid:       2039 } hitcount:          1
+{ lat:        384, common_pid:       2039 } hitcount:          1
+
+Totals:
+    Hits: 67625
+    Entries: 278
+    Dropped: 0
+
+Note, the writes are around the sleep, so ideally they will all be of 250
+microseconds. If you are wondering how there are several that are under
+250 microseconds, that is because the way cyclictest works, is if one
+iteration comes in late, the next one will set the timer to wake up less that
+250. That is, if an iteration came in 50 microseconds late, the next wake up
+will be at 200 microseconds.
+
+But this could easily be done in userspace. To make this even more
+interesting, we can mix the histogram between events that happened in the
+kernel with trace_marker.
+
+ # cd /sys/kernel/tracing
+ # echo 'latency u64 lat' > synthetic_events
+ # echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
+ # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat) if buf == "end"' > events/ftrace/print/trigger
+ # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
+
+The difference this time is that instead of using the trace_marker to start
+the latency, the sched_waking event is used, matching the common_pid for the
+trace_marker write with the pid that is being woken by sched_waking.
+
+After running cyclictest again with the same parameters, we now have:
+
+ # cat events/synthetic/latency/hist
+# event histogram
+#
+# trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
+#
+
+{ lat:          7, common_pid:       2302 } hitcount:        640
+{ lat:          7, common_pid:       2299 } hitcount:         42
+{ lat:          7, common_pid:       2303 } hitcount:         18
+{ lat:          7, common_pid:       2305 } hitcount:        166
+{ lat:          7, common_pid:       2306 } hitcount:          1
+{ lat:          7, common_pid:       2301 } hitcount:         91
+{ lat:          7, common_pid:       2300 } hitcount:         17
+{ lat:          8, common_pid:       2303 } hitcount:       8296
+{ lat:          8, common_pid:       2304 } hitcount:       6864
+{ lat:          8, common_pid:       2305 } hitcount:       9464
+{ lat:          8, common_pid:       2301 } hitcount:       9213
+{ lat:          8, common_pid:       2306 } hitcount:       6246
+{ lat:          8, common_pid:       2302 } hitcount:       8797
+{ lat:          8, common_pid:       2299 } hitcount:       8771
+{ lat:          8, common_pid:       2300 } hitcount:       8119
+{ lat:          9, common_pid:       2305 } hitcount:       1519
+{ lat:          9, common_pid:       2299 } hitcount:       2346
+{ lat:          9, common_pid:       2303 } hitcount:       2841
+{ lat:          9, common_pid:       2301 } hitcount:       1846
+{ lat:          9, common_pid:       2304 } hitcount:       3861
+{ lat:          9, common_pid:       2302 } hitcount:       1210
+{ lat:          9, common_pid:       2300 } hitcount:       2762
+{ lat:          9, common_pid:       2306 } hitcount:       4247
+{ lat:         10, common_pid:       2299 } hitcount:         16
+{ lat:         10, common_pid:       2306 } hitcount:        333
+{ lat:         10, common_pid:       2303 } hitcount:         16
+{ lat:         10, common_pid:       2304 } hitcount:        168
+{ lat:         10, common_pid:       2302 } hitcount:        240
+{ lat:         10, common_pid:       2301 } hitcount:         28
+{ lat:         10, common_pid:       2300 } hitcount:         95
+{ lat:         10, common_pid:       2305 } hitcount:         18
+{ lat:         11, common_pid:       2303 } hitcount:          5
+{ lat:         11, common_pid:       2305 } hitcount:          8
+{ lat:         11, common_pid:       2306 } hitcount:        221
+{ lat:         11, common_pid:       2302 } hitcount:         76
+{ lat:         11, common_pid:       2304 } hitcount:         26
+{ lat:         11, common_pid:       2300 } hitcount:        125
+{ lat:         11, common_pid:       2299 } hitcount:          2
+{ lat:         12, common_pid:       2305 } hitcount:          3
+{ lat:         12, common_pid:       2300 } hitcount:          6
+{ lat:         12, common_pid:       2306 } hitcount:         90
+{ lat:         12, common_pid:       2302 } hitcount:          4
+{ lat:         12, common_pid:       2303 } hitcount:          1
+{ lat:         12, common_pid:       2304 } hitcount:        122
+{ lat:         13, common_pid:       2300 } hitcount:         12
+{ lat:         13, common_pid:       2301 } hitcount:          1
+{ lat:         13, common_pid:       2306 } hitcount:         32
+{ lat:         13, common_pid:       2302 } hitcount:          5
+{ lat:         13, common_pid:       2305 } hitcount:          1
+{ lat:         13, common_pid:       2303 } hitcount:          1
+{ lat:         13, common_pid:       2304 } hitcount:         61
+{ lat:         14, common_pid:       2303 } hitcount:          4
+{ lat:         14, common_pid:       2306 } hitcount:          5
+{ lat:         14, common_pid:       2305 } hitcount:          4
+{ lat:         14, common_pid:       2304 } hitcount:         62
+{ lat:         14, common_pid:       2302 } hitcount:         19
+{ lat:         14, common_pid:       2300 } hitcount:         33
+{ lat:         14, common_pid:       2299 } hitcount:          1
+{ lat:         14, common_pid:       2301 } hitcount:          4
+{ lat:         15, common_pid:       2305 } hitcount:          1
+{ lat:         15, common_pid:       2302 } hitcount:         25
+{ lat:         15, common_pid:       2300 } hitcount:         11
+{ lat:         15, common_pid:       2299 } hitcount:          5
+{ lat:         15, common_pid:       2301 } hitcount:          1
+{ lat:         15, common_pid:       2304 } hitcount:          8
+{ lat:         15, common_pid:       2303 } hitcount:          1
+{ lat:         15, common_pid:       2306 } hitcount:          6
+{ lat:         16, common_pid:       2302 } hitcount:         31
+{ lat:         16, common_pid:       2306 } hitcount:          3
+{ lat:         16, common_pid:       2300 } hitcount:          5
+{ lat:         17, common_pid:       2302 } hitcount:          6
+{ lat:         17, common_pid:       2303 } hitcount:          1
+{ lat:         18, common_pid:       2304 } hitcount:          1
+{ lat:         18, common_pid:       2302 } hitcount:          8
+{ lat:         18, common_pid:       2299 } hitcount:          1
+{ lat:         18, common_pid:       2301 } hitcount:          1
+{ lat:         19, common_pid:       2303 } hitcount:          4
+{ lat:         19, common_pid:       2304 } hitcount:          5
+{ lat:         19, common_pid:       2302 } hitcount:          4
+{ lat:         19, common_pid:       2299 } hitcount:          3
+{ lat:         19, common_pid:       2306 } hitcount:          1
+{ lat:         19, common_pid:       2300 } hitcount:          4
+{ lat:         19, common_pid:       2305 } hitcount:          5
+{ lat:         20, common_pid:       2299 } hitcount:          2
+{ lat:         20, common_pid:       2302 } hitcount:          3
+{ lat:         20, common_pid:       2305 } hitcount:          1
+{ lat:         20, common_pid:       2300 } hitcount:          2
+{ lat:         20, common_pid:       2301 } hitcount:          2
+{ lat:         20, common_pid:       2303 } hitcount:          3
+{ lat:         21, common_pid:       2305 } hitcount:          1
+{ lat:         21, common_pid:       2299 } hitcount:          5
+{ lat:         21, common_pid:       2303 } hitcount:          4
+{ lat:         21, common_pid:       2302 } hitcount:          7
+{ lat:         21, common_pid:       2300 } hitcount:          1
+{ lat:         21, common_pid:       2301 } hitcount:          5
+{ lat:         21, common_pid:       2304 } hitcount:          2
+{ lat:         22, common_pid:       2302 } hitcount:          5
+{ lat:         22, common_pid:       2303 } hitcount:          1
+{ lat:         22, common_pid:       2306 } hitcount:          3
+{ lat:         22, common_pid:       2301 } hitcount:          2
+{ lat:         22, common_pid:       2300 } hitcount:          1
+{ lat:         22, common_pid:       2299 } hitcount:          1
+{ lat:         22, common_pid:       2305 } hitcount:          1
+{ lat:         22, common_pid:       2304 } hitcount:          1
+{ lat:         23, common_pid:       2299 } hitcount:          1
+{ lat:         23, common_pid:       2306 } hitcount:          2
+{ lat:         23, common_pid:       2302 } hitcount:          6
+{ lat:         24, common_pid:       2302 } hitcount:          3
+{ lat:         24, common_pid:       2300 } hitcount:          1
+{ lat:         24, common_pid:       2306 } hitcount:          2
+{ lat:         24, common_pid:       2305 } hitcount:          1
+{ lat:         24, common_pid:       2299 } hitcount:          1
+{ lat:         25, common_pid:       2300 } hitcount:          1
+{ lat:         25, common_pid:       2302 } hitcount:          4
+{ lat:         26, common_pid:       2302 } hitcount:          2
+{ lat:         27, common_pid:       2305 } hitcount:          1
+{ lat:         27, common_pid:       2300 } hitcount:          1
+{ lat:         27, common_pid:       2302 } hitcount:          3
+{ lat:         28, common_pid:       2306 } hitcount:          1
+{ lat:         28, common_pid:       2302 } hitcount:          4
+{ lat:         29, common_pid:       2302 } hitcount:          1
+{ lat:         29, common_pid:       2300 } hitcount:          2
+{ lat:         29, common_pid:       2306 } hitcount:          1
+{ lat:         29, common_pid:       2304 } hitcount:          1
+{ lat:         30, common_pid:       2302 } hitcount:          4
+{ lat:         31, common_pid:       2302 } hitcount:          6
+{ lat:         32, common_pid:       2302 } hitcount:          1
+{ lat:         33, common_pid:       2299 } hitcount:          1
+{ lat:         33, common_pid:       2302 } hitcount:          3
+{ lat:         34, common_pid:       2302 } hitcount:          2
+{ lat:         35, common_pid:       2302 } hitcount:          1
+{ lat:         35, common_pid:       2304 } hitcount:          1
+{ lat:         36, common_pid:       2302 } hitcount:          4
+{ lat:         37, common_pid:       2302 } hitcount:          6
+{ lat:         38, common_pid:       2302 } hitcount:          2
+{ lat:         39, common_pid:       2302 } hitcount:          2
+{ lat:         39, common_pid:       2304 } hitcount:          1
+{ lat:         40, common_pid:       2304 } hitcount:          2
+{ lat:         40, common_pid:       2302 } hitcount:          5
+{ lat:         41, common_pid:       2304 } hitcount:          1
+{ lat:         41, common_pid:       2302 } hitcount:          8
+{ lat:         42, common_pid:       2302 } hitcount:          6
+{ lat:         42, common_pid:       2304 } hitcount:          1
+{ lat:         43, common_pid:       2302 } hitcount:          3
+{ lat:         43, common_pid:       2304 } hitcount:          4
+{ lat:         44, common_pid:       2302 } hitcount:          6
+{ lat:         45, common_pid:       2302 } hitcount:          5
+{ lat:         46, common_pid:       2302 } hitcount:          5
+{ lat:         47, common_pid:       2302 } hitcount:          7
+{ lat:         48, common_pid:       2301 } hitcount:          1
+{ lat:         48, common_pid:       2302 } hitcount:          9
+{ lat:         49, common_pid:       2302 } hitcount:          3
+{ lat:         50, common_pid:       2302 } hitcount:          1
+{ lat:         50, common_pid:       2301 } hitcount:          1
+{ lat:         51, common_pid:       2302 } hitcount:          2
+{ lat:         51, common_pid:       2301 } hitcount:          1
+{ lat:         61, common_pid:       2302 } hitcount:          1
+{ lat:        110, common_pid:       2302 } hitcount:          1
+
+Totals:
+    Hits: 89565
+    Entries: 158
+    Dropped: 0
+
+This doesn't tell us any information about how late cyclictest may have
+woken up, but it does show us a nice histogram of how long it took from
+the time that cyclictest was woken to the time it made it into user space.
-- 
2.13.6

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* Re: [PATCH v3 00/14] tracing: Add triggers to trace_marker writes
  2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
                   ` (13 preceding siblings ...)
  2018-05-16 15:00 ` [PATCH v3 14/14] tracing/selftest: Add test to test hist trigger between kernel event and trace_marker Steven Rostedt
@ 2018-05-23  5:41 ` Namhyung Kim
  14 siblings, 0 replies; 28+ messages in thread
From: Namhyung Kim @ 2018-05-23  5:41 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Thomas Gleixner,
	Tom Zanussi, Clark Williams, Karim Yaghmour, Brendan Gregg,
	Joel Fernandes, Masami Hiramatsu, Yann Ylavic, linux-rt-users,
	kernel-team

Hi Steve,

On Wed, May 16, 2018 at 11:00:12AM -0400, Steven Rostedt wrote:
> A few people have asked for this in the past, and I finally got around
> to implementing it. What this does is to allow writes into trace_marker
> to initiate a trigger.
> 
> The trace_marker event is described in:
> 
>  tracefs/events/ftrace/print
> 
> Thus the trigger file is added there:
> 
>  tracefs/events/ftrace/print/trigger
> 
> As there's already a "hist" file there, everything appears to work
> just like any other trigger to an event. See the last patch for
> documentation on how to use the triggers to a trace_marker write.
> 
> By the way, the patch:
> 
>   tracing: Prevent further users of zero size static arrays in trace events
> 
> May prevent your kernel from building if you include Xen. You will need
> to add this patch to make it work (or include the git repo below).
> 
>  http://lkml.kernel.org/r/20180509144605.5a220327@gandalf.local.home
> 
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
> ftrace/core
> 
> Head SHA1: dded7b759602085b4bd2c5581f58f6b179912d89
> 
> 
> Steven Rostedt (VMware) (14):
>       tracing: Do not reference event data in post call triggers
>       tracing: Add __find_event_file() to find event files without restrictions
>       tracing: Have event_trace_init() called by trace_init_tracefs()
>       tracing: Add brackets in ftrace event dynamic arrays
>       tracing: Do not show filter file for ftrace internal events
>       tracing: Add trigger file for trace_markers tracefs/ftrace/print
>       tracing: Have zero size length in filter logic be full string
>       tracing: Prevent further users of zero size static arrays in trace events
>       tracing: Allow histogram triggers to access ftrace internal events
>       tracing: Document trace_marker triggers
>       ftrace/selftest: Have the reset_trigger code be a bit more careful
>       ftrace/selftest: Fix reset_trigger() to handle triggers with filters
>       tracing/selftest: Add selftests to test trace_marker histogram triggers
>       tracing/selftest: Add test to test hist trigger between kernel event and trace_marker
> 
> ----

For the series:

Reviewed-by: Namhyung Kim <namhyung@kernel.org>

Thanks,
Namhyung


> Changes since v2:
> 
>  - typo fixes in documentation (Tom Zanussi)
>  - Rename trigger-trace-marker{-hist} in selftest (Masami Hiramatsu)
>  - Fix onmatch(sched.sched_waking) (Namhyung Kim)
>  - Rename test to say trace_marker trigger from event trigger (Steven Rostedt)
> 
>  Diff from v2 below.
> 
>  Documentation/trace/events.rst                     |   6 +-
>  Documentation/trace/ftrace.rst                     |   5 +
>  Documentation/trace/histogram.txt                  | 546 ++++++++++++++++++++-
>  include/linux/trace_events.h                       |   3 +-
>  include/trace/trace_events.h                       |   1 +
>  kernel/trace/trace.c                               |  19 +
>  kernel/trace/trace.h                               |   9 +-
>  kernel/trace/trace_entries.h                       |   6 +-
>  kernel/trace/trace_events.c                        |  36 +-
>  kernel/trace/trace_events_filter.c                 |  23 +-
>  kernel/trace/trace_events_hist.c                   |   2 +-
>  kernel/trace/trace_events_trigger.c                |   6 +-
>  kernel/trace/trace_export.c                        |   9 +-
>  tools/testing/selftests/ftrace/test.d/functions    |  23 +-
>  .../test.d/trigger/trigger-trace-marker-hist.tc    |  49 ++
>  .../trigger/trigger-trace-marker-synthetic.tc      |  88 ++++
>  16 files changed, 790 insertions(+), 41 deletions(-)
>  create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
>  create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> 
> 
> diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt
> index 8c871f0c0e33..ae2d4f9d0a62 100644
> --- a/Documentation/trace/histogram.txt
> +++ b/Documentation/trace/histogram.txt
> @@ -2005,7 +2005,7 @@ and after it wakes up, something like this:
>  
>  static void traceputs(char *str)
>  {
> -	/* tracemark_fd is the trace_marker file descripto */
> +	/* tracemark_fd is the trace_marker file descriptor */
>  	if (tracemark_fd < 0)
>  		return;
>  	/* write the tracemark message */
> @@ -2048,7 +2048,7 @@ Now running cyclictest with:
>  
>  Note, the -b 1000 is used just to make --tracemark available.
>  
> -The we can see the histogram created by this with:
> +Then we can see the histogram created by this with:
>  
>   # cat events/synthetic/latency/hist
>  # event histogram
> @@ -2360,7 +2360,7 @@ kernel with trace_marker.
>  
>  The difference this time is that instead of using the trace_marker to start
>  the latency, the sched_waking event is used, matching the common_pid for the
> -trace_marker write with the pid that is being worken by sched_waking.
> +trace_marker write with the pid that is being woken by sched_waking.
>  
>  After running cyclictest again with the same parameters, we now have:
>  
> @@ -2535,5 +2535,5 @@ Totals:
>      Dropped: 0
>  
>  This doesn't tell us any information about how late cyclictest may have
> -worken up, but it does show us a nice histogram of how long it took from
> -the time that cyclictest was worken to the time it made it into user space.
> +woken up, but it does show us a nice histogram of how long it took from
> +the time that cyclictest was woken to the time it made it into user space.
> diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
> similarity index 93%
> rename from tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker.tc
> rename to tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
> index 48e7ac1ccbc1..2acbfe2c0c0c 100644
> --- a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker.tc
> +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
> @@ -1,6 +1,6 @@
>  #!/bin/sh
>  # SPDX-License-Identifier: GPL-2.0
> -# description: event trigger - test histogram trigger
> +# description: trace_marker trigger - test histogram trigger
>  # flags: instance
>  
>  do_reset() {
> diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> index d8cfc36f228b..b06996ecd5e0 100644
> --- a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> @@ -1,6 +1,6 @@
>  #!/bin/sh
>  # SPDX-License-Identifier: GPL-2.0
> -# description: event trigger - test histogram with synthetic event
> +# description: trace_marker trigger - test histogram with synthetic event
>  # flags:
>  
>  do_reset() {
> @@ -72,7 +72,7 @@ echo "Test histogram kernel event to trace_marker latency histogram trigger"
>  
>  echo 'latency u64 lat' > synthetic_events
>  echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
> -echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat)' > events/ftrace/print/trigger
> +echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat)' > events/ftrace/print/trigger
>  echo 'hist:keys=common_pid,lat:sort=lat' > events/synthetic/latency/trigger
>  sleep 1
>  echo "hello" > trace_marker

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH v3 13/14] tracing/selftest: Add selftests to test trace_marker histogram triggers
  2018-05-16 15:00 ` [PATCH v3 13/14] tracing/selftest: Add selftests to test trace_marker histogram triggers Steven Rostedt
@ 2018-05-23 14:13   ` Masami Hiramatsu
  2018-05-25 18:07     ` Steven Rostedt
  0 siblings, 1 reply; 28+ messages in thread
From: Masami Hiramatsu @ 2018-05-23 14:13 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Thomas Gleixner,
	Tom Zanussi, Clark Williams, Karim Yaghmour, Brendan Gregg,
	Joel Fernandes, Masami Hiramatsu, Namhyung Kim, Yann Ylavic,
	linux-rt-users

On Wed, 16 May 2018 11:00:25 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
> 
> Add a couple of tests that test the trace_marker histogram triggers.
> One does a straight histogram test, the other will create a synthetic event
> and test the latency between two different writes (using filters to
> differentiate between them).
> 

This looks good to me.

Acked-by: Masami Hiramatsu <mhiramat@kernel.org>

BTW, would you plan to add simplar test case for the marker?
(like just write a marker and read trace log, and run a simple
 trigger, like taking a snapshot by marker)

Thanks,

> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>  .../trigger/trigger-trace-marker-hist.tc      | 49 ++++++++++++++
>  .../trigger/trigger-trace-marker-synthetic.tc | 66 +++++++++++++++++++
>  2 files changed, 115 insertions(+)
>  create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
>  create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> 
> diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
> new file mode 100644
> index 000000000000..2acbfe2c0c0c
> --- /dev/null
> +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc
> @@ -0,0 +1,49 @@
> +#!/bin/sh
> +# SPDX-License-Identifier: GPL-2.0
> +# description: trace_marker trigger - test histogram trigger
> +# flags: instance
> +
> +do_reset() {
> +    reset_trigger
> +    echo > set_event
> +    clear_trace
> +}
> +
> +fail() { #msg
> +    do_reset
> +    echo $1
> +    exit_fail
> +}
> +
> +if [ ! -f set_event ]; then
> +    echo "event tracing is not supported"
> +    exit_unsupported
> +fi
> +
> +if [ ! -d events/ftrace/print ]; then
> +    echo "event trace_marker is not supported"
> +    exit_unsupported
> +fi
> +
> +if [ ! -f events/ftrace/print/trigger ]; then
> +    echo "event trigger is not supported"
> +    exit_unsupported
> +fi
> +
> +if [ ! -f events/ftrace/print/hist ]; then
> +    echo "hist trigger is not supported"
> +    exit_unsupported
> +fi
> +
> +do_reset
> +
> +echo "Test histogram trace_marker tigger"
> +
> +echo 'hist:keys=common_pid' > events/ftrace/print/trigger
> +for i in `seq 1 10` ; do echo "hello" > trace_marker; done
> +grep 'hitcount: *10$' events/ftrace/print/hist > /dev/null || \
> +    fail "hist trigger did not trigger correct times on trace_marker"
> +
> +do_reset
> +
> +exit 0
> diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> new file mode 100644
> index 000000000000..3666dd6ab02a
> --- /dev/null
> +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> @@ -0,0 +1,66 @@
> +#!/bin/sh
> +# SPDX-License-Identifier: GPL-2.0
> +# description: trace_marker trigger - test histogram with synthetic event
> +# flags:
> +
> +do_reset() {
> +    reset_trigger
> +    echo > set_event
> +    echo > synthetic_events
> +    clear_trace
> +}
> +
> +fail() { #msg
> +    do_reset
> +    echo $1
> +    exit_fail
> +}
> +
> +if [ ! -f set_event ]; then
> +    echo "event tracing is not supported"
> +    exit_unsupported
> +fi
> +
> +if [ ! -f synthetic_events ]; then
> +    echo "synthetic events not supported"
> +    exit_unsupported
> +fi
> +
> +if [ ! -d events/ftrace/print ]; then
> +    echo "event trace_marker is not supported"
> +    exit_unsupported
> +fi
> +
> +if [ ! -f events/ftrace/print/trigger ]; then
> +    echo "event trigger is not supported"
> +    exit_unsupported
> +fi
> +
> +if [ ! -f events/ftrace/print/hist ]; then
> +    echo "hist trigger is not supported"
> +    exit_unsupported
> +fi
> +
> +do_reset
> +
> +echo "Test histogram trace_marker to trace_marker latency histogram trigger"
> +
> +echo 'latency u64 lat' > synthetic_events
> +echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger
> +echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger
> +echo 'hist:keys=common_pid,lat:sort=lat' > events/synthetic/latency/trigger
> +echo -n "start" > trace_marker
> +echo -n "end" > trace_marker
> +
> +cnt=`grep 'hitcount: *1$' events/ftrace/print/hist | wc -l`
> +
> +if [ $cnt -ne 2 ]; then
> +    fail "hist trace_marker trigger did not trigger correctly"
> +fi
> +
> +grep 'hitcount: *1$' events/synthetic/latency/hist > /dev/null || \
> +    fail "hist trigger did not trigger "
> +
> +do_reset
> +
> +exit 0
> -- 
> 2.17.0
> 
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH v3 14/14] tracing/selftest: Add test to test hist trigger between kernel event and trace_marker
  2018-05-16 15:00 ` [PATCH v3 14/14] tracing/selftest: Add test to test hist trigger between kernel event and trace_marker Steven Rostedt
@ 2018-05-23 14:15   ` Masami Hiramatsu
  2018-05-25 18:15     ` Steven Rostedt
  0 siblings, 1 reply; 28+ messages in thread
From: Masami Hiramatsu @ 2018-05-23 14:15 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Thomas Gleixner,
	Tom Zanussi, Clark Williams, Karim Yaghmour, Brendan Gregg,
	Joel Fernandes, Masami Hiramatsu, Namhyung Kim, Yann Ylavic,
	linux-rt-users

On Wed, 16 May 2018 11:00:26 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
> 
> Add a test that tests a trigger that is initiated by a kernel event
> (sched_waking) and compared to a write to the trace_marker.
> 
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>  .../trigger/trigger-trace-marker-synthetic.tc | 22 +++++++++++++++++++
>  1 file changed, 22 insertions(+)
> 
> diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> index 3666dd6ab02a..b06996ecd5e0 100644
> --- a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> @@ -31,6 +31,11 @@ if [ ! -d events/ftrace/print ]; then
>      exit_unsupported
>  fi
>  
> +if [ ! -d events/sched/sched_waking ]; then
> +    echo "event sched_waking is not supported"
> +    exit_unsupported
> +fi

Hmm, this looks no good sign... Can you split this out to another testcase,
since this check is only for new test case below?

[..]
> @@ -63,4 +68,21 @@ grep 'hitcount: *1$' events/synthetic/latency/hist > /dev/null || \
>  
>  do_reset
>  
> +echo "Test histogram kernel event to trace_marker latency histogram trigger"
> +
> +echo 'latency u64 lat' > synthetic_events
> +echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
> +echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat)' > events/ftrace/print/trigger
> +echo 'hist:keys=common_pid,lat:sort=lat' > events/synthetic/latency/trigger
> +sleep 1
> +echo "hello" > trace_marker
> +
> +grep 'hitcount: *1$' events/ftrace/print/hist > /dev/null || \
> +    fail "hist trigger did not trigger correct times on trace_marker"
> +
> +grep 'hitcount: *1$' events/synthetic/latency/hist > /dev/null || \
> +    fail "hist trigger did not trigger "
> +
> +do_reset
> +

Thank you,



-- 
Masami Hiramatsu <mhiramat@kernel.org>

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH v3 13/14] tracing/selftest: Add selftests to test trace_marker histogram triggers
  2018-05-23 14:13   ` Masami Hiramatsu
@ 2018-05-25 18:07     ` Steven Rostedt
  2018-05-25 21:12       ` Steven Rostedt
  0 siblings, 1 reply; 28+ messages in thread
From: Steven Rostedt @ 2018-05-25 18:07 UTC (permalink / raw)
  To: Masami Hiramatsu
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Thomas Gleixner,
	Tom Zanussi, Clark Williams, Karim Yaghmour, Brendan Gregg,
	Joel Fernandes, Namhyung Kim, Yann Ylavic, linux-rt-users

On Wed, 23 May 2018 23:13:31 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> This looks good to me.
> 
> Acked-by: Masami Hiramatsu <mhiramat@kernel.org>

Thanks!

> 
> BTW, would you plan to add simplar test case for the marker?
> (like just write a marker and read trace log, and run a simple
>  trigger, like taking a snapshot by marker)

I wasn't planning to, but I could.

-- Steve

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH v3 14/14] tracing/selftest: Add test to test hist trigger between kernel event and trace_marker
  2018-05-23 14:15   ` Masami Hiramatsu
@ 2018-05-25 18:15     ` Steven Rostedt
  2018-05-25 18:19       ` Steven Rostedt
  0 siblings, 1 reply; 28+ messages in thread
From: Steven Rostedt @ 2018-05-25 18:15 UTC (permalink / raw)
  To: Masami Hiramatsu
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Thomas Gleixner,
	Tom Zanussi, Clark Williams, Karim Yaghmour, Brendan Gregg,
	Joel Fernandes, Namhyung Kim, Yann Ylavic, linux-rt-users

On Wed, 23 May 2018 23:15:59 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> On Wed, 16 May 2018 11:00:26 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
> > 
> > Add a test that tests a trigger that is initiated by a kernel event
> > (sched_waking) and compared to a write to the trace_marker.
> > 
> > Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> > ---
> >  .../trigger/trigger-trace-marker-synthetic.tc | 22 +++++++++++++++++++
> >  1 file changed, 22 insertions(+)
> > 
> > diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> > index 3666dd6ab02a..b06996ecd5e0 100644
> > --- a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> > +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc
> > @@ -31,6 +31,11 @@ if [ ! -d events/ftrace/print ]; then
> >      exit_unsupported
> >  fi
> >  
> > +if [ ! -d events/sched/sched_waking ]; then
> > +    echo "event sched_waking is not supported"
> > +    exit_unsupported
> > +fi  
> 
> Hmm, this looks no good sign... Can you split this out to another testcase,
> since this check is only for new test case below?
> 

You mean like this?

-- Steve


>From 9a34a00fb3c44e5adebb31e6e7d9e8c233797200 Mon Sep 17 00:00:00 2001
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Date: Mon, 14 May 2018 15:47:07 -0400
Subject: [PATCH] tracing/selftest: Add test to test hist trigger between
 kernel event and trace_marker

Add a test that tests a trigger that is initiated by a kernel event
(sched_waking) and compared to a write to the trace_marker.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 .../trigger-trace-marker-synthetic-kernel.tc       | 68 ++++++++++++++++++++++
 1 file changed, 68 insertions(+)
 create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc

diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc
new file mode 100644
index 000000000000..447df015c56f
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc
@@ -0,0 +1,68 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: trace_marker trigger - test histogram with synthetic event
+# flags:
+
+do_reset() {
+    reset_trigger
+    echo > set_event
+    echo > synthetic_events
+    clear_trace
+}
+
+fail() { #msg
+    do_reset
+    echo $1
+    exit_fail
+}
+
+if [ ! -f set_event ]; then
+    echo "event tracing is not supported"
+    exit_unsupported
+fi
+
+if [ ! -f synthetic_events ]; then
+    echo "synthetic events not supported"
+    exit_unsupported
+fi
+
+if [ ! -d events/ftrace/print ]; then
+    echo "event trace_marker is not supported"
+    exit_unsupported
+fi
+
+if [ ! -d events/sched/sched_waking ]; then
+    echo "event sched_waking is not supported"
+    exit_unsupported
+fi
+
+if [ ! -f events/ftrace/print/trigger ]; then
+    echo "event trigger is not supported"
+    exit_unsupported
+fi
+
+if [ ! -f events/ftrace/print/hist ]; then
+    echo "hist trigger is not supported"
+    exit_unsupported
+fi
+
+do_reset
+
+echo "Test histogram kernel event to trace_marker latency histogram trigger"
+
+echo 'latency u64 lat' > synthetic_events
+echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
+echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat)' > events/ftrace/print/trigger
+echo 'hist:keys=common_pid,lat:sort=lat' > events/synthetic/latency/trigger
+sleep 1
+echo "hello" > trace_marker
+
+grep 'hitcount: *1$' events/ftrace/print/hist > /dev/null || \
+    fail "hist trigger did not trigger correct times on trace_marker"
+
+grep 'hitcount: *1$' events/synthetic/latency/hist > /dev/null || \
+    fail "hist trigger did not trigger "
+
+do_reset
+
+exit 0
-- 
2.13.6

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* Re: [PATCH v3 14/14] tracing/selftest: Add test to test hist trigger between kernel event and trace_marker
  2018-05-25 18:15     ` Steven Rostedt
@ 2018-05-25 18:19       ` Steven Rostedt
  2018-05-27 16:33         ` Masami Hiramatsu
  0 siblings, 1 reply; 28+ messages in thread
From: Steven Rostedt @ 2018-05-25 18:19 UTC (permalink / raw)
  To: Masami Hiramatsu
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Thomas Gleixner,
	Tom Zanussi, Clark Williams, Karim Yaghmour, Brendan Gregg,
	Joel Fernandes, Namhyung Kim, Yann Ylavic, linux-rt-users

On Fri, 25 May 2018 14:15:06 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc
> new file mode 100644
> index 000000000000..447df015c56f
> --- /dev/null
> +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc
> @@ -0,0 +1,68 @@
> +#!/bin/sh
> +# SPDX-License-Identifier: GPL-2.0
> +# description: trace_marker trigger - test histogram with synthetic event
> +# flags:
> +

I forgot to update the description. Here's the new patch:

-- Steve

>From 9699fdb67ba8ea9981bd0af1802209b0011a86ab Mon Sep 17 00:00:00 2001
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Date: Mon, 14 May 2018 15:47:07 -0400
Subject: [PATCH] tracing/selftest: Add test to test hist trigger between
 kernel event and trace_marker

Add a test that tests a trigger that is initiated by a kernel event
(sched_waking) and compared to a write to the trace_marker.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 .../trigger-trace-marker-synthetic-kernel.tc       | 68 ++++++++++++++++++++++
 1 file changed, 68 insertions(+)
 create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc

diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc
new file mode 100644
index 000000000000..0a69c5d1cda8
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc
@@ -0,0 +1,68 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: trace_marker trigger - test histogram with synthetic event against kernel event
+# flags:
+
+do_reset() {
+    reset_trigger
+    echo > set_event
+    echo > synthetic_events
+    clear_trace
+}
+
+fail() { #msg
+    do_reset
+    echo $1
+    exit_fail
+}
+
+if [ ! -f set_event ]; then
+    echo "event tracing is not supported"
+    exit_unsupported
+fi
+
+if [ ! -f synthetic_events ]; then
+    echo "synthetic events not supported"
+    exit_unsupported
+fi
+
+if [ ! -d events/ftrace/print ]; then
+    echo "event trace_marker is not supported"
+    exit_unsupported
+fi
+
+if [ ! -d events/sched/sched_waking ]; then
+    echo "event sched_waking is not supported"
+    exit_unsupported
+fi
+
+if [ ! -f events/ftrace/print/trigger ]; then
+    echo "event trigger is not supported"
+    exit_unsupported
+fi
+
+if [ ! -f events/ftrace/print/hist ]; then
+    echo "hist trigger is not supported"
+    exit_unsupported
+fi
+
+do_reset
+
+echo "Test histogram kernel event to trace_marker latency histogram trigger"
+
+echo 'latency u64 lat' > synthetic_events
+echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
+echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat)' > events/ftrace/print/trigger
+echo 'hist:keys=common_pid,lat:sort=lat' > events/synthetic/latency/trigger
+sleep 1
+echo "hello" > trace_marker
+
+grep 'hitcount: *1$' events/ftrace/print/hist > /dev/null || \
+    fail "hist trigger did not trigger correct times on trace_marker"
+
+grep 'hitcount: *1$' events/synthetic/latency/hist > /dev/null || \
+    fail "hist trigger did not trigger "
+
+do_reset
+
+exit 0
-- 
2.13.6

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* Re: [PATCH v3 13/14] tracing/selftest: Add selftests to test trace_marker histogram triggers
  2018-05-25 18:07     ` Steven Rostedt
@ 2018-05-25 21:12       ` Steven Rostedt
  2018-05-25 21:13         ` Steven Rostedt
  0 siblings, 1 reply; 28+ messages in thread
From: Steven Rostedt @ 2018-05-25 21:12 UTC (permalink / raw)
  To: Masami Hiramatsu
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Thomas Gleixner,
	Tom Zanussi, Clark Williams, Karim Yaghmour, Brendan Gregg,
	Joel Fernandes, Namhyung Kim, Yann Ylavic, linux-rt-users

On Fri, 25 May 2018 14:07:31 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:


> > 
> > BTW, would you plan to add simplar test case for the marker?
> > (like just write a marker and read trace log, and run a simple
> >  trigger, like taking a snapshot by marker)  
> 
> I wasn't planning to, but I could.

Like something like this?

I had to remove the "instance" flag because it triggered a bug, that is
unrelated to this patch series. But that's a good thing. It found a
bug :-)

-- Steve

#!/bin/sh
# SPDX-License-Identifier: GPL-2.0
# description: trace_marker trigger - test snapshot trigger
# flags:

do_reset() {
    reset_trigger
    echo > set_event
    echo 0 > snapshot
    clear_trace
}

fail() { #msg
    do_reset
    echo $1
    exit_fail
}

if [ ! -f set_event ]; then
    echo "event tracing is not supported"
    exit_unsupported
fi

if [ ! -f snapshot ]; then
    echo "snapshot is not supported"
    exit_unsupported
fi

if [ ! -d events/ftrace/print ]; then
    echo "event trace_marker is not supported"
    exit_unsupported
fi

if [ ! -f events/ftrace/print/trigger ]; then
    echo "event trigger is not supported"
    exit_unsupported
fi

test_trace() {
    file=$1
    x=$2

    cat $file | while read line; do
	if [ "$line" != "${line/\#/}" ]; then
	    continue
	fi
	echo "testing $line for >$x<"
	if [ "$line" == "${line/>$x</}" ]; then
	    fail "$line does not have >$x< in it"
	fi
	let x=$x+2
    done
}

do_reset

echo "Test snapshot trace_marker tigger"

echo 'snapshot' > events/ftrace/print/trigger

# make sure the snapshot is allocated

grep -q 'Snapshot is allocated' snapshot

for i in `seq 1 10` ; do echo "hello >$i<" > trace_marker; done

test_trace trace 1
test_trace snapshot 2

do_reset

exit 0

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH v3 13/14] tracing/selftest: Add selftests to test trace_marker histogram triggers
  2018-05-25 21:12       ` Steven Rostedt
@ 2018-05-25 21:13         ` Steven Rostedt
  2018-05-27 16:32           ` Masami Hiramatsu
  0 siblings, 1 reply; 28+ messages in thread
From: Steven Rostedt @ 2018-05-25 21:13 UTC (permalink / raw)
  To: Masami Hiramatsu
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Thomas Gleixner,
	Tom Zanussi, Clark Williams, Karim Yaghmour, Brendan Gregg,
	Joel Fernandes, Namhyung Kim, Yann Ylavic, linux-rt-users,
	Shuah Khan

On Fri, 25 May 2018 17:12:29 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

 
> #!/bin/sh

Hmm, I think I need to make this #!/bin/bash

> test_trace() {
>     file=$1
>     x=$2
> 
>     cat $file | while read line; do
> 	if [ "$line" != "${line/\#/}" ]; then
> 	    continue
> 	fi
> 	echo "testing $line for >$x<"
> 	if [ "$line" == "${line/>$x</}" ]; then

The ${line/>$x</} is unique to bash I believe.

-- Steve

> 	    fail "$line does not have >$x< in it"
> 	fi
> 	let x=$x+2
>     done
> }
> 

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH v3 13/14] tracing/selftest: Add selftests to test trace_marker histogram triggers
  2018-05-25 21:13         ` Steven Rostedt
@ 2018-05-27 16:32           ` Masami Hiramatsu
  2018-05-29  1:20             ` Steven Rostedt
  0 siblings, 1 reply; 28+ messages in thread
From: Masami Hiramatsu @ 2018-05-27 16:32 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Thomas Gleixner,
	Tom Zanussi, Clark Williams, Karim Yaghmour, Brendan Gregg,
	Joel Fernandes, Namhyung Kim, Yann Ylavic, linux-rt-users,
	Shuah Khan

Hi Steve,

On Fri, 25 May 2018 17:13:53 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Fri, 25 May 2018 17:12:29 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
>  
> > #!/bin/sh
> 
> Hmm, I think I need to make this #!/bin/bash
> 
> > test_trace() {
> >     file=$1
> >     x=$2
> > 
> >     cat $file | while read line; do
> > 	if [ "$line" != "${line/\#/}" ]; then
> > 	    continue
> > 	fi
> > 	echo "testing $line for >$x<"
> > 	if [ "$line" == "${line/>$x</}" ]; then
> 
> The ${line/>$x</} is unique to bash I believe.

Hmm, could you try to use only posix-shell based test ?
Since I would like to keep this can run on small 
environment, like busybox, etc.

Thank you,

> 
> -- Steve
> 
> > 	    fail "$line does not have >$x< in it"
> > 	fi
> > 	let x=$x+2
> >     done
> > }
> > 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH v3 14/14] tracing/selftest: Add test to test hist trigger between kernel event and trace_marker
  2018-05-25 18:19       ` Steven Rostedt
@ 2018-05-27 16:33         ` Masami Hiramatsu
  0 siblings, 0 replies; 28+ messages in thread
From: Masami Hiramatsu @ 2018-05-27 16:33 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Thomas Gleixner,
	Tom Zanussi, Clark Williams, Karim Yaghmour, Brendan Gregg,
	Joel Fernandes, Namhyung Kim, Yann Ylavic, linux-rt-users

On Fri, 25 May 2018 14:19:43 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Fri, 25 May 2018 14:15:06 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc
> > new file mode 100644
> > index 000000000000..447df015c56f
> > --- /dev/null
> > +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc
> > @@ -0,0 +1,68 @@
> > +#!/bin/sh
> > +# SPDX-License-Identifier: GPL-2.0
> > +# description: trace_marker trigger - test histogram with synthetic event
> > +# flags:
> > +
> 
> I forgot to update the description. Here's the new patch:
> 
> -- Steve
> 
> From 9699fdb67ba8ea9981bd0af1802209b0011a86ab Mon Sep 17 00:00:00 2001
> From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
> Date: Mon, 14 May 2018 15:47:07 -0400
> Subject: [PATCH] tracing/selftest: Add test to test hist trigger between
>  kernel event and trace_marker
> 
> Add a test that tests a trigger that is initiated by a kernel event
> (sched_waking) and compared to a write to the trace_marker.
> 

Yeah, this looks good to me :)

Acked-by: Masami Hiramatsu <mhiramat@kernel.org>

Thanks!

> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ---
>  .../trigger-trace-marker-synthetic-kernel.tc       | 68 ++++++++++++++++++++++
>  1 file changed, 68 insertions(+)
>  create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc
> 
> diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc
> new file mode 100644
> index 000000000000..0a69c5d1cda8
> --- /dev/null
> +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc
> @@ -0,0 +1,68 @@
> +#!/bin/sh
> +# SPDX-License-Identifier: GPL-2.0
> +# description: trace_marker trigger - test histogram with synthetic event against kernel event
> +# flags:
> +
> +do_reset() {
> +    reset_trigger
> +    echo > set_event
> +    echo > synthetic_events
> +    clear_trace
> +}
> +
> +fail() { #msg
> +    do_reset
> +    echo $1
> +    exit_fail
> +}
> +
> +if [ ! -f set_event ]; then
> +    echo "event tracing is not supported"
> +    exit_unsupported
> +fi
> +
> +if [ ! -f synthetic_events ]; then
> +    echo "synthetic events not supported"
> +    exit_unsupported
> +fi
> +
> +if [ ! -d events/ftrace/print ]; then
> +    echo "event trace_marker is not supported"
> +    exit_unsupported
> +fi
> +
> +if [ ! -d events/sched/sched_waking ]; then
> +    echo "event sched_waking is not supported"
> +    exit_unsupported
> +fi
> +
> +if [ ! -f events/ftrace/print/trigger ]; then
> +    echo "event trigger is not supported"
> +    exit_unsupported
> +fi
> +
> +if [ ! -f events/ftrace/print/hist ]; then
> +    echo "hist trigger is not supported"
> +    exit_unsupported
> +fi
> +
> +do_reset
> +
> +echo "Test histogram kernel event to trace_marker latency histogram trigger"
> +
> +echo 'latency u64 lat' > synthetic_events
> +echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
> +echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat)' > events/ftrace/print/trigger
> +echo 'hist:keys=common_pid,lat:sort=lat' > events/synthetic/latency/trigger
> +sleep 1
> +echo "hello" > trace_marker
> +
> +grep 'hitcount: *1$' events/ftrace/print/hist > /dev/null || \
> +    fail "hist trigger did not trigger correct times on trace_marker"
> +
> +grep 'hitcount: *1$' events/synthetic/latency/hist > /dev/null || \
> +    fail "hist trigger did not trigger "
> +
> +do_reset
> +
> +exit 0
> -- 
> 2.13.6
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

^ permalink raw reply	[flat|nested] 28+ messages in thread

* Re: [PATCH v3 13/14] tracing/selftest: Add selftests to test trace_marker histogram triggers
  2018-05-27 16:32           ` Masami Hiramatsu
@ 2018-05-29  1:20             ` Steven Rostedt
  2018-05-30 23:09               ` Masami Hiramatsu
  0 siblings, 1 reply; 28+ messages in thread
From: Steven Rostedt @ 2018-05-29  1:20 UTC (permalink / raw)
  To: Masami Hiramatsu
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Thomas Gleixner,
	Tom Zanussi, Clark Williams, Karim Yaghmour, Brendan Gregg,
	Joel Fernandes, Namhyung Kim, Yann Ylavic, linux-rt-users,
	Shuah Khan

On Mon, 28 May 2018 01:32:58 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> Hi Steve,
> 
> On Fri, 25 May 2018 17:13:53 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Fri, 25 May 2018 17:12:29 -0400
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> >    
> > > #!/bin/sh  
> > 
> > Hmm, I think I need to make this #!/bin/bash
> >   
> > > test_trace() {
> > >     file=$1
> > >     x=$2
> > > 
> > >     cat $file | while read line; do
> > > 	if [ "$line" != "${line/\#/}" ]; then
> > > 	    continue
> > > 	fi
> > > 	echo "testing $line for >$x<"
> > > 	if [ "$line" == "${line/>$x</}" ]; then  
> > 
> > The ${line/>$x</} is unique to bash I believe.  
> 
> Hmm, could you try to use only posix-shell based test ?
> Since I would like to keep this can run on small 
> environment, like busybox, etc.
>

Like something like this?

-- Steve

diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-snapshot.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-snapshot.tc
index c6c50a2..3a3c33d 100644
--- a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-snapshot.tc
+++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-snapshot.tc
@@ -41,11 +41,13 @@ test_trace() {
     x=$2
 
     cat $file | while read line; do
-	if [ "$line" != "${line/\#/}" ]; then
+	comment=`echo $line | sed -e 's/^#//'`
+	if [ "$line" != "$comment" ]; then
 	    continue
 	fi
 	echo "testing $line for >$x<"
-	if [ "$line" == "${line/>$x</}" ]; then
+	match=`echo $line | sed -e "s/>$x<//"`
+	if [ "$line" == "$match" ]; then
 	    fail "$line does not have >$x< in it"
 	fi
 	let x=$x+2

^ permalink raw reply related	[flat|nested] 28+ messages in thread

* Re: [PATCH v3 13/14] tracing/selftest: Add selftests to test trace_marker histogram triggers
  2018-05-29  1:20             ` Steven Rostedt
@ 2018-05-30 23:09               ` Masami Hiramatsu
  0 siblings, 0 replies; 28+ messages in thread
From: Masami Hiramatsu @ 2018-05-30 23:09 UTC (permalink / raw)
  To: Steven Rostedt
  Cc: linux-kernel, Ingo Molnar, Andrew Morton, Thomas Gleixner,
	Tom Zanussi, Clark Williams, Karim Yaghmour, Brendan Gregg,
	Joel Fernandes, Namhyung Kim, Yann Ylavic, linux-rt-users,
	Shuah Khan

On Mon, 28 May 2018 21:20:55 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Mon, 28 May 2018 01:32:58 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > Hi Steve,
> > 
> > On Fri, 25 May 2018 17:13:53 -0400
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > On Fri, 25 May 2018 17:12:29 -0400
> > > Steven Rostedt <rostedt@goodmis.org> wrote:
> > > 
> > >    
> > > > #!/bin/sh  
> > > 
> > > Hmm, I think I need to make this #!/bin/bash
> > >   
> > > > test_trace() {
> > > >     file=$1
> > > >     x=$2
> > > > 
> > > >     cat $file | while read line; do
> > > > 	if [ "$line" != "${line/\#/}" ]; then
> > > > 	    continue
> > > > 	fi
> > > > 	echo "testing $line for >$x<"
> > > > 	if [ "$line" == "${line/>$x</}" ]; then  
> > > 
> > > The ${line/>$x</} is unique to bash I believe.  
> > 
> > Hmm, could you try to use only posix-shell based test ?
> > Since I would like to keep this can run on small 
> > environment, like busybox, etc.
> >
> 
> Like something like this?

This looks good to me. :)

Acked-by: Masami Hiramatsu <mhiramat@kernel.org>

Thanks,

> 
> -- Steve
> 
> diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-snapshot.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-snapshot.tc
> index c6c50a2..3a3c33d 100644
> --- a/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-snapshot.tc
> +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-snapshot.tc
> @@ -41,11 +41,13 @@ test_trace() {
>      x=$2
>  
>      cat $file | while read line; do
> -	if [ "$line" != "${line/\#/}" ]; then
> +	comment=`echo $line | sed -e 's/^#//'`
> +	if [ "$line" != "$comment" ]; then
>  	    continue
>  	fi
>  	echo "testing $line for >$x<"
> -	if [ "$line" == "${line/>$x</}" ]; then
> +	match=`echo $line | sed -e "s/>$x<//"`
> +	if [ "$line" == "$match" ]; then
>  	    fail "$line does not have >$x< in it"
>  	fi
>  	let x=$x+2


-- 
Masami Hiramatsu <mhiramat@kernel.org>

^ permalink raw reply	[flat|nested] 28+ messages in thread

end of thread, other threads:[~2018-05-30 23:09 UTC | newest]

Thread overview: 28+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-05-16 15:00 [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 01/14] tracing: Do not reference event data in post call triggers Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 02/14] tracing: Add __find_event_file() to find event files without restrictions Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 03/14] tracing: Have event_trace_init() called by trace_init_tracefs() Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 04/14] tracing: Add brackets in ftrace event dynamic arrays Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 05/14] tracing: Do not show filter file for ftrace internal events Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 06/14] tracing: Add trigger file for trace_markers tracefs/ftrace/print Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 07/14] tracing: Have zero size length in filter logic be full string Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 08/14] tracing: Prevent further users of zero size static arrays in trace events Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 09/14] tracing: Allow histogram triggers to access ftrace internal events Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 10/14] tracing: Document trace_marker triggers Steven Rostedt
2018-05-16 15:42   ` [PATCH v3.5 " Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 11/14] ftrace/selftest: Have the reset_trigger code be a bit more careful Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 12/14] ftrace/selftest: Fix reset_trigger() to handle triggers with filters Steven Rostedt
2018-05-16 15:00 ` [PATCH v3 13/14] tracing/selftest: Add selftests to test trace_marker histogram triggers Steven Rostedt
2018-05-23 14:13   ` Masami Hiramatsu
2018-05-25 18:07     ` Steven Rostedt
2018-05-25 21:12       ` Steven Rostedt
2018-05-25 21:13         ` Steven Rostedt
2018-05-27 16:32           ` Masami Hiramatsu
2018-05-29  1:20             ` Steven Rostedt
2018-05-30 23:09               ` Masami Hiramatsu
2018-05-16 15:00 ` [PATCH v3 14/14] tracing/selftest: Add test to test hist trigger between kernel event and trace_marker Steven Rostedt
2018-05-23 14:15   ` Masami Hiramatsu
2018-05-25 18:15     ` Steven Rostedt
2018-05-25 18:19       ` Steven Rostedt
2018-05-27 16:33         ` Masami Hiramatsu
2018-05-23  5:41 ` [PATCH v3 00/14] tracing: Add triggers to trace_marker writes Namhyung Kim

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.