[PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Li Zhijian]

LKP/0day observed that kselftests/ftrace cannot finish within 1 hour on
a 96 cpus platform where it hangs in the line like:
'cat trace | grep -v ^# | awk '{ print $5 }' | sort -u | wc -l'
subsystem-enable.tc

It seems that trace will keep growing during it's read by 'cat' command.
Consequently, trace becomes too large to finish reading.

replace 'cat trace' by:
$ sed -i 's/cat trace |/read_cached_trace |/g' $(find test.d -name "*.tc")

CC: Philip Li <philip.li@intel.com>
Reported-by: kernel test robot <lkp@intel.com>
Signed-off-by: Li Zhijian <lizhijian@cn.fujitsu.com>
---
 .../testing/selftests/ftrace/test.d/event/event-enable.tc | 6 +++---
 .../testing/selftests/ftrace/test.d/event/event-no-pid.tc | 4 ++--
 tools/testing/selftests/ftrace/test.d/event/event-pid.tc  | 6 +++---
 .../selftests/ftrace/test.d/event/subsystem-enable.tc     | 6 +++---
 .../selftests/ftrace/test.d/event/toplevel-enable.tc      | 2 +-
 .../selftests/ftrace/test.d/ftrace/fgraph-filter-stack.tc | 8 ++++----
 .../selftests/ftrace/test.d/ftrace/fgraph-filter.tc       | 4 ++--
 .../ftrace/test.d/ftrace/func-filter-notrace-pid.tc       | 8 ++++----
 .../selftests/ftrace/test.d/ftrace/func-filter-pid.tc     | 8 ++++----
 tools/testing/selftests/ftrace/test.d/functions           | 6 ++++++
 .../selftests/ftrace/test.d/kprobe/kretprobe_args.tc      | 2 +-
 11 files changed, 33 insertions(+), 27 deletions(-)

diff --git a/tools/testing/selftests/ftrace/test.d/event/event-enable.tc b/tools/testing/selftests/ftrace/test.d/event/event-enable.tc
index cfe5bd2d4267..97d64ac407c9 100644
--- a/tools/testing/selftests/ftrace/test.d/event/event-enable.tc
+++ b/tools/testing/selftests/ftrace/test.d/event/event-enable.tc
@@ -18,7 +18,7 @@ echo 'sched:sched_switch' > set_event
 
 yield
 
-count=`cat trace | grep sched_switch | wc -l`
+count=`read_cached_trace | grep sched_switch | wc -l`
 if [ $count -eq 0 ]; then
     fail "sched_switch events are not recorded"
 fi
@@ -29,7 +29,7 @@ echo 1 > events/sched/sched_switch/enable
 
 yield
 
-count=`cat trace | grep sched_switch | wc -l`
+count=`read_cached_trace | grep sched_switch | wc -l`
 if [ $count -eq 0 ]; then
     fail "sched_switch events are not recorded"
 fi
@@ -40,7 +40,7 @@ echo 0 > events/sched/sched_switch/enable
 
 yield
 
-count=`cat trace | grep sched_switch | wc -l`
+count=`read_cached_trace | grep sched_switch | wc -l`
 if [ $count -ne 0 ]; then
     fail "sched_switch events should not be recorded"
 fi
