tracing: Add triggers to trace_marker writes

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

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

---
 kernel/trace/trace_events.c | 10 ++++++----
 1 file changed, 6 insertions(+), 4 deletions(-)

kernel/trace/trace_events.c +1 -4

index 5b647904a65b..14ff4ff3caab 100644
@@ -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))

Quoted 14 lines

kernel/trace/trace_events.c +6 -2

 	/*
 	 * 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);
+	}

Quoted 2 lines

#ifdef CONFIG_HIST_TRIGGERS
trace_create_file("hist", 0444, file->dir, file,

What about moving the "hist" file as well since it's meaningless without the trigger.

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

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

Signed-off-by Steven Rostedt (VMware) <[email protected]>

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

Documentation/trace/events.rst +5 -1

index a5ea2cb0082b..1afae55dc55c 100644
@@ -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
 ---------------------
 

Documentation/trace/ftrace.rst +5 -0

index 67d9c38e95eb..aad4776c0f5d 100644
@@ -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

Documentation/trace/histogram.txt +4 -1

index 6e05510afc28..8c871f0c0e33 100644
@@ -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
+--------------------------------
+

Documentation/trace/histogram.txt +34 -0

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

Documentation/trace/histogram.txt +7 -0

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

Documentation/trace/histogram.txt +14 -0

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

Documentation/trace/histogram.txt +10 -0

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

Hi Steve,

This is a nice new event feature - thanks for doing it! Some minor typo comments below..

Quoted 8 lines

+3. User space creating a trigger
+--------------------------------

Documentation/trace/histogram.txt +6 -0

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

Documentation/trace/histogram.txt hist trigger specification. · line 2008

Quoted 6 lines

Documentation/trace/histogram.txt +5 -0

+and after it wakes up, something like this:
+
+static void traceputs(char *str)
+{
+	/* tracemark_fd is the trace_marker file descripto */

Should be 'descriptor'?

Quoted 9 lines

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

Documentation/trace/histogram.txt hist trigger specification. · line 2052

Quoted 6 lines

+ -b 1000 : stop if any latency is greater than 1000 microseconds

Documentation/trace/histogram.txt +5 -0

+
+Note, the -b 1000 is used just to make --tracemark available.
+
+The we can see the histogram created by this with:
+  

'Then we can..

Documentation/trace/histogram.txt hist trigger specification. · line 2363

Quoted 4 lines

Documentation/trace/histogram.txt +3 -0

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

s/worken/woken ?

Quoted 13 lines

Documentation/trace/histogram.txt +10 -0

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

snip

Quoted 1 line

Documentation/trace/histogram.txt hist trigger specification. · line 2539

Quoted 12 lines

Documentation/trace/histogram.txt +11 -0

