tracing: Add triggers to trace_marker writes

From: "Steven Rostedt (VMware)" <[email protected]>

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) <[email protected]>

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

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc new file +49 -0

new file mode 100644
index 000000000000..2acbfe2c0c0c
@@ -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

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc new file +66 -0

new file mode 100644
index 000000000000..3666dd6ab02a
@@ -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

Signature · 1 line

2.17.0

This looks good to me.

Acked-by Masami Hiramatsu <[email protected]>

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)

Quoted 4 lines

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.

#!/bin/sh

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
}

Quoted 1 line · On Fri, 25 May 2018 17:12:29 -0400 Steven Rostedt <[email protected]> wrote:

#!/bin/sh

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

Quoted 4 lines

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

Quoted 6 lines

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

Quoted 6 lines

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

Hi Steve,

Quoted 19 lines · On Fri, 25 May 2018 17:13:53 -0400 Steven Rostedt <[email protected]> wrote:

Quoted 1 line · On Fri, 25 May 2018 17:12:29 -0400 Steven Rostedt <[email protected]> wrote:

#!/bin/sh

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

Quoted 10 lines

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  

Quoted 1 line

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.

Quoted 24 lines · On Mon, 28 May 2018 01:32:58 +0900 Masami Hiramatsu <[email protected]> wrote:

Hi Steve,

Quoted 19 lines · On Fri, 25 May 2018 17:13:53 -0400 Steven Rostedt <[email protected]> wrote:

Quoted 1 line · On Fri, 25 May 2018 17:12:29 -0400 Steven Rostedt <[email protected]> wrote:

#!/bin/sh

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

Quoted 10 lines

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  

Quoted 6 lines

Quoted 1 line

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

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-snapshot.tc +4 -2

index c6c50a2..3a3c33d 100644
@@ -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

From: "Steven Rostedt (VMware)" <[email protected]>

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) <[email protected]>

---
 .../trigger/trigger-trace-marker-synthetic.tc | 22 +++++++++++++++++++
 1 file changed, 22 insertions(+)

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc +0 -0

index 3666dd6ab02a..b06996ecd5e0 100644

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc +7 -0

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

Quoted 18 lines · On Wed, 16 May 2018 11:00:26 -0400 Steven Rostedt <[email protected]> wrote:

From: "Steven Rostedt (VMware)" <[email protected]>

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) <[email protected]>

---
 .../trigger/trigger-trace-marker-synthetic.tc | 22 +++++++++++++++++++
 1 file changed, 22 insertions(+)

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc +0 -0

index 3666dd6ab02a..b06996ecd5e0 100644
@@ -31,6 +31,11 @@ if [ ! -d events/ftrace/print ]; then
     exit_unsupported
 fi
 

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc if [ ! -d events/ftrace/print ]; then · line 37

Quoted 4 lines

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc +4 -0

+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?

From 9a34a00fb3c44e5adebb31e6e7d9e8c233797200 Mon Sep 17 00:00:00 2001

From 9699fdb67ba8ea9981bd0af1802209b0011a86ab Mon Sep 17 00:00:00 2001

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc line 5

Quoted 11 lines · On Fri, 25 May 2018 14:15:06 -0400 Steven Rostedt <[email protected]> wrote:

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc new file +5 -0

new file mode 100644
index 000000000000..447df015c56f
@@ -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)" <[email protected]>
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) <[email protected]>

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

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic-kernel.tc new file +68 -0

new file mode 100644
index 000000000000..0a69c5d1cda8
@@ -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

Signature · 1 line

2.13.6

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/[email protected]

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

Documentation/trace/histogram.txt +5 -5

index 8c871f0c0e33..ae2d4f9d0a62 100644
@@ -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.

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-hist.tc renamed from tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker.tc +1 -1

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
@@ -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() {

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc +2 -2

index d8cfc36f228b..b06996ecd5e0 100644
@@ -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