ftrace: selftests: Add full glob matching and update ftracetest

Hi,

Here is the 3rd version of the series of patches to add full glob matching support in ftrace, and update ftracetest to fix bugs and add test for the glob matching and hexadecimal types.

Previous version is here:
https://lkml.org/lkml/2016/10/30/16

I've fix some bugs related to ftrace kconfig selection on ftracetest, and add --quiet option in this version.
Here is the short description, 3/9 - 5/9 are newly added.

[1/9] Add full glob matching support on ftrace's
function filter and event filter expression.
[2/9] Initialize ftrace before running each testcase.
(updated in v2 for checking supported features)
[3/9] Add --quiet option to suppress error logs [4/9] Fix snapshot trigger test to be unsupported
if the kernel has no snapshot feature.
[5/9] Fix hist trigger-mod test to run correctly
without syscall trace.
[6/9] Hide logs direcotry from git.
[7/9] Introduce temporary directory for test cases,
which is used for storing temporary test data.
[8/9] Add a testcase for function-name glob matching [9/9] Add a testcase for types of event arguments

Thanks,
---

Masami Hiramatsu (9):
ftrace: Support full glob matching
selftests: ftrace: Initialize ftrace before each test
selftests: ftrace: Add --quiet option not to show error logs on screen
selftests: ftrace: Check whether snapshot trigger is supported correctly
selftests: ftrace: Fix trigger-mod to run without syscall trace
selftests: ftrace: Hide ftracetest logs from git
selftests: ftrace: Introduce TMPDIR for temporary files
selftests: ftrace: Add a testcase for function filter glob match
selftests: ftrace: Add a testcase for types of kprobe event

 Documentation/trace/events.txt                     |    9 +---
 Documentation/trace/ftrace.txt                     |    9 +---
 kernel/trace/Kconfig                               |    2 +
 kernel/trace/ftrace.c                              |    4 ++
 kernel/trace/trace.c                               |    2 -
 kernel/trace/trace.h                               |    2 +
 kernel/trace/trace_events_filter.c                 |   17 +++++++
 tools/testing/selftests/ftrace/.gitignore          |    1 
 tools/testing/selftests/ftrace/ftracetest          |   12 ++++-
 .../ftrace/test.d/ftrace/func-filter-glob.tc       |   49 ++++++++++++++++++++
 tools/testing/selftests/ftrace/test.d/functions    |   28 +++++++++++
 .../ftrace/test.d/kprobe/kprobe_args_type.tc       |   37 +++++++++++++++
 .../ftrace/test.d/trigger/trigger-hist-mod.tc      |    2 -
 .../ftrace/test.d/trigger/trigger-snapshot.tc      |    5 ++
 14 files changed, 162 insertions(+), 17 deletions(-)
 create mode 100644 tools/testing/selftests/ftrace/.gitignore
 create mode 100644 tools/testing/selftests/ftrace/test.d/ftrace/func-filter-glob.tc
 create mode 100644 tools/testing/selftests/ftrace/test.d/kprobe/kprobe_args_type.tc

--
Masami Hiramatsu (Linaro Ltd.) <[email protected]>