+{ 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
+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.

A couple more that don't seem to be 'worken' ;-)

Quoted 4 lines · On Mon, 14 May 2018 16:47:07 -0500 Tom Zanussi <[email protected]>…

Hi Steve,

This is a nice new event feature - thanks for doing it! Some minor typo comments below..

Can I get an Acked-by from you?

Quoted 8 lines

Quoted 8 lines

+3. User space creating a trigger
+--------------------------------

Documentation/trace/histogram.txt +6 -0

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

Quoted 8 lines

Documentation/trace/histogram.txt hist trigger specification. · line 2008

Quoted 6 lines

Documentation/trace/histogram.txt +5 -0

+and after it wakes up, something like this:
+
+static void traceputs(char *str)
+{
+	/* tracemark_fd is the trace_marker file descripto */

Should be 'descriptor'?

Fixed.

Quoted 9 lines

Quoted 9 lines

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

Quoted 8 lines

Documentation/trace/histogram.txt hist trigger specification. · line 2052

Quoted 6 lines

+ -b 1000 : stop if any latency is greater than 1000 microseconds

Documentation/trace/histogram.txt +5 -0

+
+Note, the -b 1000 is used just to make --tracemark available.
+
+The we can see the histogram created by this with:
+  

'Then we can..

Fixed

Quoted 6 lines

Documentation/trace/histogram.txt hist trigger specification. · line 2363

Quoted 4 lines

Documentation/trace/histogram.txt +3 -0

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

s/worken/woken ?

Fixed. (It's kind of like Borken)

Quoted 18 lines

Quoted 14 lines

Documentation/trace/histogram.txt +10 -0

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

snip

Quoted 1 line

Quoted 14 lines

Documentation/trace/histogram.txt hist trigger specification. · line 2539

Quoted 12 lines

Documentation/trace/histogram.txt +11 -0

+{ 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
+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.

A couple more that don't seem to be 'worken' ;-)

I have an itchy 'r' finger.

Thanks for the review, I just updated this.

Oh, I guess I think I prefer a "Reviewed-by" tag instead of Ack (gives a stronger meaning).

Sure, but noticed in the new version you just posted, that this line is still in there for your second example:

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

Did you intend that, or am I missing something?

Anyway, you have my

Reviewed-by Tom Zanussi <[email protected]>

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

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.

Signed-off-by Steven Rostedt (VMware) <[email protected]>

---
 .../testing/selftests/ftrace/test.d/functions | 21 ++++++++++++++++---
 1 file changed, 18 insertions(+), 3 deletions(-)

tools/testing/selftests/ftrace/test.d/functions +18 -3

index 2a4f16fc9819..8393b1c06027 100644
@@ -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

Signature · 1 line

2.17.0

Quoted 10 lines · On Mon, 14 May 2018 16:58:56 -0400 Steven Rostedt <[email protected]> wrote:

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

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

Quoted 2 lines

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

Ah, right!

Acked-by Masami Hiramatsu <[email protected]>

I think this should go into stable tree too.

Thank you!

Quoted 47 lines

Signed-off-by Steven Rostedt (VMware) <[email protected]>

---
 .../testing/selftests/ftrace/test.d/functions | 21 ++++++++++++++++---
 1 file changed, 18 insertions(+), 3 deletions(-)

tools/testing/selftests/ftrace/test.d/functions +18 -3

index 2a4f16fc9819..8393b1c06027 100644
@@ -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

Signature · 1 line

2.17.0

Quoted 13 lines · On Wed, 16 May 2018 21:53:50 +0900 Masami Hiramatsu <[email protected]> wrote:

Quoted 10 lines · On Mon, 14 May 2018 16:58:56 -0400 Steven Rostedt <[email protected]> wrote:

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

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

Quoted 6 lines

Quoted 2 lines

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

Ah, right!

Acked-by Masami Hiramatsu <[email protected]>

Thanks!

Quoted 2 lines

I think this should go into stable tree too.

I wonder if I should break this into two patches then.

One for the actions before attached, and one for synthetic events?

Hmm, maybe not. As it can handle not having synthetic events, it should be OK to let the update go to a time when they were not there.

Thoughts?

-- Steve

Quoted 52 lines

Thank you!

Quoted 47 lines

Signed-off-by Steven Rostedt (VMware) <[email protected]>

---
 .../testing/selftests/ftrace/test.d/functions | 21 ++++++++++++++++---
 1 file changed, 18 insertions(+), 3 deletions(-)

tools/testing/selftests/ftrace/test.d/functions +18 -3

index 2a4f16fc9819..8393b1c06027 100644
@@ -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

Signature · 1 line

2.17.0

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

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]

Signed-off-by Steven Rostedt (VMware) <[email protected]>

---
 tools/testing/selftests/ftrace/test.d/functions | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

tools/testing/selftests/ftrace/test.d/functions +2 -2

index 8393b1c06027..e4645d5e3126 100644
@@ -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

Signature · 1 line

2.17.0

This also looks good to me and needs to go into stable.

Acked-by Masami Hiramatsu <[email protected]>

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

@@ -0,0 +1,66 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: event 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
+

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

@@ -0,0 +1,49 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: event 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

Signature · 1 line

2.17.0

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

Quoted 2 lines

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

But this test actually kicks histogram, maybe trigger-trace-marker-hist.tc will be better, since we may need to add a simpler testcase just for checking whether trace-marker works with some actions (e.g. enable/disable other events).

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 +5 -0

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

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

+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.17.0

tools/testing/selftests/ftrace/test.d/trigger/trigger-trace-marker-synthetic.tc grep 'hitcount: *1$' events/synthetic/latency/hist > /dev/null || \ · line 75

Quoted 5 lines

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

+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  

Shouldn't it be "onmatch(sched.sched_waking)" ?