diff --git a/tools/testing/selftests/ftrace/test.d/event/event-no-pid.tc b/tools/testing/selftests/ftrace/test.d/event/event-no-pid.tc
index 9933ed24f901..678f283044cb 100644
--- a/tools/testing/selftests/ftrace/test.d/event/event-no-pid.tc
+++ b/tools/testing/selftests/ftrace/test.d/event/event-no-pid.tc
@@ -23,12 +23,12 @@ fail() { #msg
 
 count_pid() {
     pid=$@
-    cat trace | grep -v '^#' | sed -e 's/[^-]*-\([0-9]*\).*/\1/' | grep $pid | wc -l
+    read_cached_trace | grep -v '^#' | sed -e 's/[^-]*-\([0-9]*\).*/\1/' | grep $pid | wc -l
 }
 
 count_no_pid() {
     pid=$1
-    cat trace | grep -v '^#' | sed -e 's/[^-]*-\([0-9]*\).*/\1/' | grep -v $pid | wc -l
+    read_cached_trace | grep -v '^#' | sed -e 's/[^-]*-\([0-9]*\).*/\1/' | grep -v $pid | wc -l
 }
 
 enable_system() {
diff --git a/tools/testing/selftests/ftrace/test.d/event/event-pid.tc b/tools/testing/selftests/ftrace/test.d/event/event-pid.tc
index 7f5f97dffdc3..da7a5aa8f061 100644
--- a/tools/testing/selftests/ftrace/test.d/event/event-pid.tc
+++ b/tools/testing/selftests/ftrace/test.d/event/event-pid.tc
@@ -23,7 +23,7 @@ echo 1 > events/sched/sched_switch/enable
 
 yield
 
-count=`cat trace | grep sched_switch | wc -l`
+count=`read_cached_trace | grep sched_switch | wc -l`
 if [ $count -eq 0 ]; then
     fail "sched_switch events are not recorded"
 fi
@@ -38,7 +38,7 @@ echo 'sched:sched_switch' > set_event
 
 yield
 
-count=`cat trace | grep sched_switch | grep -v "pid=$mypid" | wc -l`
+count=`read_cached_trace | grep sched_switch | grep -v "pid=$mypid" | wc -l`
 if [ $count -ne 0 ]; then
     fail "sched_switch events from other task are recorded"
 fi
@@ -51,7 +51,7 @@ echo 1 > events/sched/sched_switch/enable
 
 yield
 
-count=`cat trace | grep sched_switch | grep -v "pid=$mypid" | wc -l`
+count=`read_cached_trace | grep sched_switch | grep -v "pid=$mypid" | wc -l`
 if [ $count -eq 0 ]; then
     fail "sched_switch events from other task are not recorded"
 fi
diff --git a/tools/testing/selftests/ftrace/test.d/event/subsystem-enable.tc b/tools/testing/selftests/ftrace/test.d/event/subsystem-enable.tc
index b1ede6249866..e21e923d8aa2 100644
--- a/tools/testing/selftests/ftrace/test.d/event/subsystem-enable.tc
+++ b/tools/testing/selftests/ftrace/test.d/event/subsystem-enable.tc
@@ -18,7 +18,7 @@ echo 'sched:*' > set_event
 
 yield
 
-count=`cat trace | grep -v ^# | awk '{ print $5 }' | sort -u | wc -l`
+count=`read_cached_trace | grep -v ^# | awk '{ print $5 }' | sort -u | wc -l`
 if [ $count -lt 3 ]; then
     fail "at least fork, exec and exit events should be recorded"
 fi
@@ -29,7 +29,7 @@ echo 1 > events/sched/enable
 
 yield
 
-count=`cat trace | grep -v ^# | awk '{ print $5 }' | sort -u | wc -l`
+count=`read_cached_trace | grep -v ^# | awk '{ print $5 }' | sort -u | wc -l`
 if [ $count -lt 3 ]; then
     fail "at least fork, exec and exit events should be recorded"
 fi
@@ -40,7 +40,7 @@ echo 0 > events/sched/enable
 
 yield
 
-count=`cat trace | grep -v ^# | awk '{ print $5 }' | sort -u | wc -l`
+count=`read_cached_trace | grep -v ^# | awk '{ print $5 }' | sort -u | wc -l`
 if [ $count -ne 0 ]; then
     fail "any of scheduler events should not be recorded"
 fi
diff --git a/tools/testing/selftests/ftrace/test.d/event/toplevel-enable.tc b/tools/testing/selftests/ftrace/test.d/event/toplevel-enable.tc
index 93c10ea42a68..b24792987438 100644
--- a/tools/testing/selftests/ftrace/test.d/event/toplevel-enable.tc
+++ b/tools/testing/selftests/ftrace/test.d/event/toplevel-enable.tc
@@ -43,7 +43,7 @@ echo 0 > events/enable
 
 yield
 
-count=`cat trace | grep -v ^# | wc -l`
+count=`read_cached_trace | grep -v ^# | wc -l`
 if [ $count -ne 0 ]; then
     fail "any of events should not be recorded"
 fi
diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter-stack.tc b/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter-stack.tc
index cf3ea42b12b0..157080f682bf 100644
--- a/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter-stack.tc
+++ b/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter-stack.tc
@@ -40,14 +40,14 @@ clear_trace
 enable_tracing
 sleep 1
 
-count=`cat trace | grep '()' | grep -v schedule | wc -l`
+count=`read_cached_trace | grep '()' | grep -v schedule | wc -l`
 
 if [ $count -ne 0 ]; then
     fail "Graph filtering not working with stack tracer?"
 fi
 
 # Make sure we did find something
-count=`cat trace | grep 'schedule()' | wc -l` 
+count=`read_cached_trace | grep 'schedule()' | wc -l` 
 if [ $count -eq 0 ]; then
     fail "No schedule traces found?"
 fi
@@ -57,13 +57,13 @@ clear_trace
 sleep 1
 
 
-count=`cat trace | grep '()' | grep -v schedule | wc -l`
+count=`read_cached_trace | grep '()' | grep -v schedule | wc -l`
 
 if [ $count -ne 0 ]; then
     fail "Graph filtering not working after stack tracer disabled?"
 fi
 
-count=`cat trace | grep 'schedule()' | wc -l` 
+count=`read_cached_trace | grep 'schedule()' | wc -l` 
 if [ $count -eq 0 ]; then
     fail "No schedule traces found?"
 fi
diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter.tc b/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter.tc
index b3ccdaec2a61..930dfc06f4ba 100644
--- a/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter.tc
+++ b/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter.tc
@@ -26,13 +26,13 @@ enable_tracing
 sleep 1
 # search for functions (has "()" on the line), and make sure
 # that only the schedule function was found
-count=`cat trace | grep '()' | grep -v schedule | wc -l`
+count=`read_cached_trace | grep '()' | grep -v schedule | wc -l`
 if [ $count -ne 0 ]; then
     fail "Graph filtering not working by itself?"
 fi
 
 # Make sure we did find something
-count=`cat trace | grep 'schedule()' | wc -l` 
+count=`read_cached_trace | grep 'schedule()' | wc -l` 
 if [ $count -eq 0 ]; then
     fail "No schedule traces found?"
 fi
diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-notrace-pid.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-notrace-pid.tc
index 80541964b927..1f08b7207d74 100644
--- a/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-notrace-pid.tc
+++ b/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-notrace-pid.tc
@@ -52,8 +52,8 @@ do_test() {
     enable_tracing
     yield
 
-    count_pid=`cat trace | grep -v ^# | grep $PID | wc -l`
-    count_other=`cat trace | grep -v ^# | grep -v $PID | wc -l`
+    count_pid=`read_cached_trace | grep -v ^# | grep $PID | wc -l`
+    count_other=`read_cached_trace | grep -v ^# | grep -v $PID | wc -l`
 
     # count_pid should be 0
     if [ $count_pid -ne 0 -o $count_other -eq 0 ]; then
@@ -78,8 +78,8 @@ do_test() {
     enable_tracing
     yield
 
-    count_pid=`cat trace | grep -v ^# | grep $PID | wc -l`
-    count_other=`cat trace | grep -v ^# | grep -v $PID | wc -l`
+    count_pid=`read_cached_trace | grep -v ^# | grep $PID | wc -l`
+    count_other=`read_cached_trace | grep -v ^# | grep -v $PID | wc -l`
 
     # both should be zero
     if [ $count_pid -ne 0 -o $count_other -ne 0 ]; then
diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc
index 2f7211254529..30c218b849dc 100644
--- a/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc
+++ b/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc
@@ -52,8 +52,8 @@ do_test() {
     enable_tracing
     yield
 
-    count_pid=`cat trace | grep -v ^# | grep $PID | wc -l`
-    count_other=`cat trace | grep -v ^# | grep -v $PID | wc -l`
+    count_pid=`read_cached_trace | grep -v ^# | grep $PID | wc -l`
+    count_other=`read_cached_trace | grep -v ^# | grep -v $PID | wc -l`
 
     # count_other should be 0
     if [ $count_pid -eq 0 -o $count_other -ne 0 ]; then
@@ -73,8 +73,8 @@ do_test() {
     enable_tracing
     yield
 
-    count_pid=`cat trace | grep -v ^# | grep $PID | wc -l`
-    count_other=`cat trace | grep -v ^# | grep -v $PID | wc -l`
+    count_pid=`read_cached_trace | grep -v ^# | grep $PID | wc -l`
+    count_other=`read_cached_trace | grep -v ^# | grep -v $PID | wc -l`
 
     # count_other should NOT be 0
     if [ $count_pid -eq 0 -o $count_other -eq 0 ]; then
diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions
index 000fd05e84b1..35d1d173d44b 100644
--- a/tools/testing/selftests/ftrace/test.d/functions
+++ b/tools/testing/selftests/ftrace/test.d/functions
@@ -175,3 +175,9 @@ ftrace_errlog_check() { # err-prefix command-with-error-pos-by-^ command-file
     # "  Command: " and "^\n" => 13
     test $(expr 13 + $pos) -eq $N
 }
+
+read_cached_trace() {
+    cp trace /tmp/cached_trace
+    cat /tmp/cached_trace
+    rm -f /tmp/cached_trace
+}
diff --git a/tools/testing/selftests/ftrace/test.d/kprobe/kretprobe_args.tc b/tools/testing/selftests/ftrace/test.d/kprobe/kretprobe_args.tc
index 197cc2afd404..57b3b215122f 100644
--- a/tools/testing/selftests/ftrace/test.d/kprobe/kretprobe_args.tc
+++ b/tools/testing/selftests/ftrace/test.d/kprobe/kretprobe_args.tc
@@ -11,7 +11,7 @@ test -d events/kprobes/testprobe2
 echo 1 > events/kprobes/testprobe2/enable
 ( echo "forked")
 
-cat trace | grep testprobe2 | grep -q "<- $FUNCTION_FORK"
+read_cached_trace | grep testprobe2 | grep -q "<- $FUNCTION_FORK"
 
 echo 0 > events/kprobes/testprobe2/enable
 echo '-:testprobe2' >> kprobe_events
-- 
2.31.1

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Steven Rostedt]

On Mon, 18 Oct 2021 21:26:16 +0800
Li Zhijian <lizhijian@cn.fujitsu.com> wrote:

> LKP/0day observed that kselftests/ftrace cannot finish within 1 hour on
> a 96 cpus platform where it hangs in the line like:
> 'cat trace | grep -v ^# | awk '{ print $5 }' | sort -u | wc -l'
> subsystem-enable.tc
> 
> It seems that trace will keep growing during it's read by 'cat' command.
> Consequently, trace becomes too large to finish reading.
> 
> replace 'cat trace' by:
> $ sed -i 's/cat trace |/read_cached_trace |/g' $(find test.d -name "*.tc")
> 

Instead, what happens if you add this command to each test?

if [ -t options/pause-on-trace ]; then
   echo 1 > options/pause-on-trace
fi

We also need to add to the "initialize_ftrace" function in test.d/functions.

if [ -t options/pause-on-trace ]; then
   echo 0 > options/pause-on-trace
fi

-- Steve

> CC: Philip Li <philip.li@intel.com>
> Reported-by: kernel test robot <lkp@intel.com>
> Signed-off-by: Li Zhijian <lizhijian@cn.fujitsu.com>
> ---

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Masami Hiramatsu]

On Mon, 18 Oct 2021 22:16:36 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Mon, 18 Oct 2021 21:26:16 +0800
> Li Zhijian <lizhijian@cn.fujitsu.com> wrote:
> 
> > LKP/0day observed that kselftests/ftrace cannot finish within 1 hour on
> > a 96 cpus platform where it hangs in the line like:
> > 'cat trace | grep -v ^# | awk '{ print $5 }' | sort -u | wc -l'
> > subsystem-enable.tc
> > 
> > It seems that trace will keep growing during it's read by 'cat' command.
> > Consequently, trace becomes too large to finish reading.
> > 
> > replace 'cat trace' by:
> > $ sed -i 's/cat trace |/read_cached_trace |/g' $(find test.d -name "*.tc")
> > 
> 
> Instead, what happens if you add this command to each test?
> 
> if [ -t options/pause-on-trace ]; then
>    echo 1 > options/pause-on-trace
> fi
> 
> We also need to add to the "initialize_ftrace" function in test.d/functions.
> 
> if [ -t options/pause-on-trace ]; then
>    echo 0 > options/pause-on-trace
> fi

Hmm, by the way, shouldn't we set this feature by default?
There are many "cat trace | grep ..." style test code in ftracetest just for
checking whether the event is recorded. At least for the ftracetest, it should
be set unless the testcase is explicitly disable it.

Thank you.

> 
> -- Steve
> 
> > CC: Philip Li <philip.li@intel.com>
> > Reported-by: kernel test robot <lkp@intel.com>
> > Signed-off-by: Li Zhijian <lizhijian@cn.fujitsu.com>
> > ---


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Steven Rostedt]

On Wed, 20 Oct 2021 11:20:27 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> Hmm, by the way, shouldn't we set this feature by default?
> There are many "cat trace | grep ..." style test code in ftracetest just for
> checking whether the event is recorded. At least for the ftracetest, it should
> be set unless the testcase is explicitly disable it.

For testing, sure.

I was criticized by the BPF folks about tracing stopping when the trace
file was being read. So for normal operations, it doesn't pause, because
that "confuses" people (so I am told).

-- Steve

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Masami Hiramatsu]

On Tue, 19 Oct 2021 22:34:54 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Wed, 20 Oct 2021 11:20:27 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > Hmm, by the way, shouldn't we set this feature by default?
> > There are many "cat trace | grep ..." style test code in ftracetest just for
> > checking whether the event is recorded. At least for the ftracetest, it should
> > be set unless the testcase is explicitly disable it.
> 
> For testing, sure.
> 
> I was criticized by the BPF folks about tracing stopping when the trace
> file was being read. So for normal operations, it doesn't pause, because
> that "confuses" people (so I am told).

OK, I got it.

Here is the patch to enable it by default for ftracetest :)

Thanks!

From 61e641f494307d9942a8415bc6743e85dd95438e Mon Sep 17 00:00:00 2001
From: Masami Hiramatsu <mhiramat@kernel.org>
Date: Wed, 20 Oct 2021 11:50:35 +0900
Subject: [PATCH] selftests/ftrace: Stop tracing while reading the trace file
 by default

Stop tracing while reading the trace file by default, to prevent
the test results while checking it and to avoid taking a long time
to check the result.
If there is any testcase which wants to test the tracing while reading
the trace file, please override this setting inside the test case.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 tools/testing/selftests/ftrace/test.d/functions | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions
index 000fd05e84b1..8adc0140d03f 100644
--- a/tools/testing/selftests/ftrace/test.d/functions
+++ b/tools/testing/selftests/ftrace/test.d/functions
@@ -124,6 +124,12 @@ initialize_ftrace() { # Reset ftrace to initial-state
     [ -f uprobe_events ] && echo > uprobe_events
     [ -f synthetic_events ] && echo > synthetic_events
     [ -f snapshot ] && echo 0 > snapshot
+
+# Stop tracing while reading the trace file by default, to prevent
+# the test results while checking it and to avoid taking a long time
+# to check the result.
+    [ -f options/pause-on-trace ] && echo 1 > options/pause-on-trace
+
     clear_trace
     enable_tracing
 }
-- 
2.25.1

 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[lizhijian]

On 20/10/2021 10:55, Masami Hiramatsu wrote:
> On Tue, 19 Oct 2021 22:34:54 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
>
>> On Wed, 20 Oct 2021 11:20:27 +0900
>> Masami Hiramatsu <mhiramat@kernel.org> wrote:
>>
>>> Hmm, by the way, shouldn't we set this feature by default?
>>> There are many "cat trace | grep ..." style test code in ftracetest just for
>>> checking whether the event is recorded. At least for the ftracetest, it should
>>> be set unless the testcase is explicitly disable it.
>> For testing, sure.
>>
>> I was criticized by the BPF folks about tracing stopping when the trace
>> file was being read. So for normal operations, it doesn't pause, because
>> that "confuses" people (so I am told).
> OK, I got it.
>
> Here is the patch to enable it by default for ftracetest :)
>
> Thanks!
>
>  From 61e641f494307d9942a8415bc6743e85dd95438e Mon Sep 17 00:00:00 2001
> From: Masami Hiramatsu <mhiramat@kernel.org>
> Date: Wed, 20 Oct 2021 11:50:35 +0900
> Subject: [PATCH] selftests/ftrace: Stop tracing while reading the trace file
>   by default
>
> Stop tracing while reading the trace file by default, to prevent
> the test results while checking it and to avoid taking a long time
> to check the result.
> If there is any testcase which wants to test the tracing while reading
> the trace file, please override this setting inside the test case.
>
> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>

