selftests: ftrace: Tracing updates to allow instance testing

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
for-next

Head SHA1: d6322f6cc483bd512efd3360fa76d0286a5b528b

Steven Rostedt (VMware) (5):
selftests: ftrace: Allow some tests to be run in a tracing instance
selftests: ftrace: Make func_event_triggers and func_traceonoff_triggers tests do instances
selftests: ftrace: Have event tests also run in an tracing instance
selftests: ftrace: Have some basic tests run in a tracing instance too
selftests: ftrace: Allow some event trigger tests to run in an instance

----

 tools/testing/selftests/ftrace/ftracetest              | 18 +++++++++++++++++-
 .../testing/selftests/ftrace/test.d/00basic/basic2.tc  |  1 +
 .../testing/selftests/ftrace/test.d/00basic/basic3.tc  |  1 +
 .../selftests/ftrace/test.d/event/event-enable.tc      |  1 +
 .../testing/selftests/ftrace/test.d/event/event-pid.tc |  1 +
 .../selftests/ftrace/test.d/event/subsystem-enable.tc  |  1 +
 .../ftrace/test.d/ftrace/func_event_triggers.tc        |  1 +
 .../ftrace/test.d/ftrace/func_traceonoff_triggers.tc   |  1 +
 .../ftrace/test.d/trigger/trigger-eventonoff.tc        |  1 +
 .../selftests/ftrace/test.d/trigger/trigger-filter.tc  |  1 +
 .../ftrace/test.d/trigger/trigger-hist-mod.tc          |  1 +
 .../selftests/ftrace/test.d/trigger/trigger-hist.tc    |  1 +
 .../ftrace/test.d/trigger/trigger-multihist.tc         |  1 +
 13 files changed, 29 insertions(+), 1 deletion(-)

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

An tracing instance has several of the same capabilities as the top level instance, but may be implemented slightly different. Instead of just writing tests that duplicat the same test cases of the top level instance, allow a test to be written for both the top level as well as for an instance.

If a test case can be run in both the top level as well as in an tracing instance directory, then it should add a tag "# flags: instance" in the header of the test file. Then after all tests have run, any test that has an instance flag set, will run again within a tracing instance.

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

index a8631d978725..32e6211e1c6e 100755
@@ -150,11 +150,16 @@ XFAILED_CASES=
 UNDEFINED_CASES=
 TOTAL_RESULT=0
 