Use glob_match() to support flexible glob wildcards (*,?) and character classes ([) for ftrace.
Since the full glob matching is slower than the current partial matching routines(*pat, pat*, *pat*), this leaves those routines and just add MATCH_GLOB for complex glob expression.

e.g.
----
[root@localhost tracing]# echo 'sched*group' > set_ftrace_filter [root@localhost tracing]# cat set_ftrace_filter sched_free_group
sched_change_group
sched_create_group
sched_online_group
sched_destroy_group
sched_offline_group
[root@localhost tracing]# echo '[Ss]y[Ss]_*' > set_ftrace_filter [root@localhost tracing]# head set_ftrace_filter sys_arch_prctl
sys_rt_sigreturn
sys_ioperm
SyS_iopl
sys_modify_ldt
SyS_mmap
SyS_set_thread_area
SyS_get_thread_area
SyS_set_tid_address
sys_fork
----

---
 Documentation/trace/events.txt     |    9 +++------
 Documentation/trace/ftrace.txt     |    9 +++------
 kernel/trace/Kconfig               |    2 ++
 kernel/trace/ftrace.c              |    4 ++++
 kernel/trace/trace.c               |    2 +-
 kernel/trace/trace.h               |    2 ++
 kernel/trace/trace_events_filter.c |   17 ++++++++++++++++-
 7 files changed, 31 insertions(+), 14 deletions(-)

index 08d74d7..2cc08d4 100644
@@ -189,16 +189,13 @@ And for string fields they are:
 
 ==, !=, ~
 
-The glob (~) only accepts a wild card character (*) at the start and or
-end of the string. For example:
+The glob (~) accepts a wild card character (*,?) and character classes
+([). For example:
 
   prev_comm ~ "*sh"
   prev_comm ~ "sh*"
   prev_comm ~ "*sh*"
-
-But does not allow for it to be within the string:
-
-  prev_comm ~ "ba*sh"   <-- is invalid
+  prev_comm ~ "ba*sh"
 
 5.2 Setting filters
 -------------------

index 185c39f..1bc66c1 100644
@@ -2218,16 +2218,13 @@ hrtimer_interrupt
 sys_nanosleep
 
 
-Perhaps this is not enough. The filters also allow simple wild
-cards. Only the following are currently available
+Perhaps this is not enough. The filters also allow glob(7) matching.
 
   <match>*  - will match functions that begin with <match>
   *<match>  - will match functions that end with <match>
   *<match>* - will match functions that have <match> in it
-
-These are the only wild cards which are supported.
-
-  <match>*<match> will not work.
+  <match1>*<match2> - will match functions that begin with
+                      <match1> and end with <match2>
 
 Note: It is better to use quotes to enclose the wild cards,
       otherwise the shell may expand the parameters into names

index 2a96b06..d503800 100644
@@ -70,6 +70,7 @@ config FTRACE_NMI_ENTER
 
 config EVENT_TRACING
 	select CONTEXT_SWITCH_TRACER
+        select GLOB
 	bool
 
 config CONTEXT_SWITCH_TRACER

@@ -133,6 +134,7 @@ config FUNCTION_TRACER
 	select KALLSYMS
 	select GENERIC_TRACER
 	select CONTEXT_SWITCH_TRACER
+        select GLOB
 	help
 	  Enable the kernel to trace every kernel function. This is done
 	  by using a compiler feature to insert a small, 5-byte No-Operation

index 2050a765..7d97c45 100644
@@ -3499,6 +3499,10 @@ static int ftrace_match(char *str, struct ftrace_glob *g)
 		    memcmp(str + slen - g->len, g->search, g->len) == 0)
 			matched = 1;
 		break;
+	case MATCH_GLOB:
+		if (glob_match(g->search, str))
+			matched = 1;
+		break;
 	}
 
 	return matched;

index 8696ce6..d904516d 100644
@@ -4065,7 +4065,7 @@ static const char readme_msg[] =
 	"\n  available_filter_functions - list of functions that can be filtered on\n"
 	"  set_ftrace_filter\t- echo function name in here to only trace these\n"
 	"\t\t\t  functions\n"
-	"\t     accepts: func_full_name, *func_end, func_begin*, *func_middle*\n"
+	"\t     accepts: func_full_name or glob-matching-pattern\n"
 	"\t     modules: Can select a group via module\n"
 	"\t      Format: :mod:<module-name>\n"
 	"\t     example: echo :mod:ext3 > set_ftrace_filter\n"

index fd24b1f..4b79189 100644
@@ -15,6 +15,7 @@
 #include <linux/trace_events.h>
 #include <linux/compiler.h>
 #include <linux/trace_seq.h>