LGTM.

Tested-by: Li Zhijian <lizhijian@cn.fujitsu.com>
Reported-by: kernel test robot<lkp@intel.com>


> ---
>   tools/testing/selftests/ftrace/test.d/functions | 6 ++++++
>   1 file changed, 6 insertions(+)
>
> diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions
> index 000fd05e84b1..8adc0140d03f 100644
> --- a/tools/testing/selftests/ftrace/test.d/functions
> +++ b/tools/testing/selftests/ftrace/test.d/functions
> @@ -124,6 +124,12 @@ initialize_ftrace() { # Reset ftrace to initial-state
>       [ -f uprobe_events ] && echo > uprobe_events
>       [ -f synthetic_events ] && echo > synthetic_events
>       [ -f snapshot ] && echo 0 > snapshot
> +
> +# Stop tracing while reading the trace file by default, to prevent
> +# the test results while checking it and to avoid taking a long time
> +# to check the result.
> +    [ -f options/pause-on-trace ] && echo 1 > options/pause-on-trace
> +
>       clear_trace
>       enable_tracing
>   }

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Steven Rostedt]

On Wed, 20 Oct 2021 11:55:22 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> --- a/tools/testing/selftests/ftrace/test.d/functions
> +++ b/tools/testing/selftests/ftrace/test.d/functions
> @@ -124,6 +124,12 @@ initialize_ftrace() { # Reset ftrace to initial-state
>      [ -f uprobe_events ] && echo > uprobe_events
>      [ -f synthetic_events ] && echo > synthetic_events
>      [ -f snapshot ] && echo 0 > snapshot
> +
> +# Stop tracing while reading the trace file by default, to prevent
> +# the test results while checking it and to avoid taking a long time
> +# to check the result.
> +    [ -f options/pause-on-trace ] && echo 1 > options/pause-on-trace
> +

Is there a way we can save the previous setting and put it back on reset?

-- Steve

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Masami Hiramatsu]

