[PATCH v3 00/14] tracing: Add triggers to trace_marker writes

From: Steven Rostedt
Date: Wed May 16 2018 - 10:29:51 EST


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@xxxxxxxxxxxxxxxxxx


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