+#include <linux/glob.h>
 
 #ifdef CONFIG_FTRACE_SYSCALLS
 #include <asm/unistd.h>		/* For NR_SYSCALLS	     */

@@ -1257,6 +1258,7 @@ enum regex_type {
 	MATCH_FRONT_ONLY,
 	MATCH_MIDDLE_ONLY,
 	MATCH_END_ONLY,
+	MATCH_GLOB,
 };
 
 struct regex {

index 9daa9b3..e1c7e2c 100644
@@ -344,6 +344,12 @@ static int regex_match_end(char *str, struct regex *r, int len)
 	return 0;
 }
 
+static int regex_match_glob(char *str, struct regex *r, int len __maybe_unused)
+{
+	if (glob_match(r->pattern, str))
+		return 1;
+	return 0;
+}
 /**
  * filter_parse_regex - parse a basic regex
  * @buff:   the raw regex

@@ -380,14 +386,20 @@ enum regex_type filter_parse_regex(char *buff, int len, char **search, int *not)
 			if (!i) {
 				*search = buff + 1;
 				type = MATCH_END_ONLY;
-			} else {
+			} else if (i == len - 1) {
 				if (type == MATCH_END_ONLY)
 					type = MATCH_MIDDLE_ONLY;
 				else
 					type = MATCH_FRONT_ONLY;
 				buff[i] = 0;
 				break;
+			} else {	/* pattern continues, use full glob */
+				type = MATCH_GLOB;
+				break;
 			}
+		} else if (strchr("[?\\", buff[i])) {
+			type = MATCH_GLOB;
+			break;
 		}
 	}
 

@@ -420,6 +432,9 @@ static void filter_build_regex(struct filter_pred *pred)
 	case MATCH_END_ONLY:
 		r->match = regex_match_end;
 		break;
+	case MATCH_GLOB:
+		r->match = regex_match_glob;
+		break;
 	}
 
 	pred->not ^= not;

Oops, sorry, ignore this patch in the series..
This is actually already picked by Steve.

Masami Hiramatsu <[email protected]>

Reset ftrace to initial state before running each test. This fixes some test cases to enable tracing before starting trace test. This can avoid false-positive failure when previous testcase fails while disabling tracing.

---
Changes in v3:
- Fix to avoid initializing error by checking all optional features

---
 tools/testing/selftests/ftrace/ftracetest       |    2 +-
 tools/testing/selftests/ftrace/test.d/functions |   28 +++++++++++++++++++++++
 2 files changed, 29 insertions(+), 1 deletion(-)

index 4c6a0bf..a03d366 100755
@@ -228,7 +228,7 @@ trap 'SIG_RESULT=$XFAIL' $SIG_XFAIL
 
 __run_test() { # testfile
   # setup PID and PPID, $$ is not updated.
-  (cd $TRACING_DIR; read PID _ < /proc/self/stat ; set -e; set -x; . $1)
+  (cd $TRACING_DIR; read PID _ < /proc/self/stat; set -e; set -x; initialize_ftrace; . $1)
   [ $? -ne 0 ] && kill -s $SIG_FAIL $SIG_PID
 }
 

index c37262f..91de1a8 100644
@@ -23,3 +23,31 @@ reset_trigger() { # reset all current setting triggers
     done
 }
 
+reset_events_filter() { # reset all current setting filters
+    grep -v ^none events/*/*/filter |
+    while read line; do
+	echo 0 > `echo $line | cut -f1 -d:`
+    done
+}
+
+disable_events() {
+    echo 0 > events/enable
+}
+
+initialize_ftrace() { # Reset ftrace to initial-state
+# As the initial state, ftrace will be set to nop tracer,
+# no events, no triggers, no filters, no function filters,
+# no probes, and tracing on.
+    disable_tracing
+    reset_tracer
+    reset_trigger
+    reset_events_filter
+    disable_events
+    echo > set_event_pid	# event tracer is always on
+    [ -f set_ftrace_filter ] && echo | tee set_ftrace_*
+    [ -f set_graph_function ] && echo | tee set_graph_*
+    [ -f stack_trace_filter ] && echo > stack_trace_filter
+    [ -f kprobe_events ] && echo > kprobe_events
+    [ -f uprobe_events ] && echo > uprobe_events
+    enable_tracing
+}