+INSTANCE=
 CASENO=0
 testcase() { # testfile
   CASENO=$((CASENO+1))
   desc=`grep "^#[ \t]*description:" $1 | cut -f2 -d:`
-  prlog -n "[$CASENO]$desc"
+  prlog -n "[$CASENO]$INSTANCE$desc"
+}
+
+test_on_instance() { # testfile
+  grep -q "^#[ \t]*flags:.*instance" $1
 }
 
 eval_result() { # sigval

@@ -271,6 +276,17 @@ for t in $TEST_CASES; do
   run_test $t
 done
 
+# Test on instance loop
+INSTANCE=" (instance) "
+for t in $TEST_CASES; do
+  test_on_instance $t || continue
+  SAVED_TRACING_DIR=$TRACING_DIR
+  export TRACING_DIR=`mktemp -d $TRACING_DIR/instances/ftracetest.XXXXXX`
+  run_test $t
+  rmdir $TRACING_DIR
+  TRACING_DIR=$SAVED_TRACING_DIR
+done
+
 prlog ""
 prlog "# of passed: " `echo $PASSED_CASES | wc -w`
 prlog "# of failed: " `echo $FAILED_CASES | wc -w`

2.10.2

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

Both the func_event_triggers and func_traceonoff_triggers tests can be performed in both the toplevel instance as well as for individual instances. Have their tests run in both cases.

---
 tools/testing/selftests/ftrace/test.d/ftrace/func_event_triggers.tc      | 1 +
 tools/testing/selftests/ftrace/test.d/ftrace/func_traceonoff_triggers.tc | 1 +
 2 files changed, 2 insertions(+)

index 5c60afca24a6..07bb3e5930b4 100644
@@ -1,5 +1,6 @@
 #!/bin/sh
 # description: ftrace - test for function event triggers
+# flags: instance
 #
 # Ftrace allows to add triggers to functions, such as enabling or disabling
 # tracing, enabling or disabling trace events, or recording a stack trace

index 3c60ca61fee3..c8e02ec01eaf 100644
@@ -1,5 +1,6 @@
 #!/bin/sh
 # description: ftrace - test for function traceon/off triggers
+# flags: instance
 #
 # Ftrace allows to add triggers to functions, such as enabling or disabling
 # tracing, enabling or disabling trace events, or recording a stack trace

2.10.2

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

The ftrace selftests of events: event-enable, event-pid, and subsystem-enable can all be run inside an instance. Change their tests to do both a toplevel run an an instance run.

---
 tools/testing/selftests/ftrace/test.d/event/event-enable.tc     | 1 +
 tools/testing/selftests/ftrace/test.d/event/event-pid.tc        | 1 +
 tools/testing/selftests/ftrace/test.d/event/subsystem-enable.tc | 1 +
 3 files changed, 3 insertions(+)

index 87eb9d6dd4ca..283b45ecb199 100644
@@ -1,5 +1,6 @@
 #!/bin/sh
 # description: event tracing - enable/disable with event level files
+# flags: instance
 
 do_reset() {
     echo > set_event

index d4ab27b522f8..96c1a95be4f7 100644
@@ -1,5 +1,6 @@
 #!/bin/sh
 # description: event tracing - restricts events based on pid
+# flags: instance
 
 do_reset() {
     echo > set_event

index ced27ef0638f..b8fe2e5b9e67 100644
@@ -1,5 +1,6 @@
 #!/bin/sh
 # description: event tracing - enable/disable with subsystem level files
+# flags: instance
 
 do_reset() {
     echo > set_event

2.10.2

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

Some of the basic ftrace selftests should also be run in an instance. These test a quick case of running all tracers in the available_tracers file within the instance. The other is testing the clock used for the instance.

---
 tools/testing/selftests/ftrace/test.d/00basic/basic2.tc | 1 +
 tools/testing/selftests/ftrace/test.d/00basic/basic3.tc | 1 +
 2 files changed, 2 insertions(+)

index bf9a7b037924..ebfce83f35b4 100644
@@ -1,5 +1,6 @@
 #!/bin/sh
 # description: Basic test for tracers
+# flags: instance
 test -f available_tracers
 for t in `cat available_tracers`; do
   echo $t > current_tracer

index bde6625d9785..9e33f841812f 100644
@@ -1,5 +1,6 @@
 #!/bin/sh
 # description: Basic trace clock test
+# flags: instance
 test -f trace_clock
 for c in `cat trace_clock | tr  -d \[\]`; do
   echo $c > trace_clock

2.10.2

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

Some of the event triggers can run fine in an instance. Have them tested in one as well. The ones that still need work are the snapshot, stacktrace and traceon/off triggers, as they don't currently pass a handle to the trace_array they are attached to. But that can be for a future project.

---
 tools/testing/selftests/ftrace/test.d/trigger/trigger-eventonoff.tc | 1 +
 tools/testing/selftests/ftrace/test.d/trigger/trigger-filter.tc     | 1 +
 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-mod.tc   | 1 +
 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist.tc       | 1 +
 tools/testing/selftests/ftrace/test.d/trigger/trigger-multihist.tc  | 1 +
 5 files changed, 5 insertions(+)

index 1a9445021bf1..c5435adfdd93 100644
@@ -1,5 +1,6 @@
 #!/bin/sh
 # description: event trigger - test event enable/disable trigger
+# flags: instance
 
 do_reset() {
     reset_trigger

index 514e466e198b..48849a8d577f 100644
@@ -1,5 +1,6 @@
 #!/bin/sh
 # description: event trigger - test trigger filter
+# flags: instance
 
 do_reset() {
     reset_trigger

index 400e98b64948..b7f86d10b549 100644
@@ -1,5 +1,6 @@
 #!/bin/sh
 # description: event trigger - test histogram modifiers
+# flags: instance
 
 do_reset() {
     reset_trigger

index a00184cd9c95..fb66f7d9339d 100644
@@ -1,5 +1,6 @@
 #!/bin/sh
 # description: event trigger - test histogram trigger
+# flags: instance
 
 do_reset() {
     reset_trigger

index 3478b00ead57..f9153087dd7c 100644
@@ -1,5 +1,6 @@
 #!/bin/sh
 # description: event trigger - test multiple histogram triggers
+# flags: instance
 
 do_reset() {
     reset_trigger

2.10.2

I've reviewed & tested the series. Looks good to me.

for the series.

Tue Apr 25 16:02:40 UTC 2017
=== 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 [PASS]
[10] ftrace - function graph filters [PASS]
[11] ftrace - function glob filters [PASS]
[12] ftrace - function pid filters [PASS]
[13] ftrace - test for function event triggers [PASS]
[14] ftrace - function profiler with function tracing [PASS]
[15] ftrace - test reading of set_ftrace_filter [PASS]
[16] ftrace - test for function traceon/off triggers [PASS]
[17] Test creation and deletion of trace instances while setting an event [PASS]
[18] Test creation and deletion of trace instances [PASS]
[19] Kprobe dynamic event - adding and removing [PASS]
[20] Kprobe dynamic event - busy event check [PASS]
[21] Kprobe dynamic event with arguments [PASS]
[22] Kprobes event arguments with types [PASS]
[23] Kprobe dynamic event with function tracer [PASS]
[24] Kretprobe dynamic event with arguments [PASS]
[25] Kretprobe dynamic event with maxactive [PASS]
[26] event trigger - test event enable/disable trigger [PASS]
[27] event trigger - test trigger filter [PASS]
[28] event trigger - test histogram modifiers [PASS]
[29] event trigger - test histogram trigger [PASS]
[30] event trigger - test multiple histogram triggers [PASS]
[31] event trigger - test snapshot-trigger [PASS]
[32] event trigger - test stacktrace-trigger [PASS]
[33] event trigger - test traceon/off trigger [PASS]

[34] (instance)  Basic test for tracers	[PASS]
[35] (instance)  Basic trace clock test	[PASS]
[36] (instance)  event tracing - enable/disable with event level files	[PASS]
[37] (instance)  event tracing - restricts events based on pid	[PASS]
[38] (instance)  event tracing - enable/disable with subsystem level files	[PASS]
[39] (instance)  ftrace - test for function event triggers	[PASS]
[40] (instance)  ftrace - test for function traceon/off triggers	[PASS]
[41] (instance)  event trigger - test event enable/disable trigger	[PASS]
[42] (instance)  event trigger - test trigger filter	[PASS]
[43] (instance)  event trigger - test histogram modifiers	[PASS]
[44] (instance)  event trigger - test histogram trigger	[PASS]
[45] (instance)  event trigger - test multiple histogram triggers	[PASS]

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

Thank you,

Masami Hiramatsu <[email protected]>

Hi Steve,

But I saw a warning during the below test. I used the for-next branch but the commit id was different:

c486bbae781cce337a31cbbbc609f2313ab54542 ("Merge branch 'trace/ftrace/core' into trace/ftrace/next").

Thanks,
Namhyung

[2] Basic test for tracers

[  908.674961] 
[  908.675178] ===============================
[  908.675611] [ ERR: suspicious RCU usage.  ]
[  908.675922] 4.11.0-rc5kvm+ #230 Tainted: G        W      
[  908.675922] -------------------------------
[  908.675922] /home/namhyung/project/linux/include/linux/rcupdate.h:842 rcu_read_lock() used illegally while idle!
[  908.675922] 
[  908.675922] other info that might help us debug this:
[  908.675922] 
[  908.675922] 
[  908.675922] RCU used illegally from idle CPU!
[  908.675922] rcu_scheduler_active = 2, debug_locks = 0
[  908.675922] RCU used illegally from extended quiescent state!
[  908.675922] 2 locks held by swapper/0/0:
[  908.675922]  #0:  (max_trace_lock){......}, at: [<ffffffff81143c33>] check_critical_timing+0xa3/0x150
[  908.675922]  #1:  (rcu_read_lock){......}, at: [<ffffffff8111f9b5>] __is_insn_slot_addr+0x5/0x120
[  908.675922] 
[  908.675922] stack backtrace:
[  908.675922] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W       4.11.0-rc5kvm+ #230
[  908.675922] Call Trace:
[  908.675922]  dump_stack+0x68/0x93
[  908.675922]  lockdep_rcu_suspicious+0xe0/0x100
[  908.675922]  ? start_kernel+0x3b7/0x3c4
[  908.675922]  __is_insn_slot_addr+0xe4/0x120
[  908.675922]  ? start_kernel+0x3b7/0x3c4
[  908.675922]  __kernel_text_address+0x69/0xb0
[  908.675922]  ? start_kernel+0x3b7/0x3c4
[  908.675922]  unwind_get_return_address+0x47/0x60
[  908.675922]  __save_stack_trace+0x83/0xd0
[  908.675922]  save_stack_trace+0x1b/0x20
[  908.675922]  __ftrace_trace_stack+0x22e/0x240
[  908.675922]  __trace_stack+0x10/0x20
[  908.675922]  check_critical_timing+0xe9/0x150
[  908.675922]  ? do_idle+0x88/0x120
[  908.675922]  ? default_idle_call+0x23/0x37
[  908.675922]  ? do_idle+0x88/0x120
[  908.675922]  stop_critical_timings+0xcf/0xe0
[  908.675922]  default_idle_call+0x23/0x37
[  908.675922]  do_idle+0x88/0x120
[  908.675922]  cpu_startup_entry+0x1d/0x20
[  908.675922]  rest_init+0x130/0x140
[  908.675922]  start_kernel+0x3b7/0x3c4
[  908.675922]  x86_64_start_reservations+0x2f/0x31
[  908.675922]  x86_64_start_kernel+0x17d/0x190
[  908.675922]  start_cpu+0x14/0x14
[  908.675922]  ? start_cpu+0x14/0x14
	[PASS]

Yeah, my for-next branch is a merge of urgent and my branch. I don't do rebases, but this is actually a reset, of a new merge between my two branches.

Ah, this is a different issue from the stack tracing one. This is irq tracing. I wonder if we should have that stop latency tracing when RCU is not functioning.

-- Steve