On Wed, 20 Oct 2021 10:16:59 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Wed, 20 Oct 2021 11:55:22 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > --- a/tools/testing/selftests/ftrace/test.d/functions
> > +++ b/tools/testing/selftests/ftrace/test.d/functions
> > @@ -124,6 +124,12 @@ initialize_ftrace() { # Reset ftrace to initial-state
> >      [ -f uprobe_events ] && echo > uprobe_events
> >      [ -f synthetic_events ] && echo > synthetic_events
> >      [ -f snapshot ] && echo 0 > snapshot
> > +
> > +# Stop tracing while reading the trace file by default, to prevent
> > +# the test results while checking it and to avoid taking a long time
> > +# to check the result.
> > +    [ -f options/pause-on-trace ] && echo 1 > options/pause-on-trace
> > +
> 
> Is there a way we can save the previous setting and put it back on reset?

No, since each testcase must be run under the clean state. Would we need to
recover the settings?

Thank you,

> 
> -- Steve


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Steven Rostedt]

On Thu, 21 Oct 2021 09:31:31 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> > > +# Stop tracing while reading the trace file by default, to prevent
> > > +# the test results while checking it and to avoid taking a long time
> > > +# to check the result.
> > > +    [ -f options/pause-on-trace ] && echo 1 > options/pause-on-trace
> > > +  
> > 
> > Is there a way we can save the previous setting and put it back on reset?  
> 
> No, since each testcase must be run under the clean state. Would we need to
> recover the settings?