Since the verbose error logs scrolls out previous test results --quiet option suppress to show such message.

e.g.

 # ./ftracetest -q
=== Ftrace unit tests ===
[1] Basic trace file check	[PASS]
[2] Basic test for tracers	[PASS]
[3] Basic trace clock test	[PASS]
[4] Basic event tracing check	[PASS]
[5] event tracing - enable/disable with event level files	[PASS]
[6] event tracing - restricts events based on pid	[PASS]
[7] event tracing - enable/disable with subsystem level files	[PASS]
[8] event tracing - enable/disable with top level files	[PASS]
[9] ftrace - function graph filters with stack tracer	[UNSUPPORTED]
[10] ftrace - function graph filters	[UNSUPPORTED]
[11] ftrace - function profiler with function tracing	[UNSUPPORTED]
[12] Test creation and deletion of trace instances while setting an event
	[PASS]
[13] Test creation and deletion of trace instances	[PASS]
[14] Kprobe dynamic event - adding and removing	[UNSUPPORTED]
[15] Kprobe dynamic event - busy event check	[UNSUPPORTED]
[16] Kprobe dynamic event with arguments	[UNSUPPORTED]
[17] Kprobe dynamic event with function tracer	[UNSUPPORTED]
[18] Kretprobe dynamic event with arguments	[UNSUPPORTED]
[19] event trigger - test event enable/disable trigger	[PASS]
[20] event trigger - test trigger filter	[PASS]
[21] event trigger - test histogram modifiers	[UNSUPPORTED]
[22] event trigger - test histogram trigger	[UNSUPPORTED]
[23] event trigger - test multiple histogram triggers	[UNSUPPORTED]
[24] event trigger - test snapshot-trigger	[FAIL]
[25] event trigger - test stacktrace-trigger	[PASS]
[26] event trigger - test traceon/off trigger	[PASS]

# of passed:  14
# of failed:  1
# of unresolved:  0
# of untested:  0
# of unsupported:  11
# of xfailed:  0
# of undefined(test bug):  0

---
 tools/testing/selftests/ftrace/ftracetest |    8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

index a03d366..d08235f 100755
@@ -14,6 +14,7 @@ echo " Options:"
 echo "		-h|--help  Show help message"
 echo "		-k|--keep  Keep passed test logs"
 echo "		-v|--verbose Show all stdout messages in testcases"
+echo "		-q|--quiet Do not show error log on stdout"
 echo "		-d|--debug Debug mode (trace all shell commands)"
 exit $1
 }

@@ -58,6 +59,10 @@ parse_opts() { # opts
       VERBOSE=1
       shift 1
     ;;
+    --quiet|-q)
+      BE_QUIET=1
+      shift 1
+    ;;
     --debug|-d)
       DEBUG=1
       shift 1

@@ -101,6 +106,7 @@ LOG_DIR=$TOP_DIR/logs/`date +%Y%m%d-%H%M%S`/
 KEEP_LOG=0
 DEBUG=0
 VERBOSE=0
+BE_QUIET=0
 # Parse command-line options
 parse_opts $*
 

@@ -249,7 +255,7 @@ run_test() { # testfile
     # Remove test log if the test was done as it was expected.
     [ $KEEP_LOG -eq 0 ] && rm $testlog
   else
-    catlog $testlog
+    [ $BE_QUIET -eq 0 ] && catlog $testlog
     TOTAL_RESULT=1
   fi
 }

I wonder if -q should be default, and -v be what we have, and -vv be verbose?

-- Steve

Hm, it sounds reasonable. I'll make it default and support -v and -vv. :)

Masami Hiramatsu <[email protected]>

If "snapshot" special file doesn't exist, that kernel does not support snapshot and snapshot trigger too. In that case snapshot trigger test results to unsupported instead of fail.

---
 .../ftrace/test.d/trigger/trigger-snapshot.tc      |    5 +++++
 1 file changed, 5 insertions(+)

index f84b80d..ed94f0c 100644
@@ -23,6 +23,11 @@ if [ ! -f events/sched/sched_process_fork/trigger ]; then
     exit_unsupported
 fi
 
+if [ ! -f snapshot ]; then
+    echo "snapshot is not supported"
+    exit_unsupported
+fi
+
 reset_tracer
 do_reset
 

Since histogram trigger id.syscall depends on CONFIG_FTRACE_SYSCALLS, a testcase in trigger-modifier test fails if that config is disabled.

Fix this bug by using flexible pattern to check the histogram output.

---
 .../ftrace/test.d/trigger/trigger-hist-mod.tc      |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index 0bf5085..400e98b 100644
@@ -56,7 +56,7 @@ echo "Test histogram with syscall modifier"
 
 echo 'hist:keys=id.syscall' > events/raw_syscalls/sys_exit/trigger
 for i in `seq 1 10` ; do ( echo "forked" > /dev/null); done
-grep "id: sys_" events/raw_syscalls/sys_exit/hist > /dev/null || \
+grep "id: \(unknown_\|sys_\)" events/raw_syscalls/sys_exit/hist > /dev/null || \
     fail "syscall modifier on raw_syscalls/sys_exit did not work"
 
 

Hide ftracetest result log directory from git.

---
 tools/testing/selftests/ftrace/.gitignore |    1 +
 1 file changed, 1 insertion(+)
 create mode 100644 tools/testing/selftests/ftrace/.gitignore

new file mode 100644
index 0000000..98d8a5a
@@ -0,0 +1 @@
+logs

Introduce TMPDIR variable which is removed after each test is done, so that the test script can put their temporary files in that.

---
 tools/testing/selftests/ftrace/ftracetest |    2 ++
 1 file changed, 2 insertions(+)