I would at least put it back to the default. If someone runs the tests,
it should at least put it back to what it was at boot. Otherwise,
someone might run the tests, and then wonder why events are being
dropped when they are reading the trace.

-- Steve

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Masami Hiramatsu]

On Mon, 25 Oct 2021 22:17:17 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Thu, 21 Oct 2021 09:31:31 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > > > +# Stop tracing while reading the trace file by default, to prevent
> > > > +# the test results while checking it and to avoid taking a long time
> > > > +# to check the result.
> > > > +    [ -f options/pause-on-trace ] && echo 1 > options/pause-on-trace
> > > > +  
> > > 
> > > Is there a way we can save the previous setting and put it back on reset?  
> > 
> > No, since each testcase must be run under the clean state. Would we need to
> > recover the settings?
> 
> I would at least put it back to the default. If someone runs the tests,
> it should at least put it back to what it was at boot. Otherwise,
> someone might run the tests, and then wonder why events are being
> dropped when they are reading the trace.

Umm, we may need to have a knob to reset the ftrace options...
Can we warn such user that if the ftracetest finds that the current
value is not the same what it sets?

Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Steven Rostedt]

On Tue, 26 Oct 2021 21:13:31 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> > > No, since each testcase must be run under the clean state. Would we need to
> > > recover the settings?  
> > 
> > I would at least put it back to the default. If someone runs the tests,
> > it should at least put it back to what it was at boot. Otherwise,
> > someone might run the tests, and then wonder why events are being
> > dropped when they are reading the trace.  
> 
> Umm, we may need to have a knob to reset the ftrace options...
> Can we warn such user that if the ftracetest finds that the current
> value is not the same what it sets?