index d08235f..685376b4 100755
@@ -242,6 +242,7 @@ __run_test() { # testfile
 run_test() { # testfile
   local testname=`basename $1`
   local testlog=`mktemp $LOG_DIR/${testname}-log.XXXXXX`
+  export TMPDIR=`mktemp -d /tmp/ftracetest-dir.XXXXXX`
   testcase $1
   echo "execute: "$1 > $testlog
   SIG_RESULT=0

@@ -258,6 +259,7 @@ run_test() { # testfile
     [ $BE_QUIET -eq 0 ] && catlog $testlog
     TOTAL_RESULT=1
   fi
+  rm -rf $TMPDIR
 }
 
 # load in the helper functions

Add function filter glob matching test case. This checks whether the kernel supports glob matching (front match, end match, middle match, side match, character class and '?').

Here is the test result.
-----
./ftracetest test.d/ftrace/func-filter-glob.tc
=== Ftrace unit tests ===
[1] ftrace - function glob filters [PASS]

  # of passed:  1
  # of failed:  0
  # of unresolved:  0
  # of untested:  0
  # of unsupported:  0
  # of xfailed:  0
  # of undefined(test bug):  0
  -----

---
 .../ftrace/test.d/ftrace/func-filter-glob.tc       |   49 ++++++++++++++++++++
 1 file changed, 49 insertions(+)
 create mode 100644 tools/testing/selftests/ftrace/test.d/ftrace/func-filter-glob.tc

new file mode 100644
index 0000000..9dcd0ca
@@ -0,0 +1,49 @@
+#!/bin/sh
+# description: ftrace - function glob filters
+
+# Make sure that function glob matching filter works.
+
+if ! grep -q function available_tracers; then
+    echo "no function tracer configured"
+    exit_unsupported
+fi
+
+disable_tracing
+clear_trace
+
+# filter by ?, schedule is always good
+if ! echo "sch?dule" > set_ftrace_filter; then
+    # test for powerpc 64
+    if ! echo ".sch?dule" > set_ftrace_filter; then
+	fail "can not enable schedule filter"
+    fi
+    cat set_ftrace_filter | grep '^.schedule$'
+else
+    cat set_ftrace_filter | grep '^schedule$'
+fi
+
+ftrace_filter_check() { # glob grep
+  echo "$1" > set_ftrace_filter
+  cut -f1 -d" " set_ftrace_filter > $TMPDIR/actual
+  cut -f1 -d" " available_filter_functions | grep "$2" > $TMPDIR/expected
+  DIFF=`diff $TMPDIR/actual $TMPDIR/expected`
+  test -z "$DIFF"
+}
+
+# filter by *, front match
+ftrace_filter_check '*schedule' '^.*schedule$'
+
+# filter by *, middle match
+ftrace_filter_check '*schedule*' '^.*schedule.*$'
+
+# filter by *, end match
+ftrace_filter_check 'schedule*' '^schedule.*$'
+
+# filter by *, both side match
+ftrace_filter_check 'sch*ule' '^sch.*ule$'
+
+# filter by char class.
+ftrace_filter_check '[Ss]y[Ss]_*' '^[Ss]y[Ss]_.*$'
+
+echo > set_ftrace_filter
+enable_tracing

Add a testcase for types of kprobe event. This checks kprobe event can accept and correctly expressed the arguments typed as s32, u32, x32 and bitfield.

Here is the test result.
-----

  # ./ftracetest test.d/kprobe/kprobe_args_type.tc
  === Ftrace unit tests ===
  [1] Kprobes event arguments with types	[PASS]

  # of passed:  1
  # of failed:  0
  # of unresolved:  0
  # of untested:  0
  # of unsupported:  0
  # of xfailed:  0
  # of undefined(test bug):  0
  -----

---
 .../ftrace/test.d/kprobe/kprobe_args_type.tc       |   37 ++++++++++++++++++++
 1 file changed, 37 insertions(+)
 create mode 100644 tools/testing/selftests/ftrace/test.d/kprobe/kprobe_args_type.tc

new file mode 100644
index 0000000..0a78705
@@ -0,0 +1,37 @@
+#!/bin/sh
+# description: Kprobes event arguments with types
+
+[ -f kprobe_events ] || exit_unsupported # this is configurable
+
+grep "x8/16/32/64" README > /dev/null || exit_unsupported # version issue
+
+echo 0 > events/enable
+echo > kprobe_events
+enable_tracing
+
+echo 'p:testprobe _do_fork $stack0:s32 $stack0:u32 $stack0:x32 $stack0:b8@4/32' > kprobe_events
+grep testprobe kprobe_events
+test -d events/kprobes/testprobe
+
+echo 1 > events/kprobes/testprobe/enable
+( echo "forked")
+echo 0 > events/kprobes/testprobe/enable
+ARGS=`tail -n 1 trace | sed -e 's/.* arg1=\(.*\) arg2=\(.*\) arg3=\(.*\) arg4=\(.*\)/\1 \2 \3 \4/'`
+
+check_types() {
+  X1=`printf "%x" $1 | tail -c 8`
+  X2=`printf "%x" $2`
+  X3=`printf "%x" $3`
+  test $X1 = $X2
+  test $X2 = $X3
+  test 0x$X3 = $3
+
+  B4=`printf "%x" $4`
+  B3=`echo -n $X3 | tail -c 3 | head -c 2`
+  test $B3 = $B4
+}
+check_types $ARGS
+
+echo "-:testprobe" >> kprobe_events
+clear_trace
+test -d events/kprobes/testprobe && exit 1 || exit 0