You mean before we set pause-on-trace, make sure that it was cleared?

That could work too, and then just set everything back to what we expected
it to be at the start.

-- Steve

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Masami Hiramatsu]

On Tue, 26 Oct 2021 09:15:34 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Tue, 26 Oct 2021 21:13:31 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > > > No, since each testcase must be run under the clean state. Would we need to
> > > > recover the settings?  
> > > 
> > > I would at least put it back to the default. If someone runs the tests,
> > > it should at least put it back to what it was at boot. Otherwise,
> > > someone might run the tests, and then wonder why events are being
> > > dropped when they are reading the trace.  
> > 
> > Umm, we may need to have a knob to reset the ftrace options...
> > Can we warn such user that if the ftracetest finds that the current
> > value is not the same what it sets?
> 
> You mean before we set pause-on-trace, make sure that it was cleared?
> 
> That could work too, and then just set everything back to what we expected
> it to be at the start.

No, it costs much higher (to save the default settings and recover)
OK, then just make it recover to the build default setting.

From e6ab7217c8f50dabee0f565764489fdd32e1ff07 Mon Sep 17 00:00:00 2001
From: Masami Hiramatsu <mhiramat@kernel.org>
Date: Wed, 20 Oct 2021 11:55:22 +0900
Subject: [PATCH v2] selftests/ftrace: Stop tracing while reading the trace file
 by default

Stop tracing while reading the trace file by default, to prevent
the test results while checking it and to avoid taking a long time
to check the result.
If there is any testcase which wants to test the tracing while reading
the trace file, please override this setting inside the test case.

This also recovers the pause-on-trace when clean it up.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 Changes in v2:
  - Recover pause-on-trace to 0 when exit.
---
 tools/testing/selftests/ftrace/ftracetest       |  2 +-
 tools/testing/selftests/ftrace/test.d/functions | 12 ++++++++++++
 2 files changed, 13 insertions(+), 1 deletion(-)

diff --git a/tools/testing/selftests/ftrace/ftracetest b/tools/testing/selftests/ftrace/ftracetest
index 8ec1922e974e..c3311c8c4089 100755
--- a/tools/testing/selftests/ftrace/ftracetest
+++ b/tools/testing/selftests/ftrace/ftracetest
@@ -428,7 +428,7 @@ for t in $TEST_CASES; do
     exit 1
   fi
 done
-(cd $TRACING_DIR; initialize_ftrace) # for cleanup
+(cd $TRACING_DIR; finish_ftrace) # for cleanup
 
 prlog ""
 prlog "# of passed: " `echo $PASSED_CASES | wc -w`
diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions
index 000fd05e84b1..5f6cbec847fc 100644
--- a/tools/testing/selftests/ftrace/test.d/functions
+++ b/tools/testing/selftests/ftrace/test.d/functions
@@ -124,10 +124,22 @@ initialize_ftrace() { # Reset ftrace to initial-state
     [ -f uprobe_events ] && echo > uprobe_events
     [ -f synthetic_events ] && echo > synthetic_events
     [ -f snapshot ] && echo 0 > snapshot
+
+# Stop tracing while reading the trace file by default, to prevent
+# the test results while checking it and to avoid taking a long time
+# to check the result.
+    [ -f options/pause-on-trace ] && echo 1 > options/pause-on-trace
+
     clear_trace
     enable_tracing
 }
 
+finish_ftrace() {
+    initialize_ftrace
+# And recover it to default.
+    [ -f options/pause-on-trace ] && echo 0 > options/pause-on-trace
+}
+
 check_requires() { # Check required files and tracers
     for i in "$@" ; do
         r=${i%:README}
-- 
2.25.1

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Steven Rostedt]

On Tue, 26 Oct 2021 23:13:14 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> >From e6ab7217c8f50dabee0f565764489fdd32e1ff07 Mon Sep 17 00:00:00 2001  
> From: Masami Hiramatsu <mhiramat@kernel.org>
> Date: Wed, 20 Oct 2021 11:55:22 +0900
> Subject: [PATCH v2] selftests/ftrace: Stop tracing while reading the trace file
>  by default
> 
> Stop tracing while reading the trace file by default, to prevent
> the test results while checking it and to avoid taking a long time
> to check the result.
> If there is any testcase which wants to test the tracing while reading
> the trace file, please override this setting inside the test case.
> 
> This also recovers the pause-on-trace when clean it up.
> 
> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>

Looks good. Can you resend this as a standalone patch, so that it triggers
my patchwork?

-- Steve

Re: [PATCH] kselftests: ftrace: limit the executing time by reading from cached trace

[Masami Hiramatsu]

On Tue, 26 Oct 2021 11:16:26 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Tue, 26 Oct 2021 23:13:14 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > >From e6ab7217c8f50dabee0f565764489fdd32e1ff07 Mon Sep 17 00:00:00 2001  
> > From: Masami Hiramatsu <mhiramat@kernel.org>
> > Date: Wed, 20 Oct 2021 11:55:22 +0900
> > Subject: [PATCH v2] selftests/ftrace: Stop tracing while reading the trace file
> >  by default
> > 
> > Stop tracing while reading the trace file by default, to prevent
> > the test results while checking it and to avoid taking a long time
> > to check the result.
> > If there is any testcase which wants to test the tracing while reading
> > the trace file, please override this setting inside the test case.
> > 
> > This also recovers the pause-on-trace when clean it up.
> > 
> > Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> 
> Looks good. Can you resend this as a standalone patch, so that it triggers
> my patchwork?

Sure, let me send it :-)

Thank you,



-- 
Masami Hiramatsu <mhiramat@kernel.org>