[PATCH] selftests/ftrace: Limit number of lines processed in 'trace'

[PATCH] selftests/ftrace: Limit number of lines processed in 'trace'

[Naveen N. Rao]

On very large machines, ftracetest can seem to hang or otherwise take a
very long time to complete individual tests. This can be attributed to
statements that try to process the entire contents of 'trace'.

Limit the number of lines processed from 'trace' to resolve this. Apart
from the change in test.d/functions to add TRACENL, this commit is the
result of running the below command (and fixing some whitespace errors):
  grep -l -R 'cat trace |' -- ./tools/testing/selftests/ftrace/test.d/ | \
	xargs -n 1 sed --in-place -e "s/cat trace |/head -\$\{TRACENL\} trace |/g"

Reported-by: Akanksha J N <akanksha@linux.vnet.ibm.com>
Signed-off-by: Naveen N. Rao <naveen.n.rao@linux.vnet.ibm.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           | 3 +++
 .../selftests/ftrace/test.d/kprobe/kretprobe_args.tc      | 2 +-
 11 files changed, 30 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 cfe5bd2d426794..0a2d236cd94822 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=`head -${TRACENL} 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=`head -${TRACENL} 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=`head -${TRACENL} 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 9933ed24f90124..711301a36b69b6 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
+    head -${TRACENL} 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
+    head -${TRACENL} 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 7f5f97dffdc3dd..8ecdc211ac0432 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=`head -${TRACENL} 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=`head -${TRACENL} 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=`head -${TRACENL} 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 b1ede624986676..d5a1faff71773c 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=`head -${TRACENL} 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=`head -${TRACENL} 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=`head -${TRACENL} 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 93c10ea42a6868..1b7d4700a21b1e 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=`head -${TRACENL} 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 cf3ea42b12b09f..2861aaaec3908b 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=`head -${TRACENL} 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=`head -${TRACENL} 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=`head -${TRACENL} 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=`head -${TRACENL} 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 b3ccdaec2a61ba..679eed983ef931 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=`head -${TRACENL} 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=`head -${TRACENL} 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 80541964b9270b..088ec11d87fa46 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=`head -${TRACENL} trace | grep -v ^# | grep $PID | wc -l`
+    count_other=`head -${TRACENL} 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=`head -${TRACENL} trace | grep -v ^# | grep $PID | wc -l`
+    count_other=`head -${TRACENL} 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 2f7211254529ba..fed002ed262b1d 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=`head -${TRACENL} trace | grep -v ^# | grep $PID | wc -l`
+    count_other=`head -${TRACENL} 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=`head -${TRACENL} trace | grep -v ^# | grep $PID | wc -l`
+    count_other=`head -${TRACENL} 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 5f6cbec847fc99..6a9a794bde11f7 100644
--- a/tools/testing/selftests/ftrace/test.d/functions
+++ b/tools/testing/selftests/ftrace/test.d/functions
@@ -174,6 +174,9 @@ yield() {
 FUNCTION_FORK=`(if grep '\bkernel_clone\b' /proc/kallsyms > /dev/null; then
                 echo kernel_clone; else echo '_do_fork'; fi)`
 
+# TRACENL controls the number of lines processed from the 'trace' file
+TRACENL=3000
+
 # Since probe event command may include backslash, explicitly use printf "%s"
 # to NOT interpret it.
 ftrace_errlog_check() { # err-prefix command-with-error-pos-by-^ command-file
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 197cc2afd4046b..804d6a6e3a99dd 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"
+head -${TRACENL} trace | grep testprobe2 | grep -q "<- $FUNCTION_FORK"
 
 echo 0 > events/kprobes/testprobe2/enable
 echo '-:testprobe2' >> kprobe_events

base-commit: 6c0f39e87b6ab1a3009e3a49d3e6f6db8dc756a8
-- 
2.38.0

Re: [PATCH] selftests/ftrace: Limit number of lines processed in 'trace'

[Steven Rostedt]

On Mon, 17 Oct 2022 16:25:02 +0530
"Naveen N. Rao" <naveen.n.rao@linux.vnet.ibm.com> wrote:

> On very large machines, ftracetest can seem to hang or otherwise take a
> very long time to complete individual tests. This can be attributed to
> statements that try to process the entire contents of 'trace'.
> 
> Limit the number of lines processed from 'trace' to resolve this. Apart
> from the change in test.d/functions to add TRACENL, this commit is the
> result of running the below command (and fixing some whitespace errors):
>   grep -l -R 'cat trace |' -- ./tools/testing/selftests/ftrace/test.d/ | \
> 	xargs -n 1 sed --in-place -e "s/cat trace |/head -\$\{TRACENL\} trace |/g"
> 

No. This shows that there's an issue in the test. This should never hang
even with a thousand CPUs.

You need to make sure that the "pause-on-trace" option is set or tracing_on
is set to 0 (disabled). Otherwise, if the tracing is still active, then the
reading of the trace file could potentially never end.

Did you have tracing enabled and "pause_on_trace" not set when you ran that
above command? If so, then it may take forever to finish. But the tests
should take care to not read the trace file unless it has stopped tracing.

If there's a case where it will read while tracing is active, then sure, we
need to limit the reporting, otherwise nack on this change.

-- Steve

Re: [PATCH] selftests/ftrace: Limit number of lines processed in 'trace'

[Masami Hiramatsu]

On Mon, 17 Oct 2022 10:51:03 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Mon, 17 Oct 2022 16:25:02 +0530
> "Naveen N. Rao" <naveen.n.rao@linux.vnet.ibm.com> wrote:
> 
> > On very large machines, ftracetest can seem to hang or otherwise take a
> > very long time to complete individual tests. This can be attributed to
> > statements that try to process the entire contents of 'trace'.
> > 
> > Limit the number of lines processed from 'trace' to resolve this. Apart
> > from the change in test.d/functions to add TRACENL, this commit is the
> > result of running the below command (and fixing some whitespace errors):
> >   grep -l -R 'cat trace |' -- ./tools/testing/selftests/ftrace/test.d/ | \
> > 	xargs -n 1 sed --in-place -e "s/cat trace |/head -\$\{TRACENL\} trace |/g"
> > 
> 
> No. This shows that there's an issue in the test. This should never hang
> even with a thousand CPUs.
> 
> You need to make sure that the "pause-on-trace" option is set or tracing_on
> is set to 0 (disabled). Otherwise, if the tracing is still active, then the
> reading of the trace file could potentially never end.

initialize_ftrace() does this setting. So it must be set.
If you run the ftracetest on old kernel, this feature is not there and
it may cause a trouble. Naveen, can you clarify it?

Thank you,

> 
> Did you have tracing enabled and "pause_on_trace" not set when you ran that
> above command? If so, then it may take forever to finish. But the tests
> should take care to not read the trace file unless it has stopped tracing.
> 
> If there's a case where it will read while tracing is active, then sure, we
> need to limit the reporting, otherwise nack on this change.
> 
> -- Steve


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>

Re: [PATCH] selftests/ftrace: Limit number of lines processed in 'trace'

[Steven Rostedt]

On Wed, 19 Oct 2022 00:19:49 +0900
Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:

> > You need to make sure that the "pause-on-trace" option is set or tracing_on
> > is set to 0 (disabled). Otherwise, if the tracing is still active, then the
> > reading of the trace file could potentially never end.  
> 
> initialize_ftrace() does this setting. So it must be set.
> If you run the ftracetest on old kernel, this feature is not there and
> it may cause a trouble. Naveen, can you clarify it?

But for old kernels that do not have "pause-on-trace" it should be the
default. The "pause-on-trace" was added when the default was changed to not
pause the trace while reading it.

-- Steve

Re: [PATCH] selftests/ftrace: Limit number of lines processed in 'trace'

[Naveen N. Rao]

Steven Rostedt wrote:
> On Wed, 19 Oct 2022 00:19:49 +0900
> Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:
> 
>> > You need to make sure that the "pause-on-trace" option is set or tracing_on
>> > is set to 0 (disabled). Otherwise, if the tracing is still active, then the
>> > reading of the trace file could potentially never end.  
>> 
>> initialize_ftrace() does this setting. So it must be set.
>> If you run the ftracetest on old kernel, this feature is not there and
>> it may cause a trouble. Naveen, can you clarify it?

Yes, the change to not pause on opening the trace file looks to be the 
problem.

> 
> But for old kernels that do not have "pause-on-trace" it should be the
> default. The "pause-on-trace" was added when the default was changed to not
> pause the trace while reading it.

It looks like the kernel patch was picked up, but Masami's patch for the 
selftest wasn't backported. I have requested a test with that applied.

Separately, before I saw your response, I came up with the below patch 
to update the selftests to disable tracing before reading the trace 
file. I have also requested this to be tested.


- Naveen

---
 .../selftests/ftrace/test.d/ftrace/fgraph-filter-stack.tc     | 4 +++-
 tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter.tc | 2 ++
 .../selftests/ftrace/test.d/ftrace/func-filter-notrace-pid.tc | 3 ++-
 .../testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc | 3 ++-
 4 files changed, 9 insertions(+), 3 deletions(-)

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 cf3ea42b12b09f..7e74df1ef928f9 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
@@ -39,6 +39,7 @@ disable_tracing
 clear_trace
 enable_tracing
 sleep 1
+disable_tracing
 
 count=`cat trace | grep '()' | grep -v schedule | wc -l`
 
@@ -54,8 +55,9 @@ fi
 
 echo 0 > /proc/sys/kernel/stack_tracer_enabled
 clear_trace
+enable_tracing
 sleep 1
-
+disable_tracing
 
 count=`cat trace | grep '()' | grep -v schedule | wc -l`
 
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 b3ccdaec2a61ba..7e65a115054127 100644
--- a/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter.tc
+++ b/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter.tc
@@ -24,6 +24,8 @@ fi
 echo function_graph > current_tracer
 enable_tracing
 sleep 1
+disable_tracing
+
 # 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`
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 80541964b9270b..9fb0511b5d2eeb 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
@@ -51,6 +51,7 @@ do_test() {
 
     enable_tracing
     yield
+    disable_tracing
 
     count_pid=`cat trace | grep -v ^# | grep $PID | wc -l`
     count_other=`cat trace | grep -v ^# | grep -v $PID | wc -l`
@@ -60,7 +61,6 @@ do_test() {
 	fail "PID filtering not working? traced task = $count_pid; other tasks = $count_other "
     fi
 
-    disable_tracing
     clear_trace
 
     if [ $do_function_fork -eq 0 ]; then
@@ -77,6 +77,7 @@ do_test() {
 
     enable_tracing
     yield
+    disable_tracing
 
     count_pid=`cat trace | grep -v ^# | grep $PID | wc -l`
     count_other=`cat trace | grep -v ^# | grep -v $PID | wc -l`
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 2f7211254529ba..c55bcf2fe1966f 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
@@ -51,6 +51,7 @@ do_test() {
 
     enable_tracing
     yield
+    disable_tracing
 
     count_pid=`cat trace | grep -v ^# | grep $PID | wc -l`
     count_other=`cat trace | grep -v ^# | grep -v $PID | wc -l`
@@ -60,7 +61,6 @@ do_test() {
 	fail "PID filtering not working?"
     fi
 
-    disable_tracing
     clear_trace
 
     if [ $do_function_fork -eq 0 ]; then
@@ -72,6 +72,7 @@ do_test() {
 
     enable_tracing
     yield
+    disable_tracing
 
     count_pid=`cat trace | grep -v ^# | grep $PID | wc -l`
     count_other=`cat trace | grep -v ^# | grep -v $PID | wc -l`

Re: [PATCH] selftests/ftrace: Limit number of lines processed in 'trace'

[Masami Hiramatsu]

On Wed, 19 Oct 2022 15:15:09 +0530
"Naveen N. Rao" <naveen.n.rao@linux.vnet.ibm.com> wrote:

> Steven Rostedt wrote:
> > On Wed, 19 Oct 2022 00:19:49 +0900
> > Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:
> > 
> >> > You need to make sure that the "pause-on-trace" option is set or tracing_on
> >> > is set to 0 (disabled). Otherwise, if the tracing is still active, then the
> >> > reading of the trace file could potentially never end.  
> >> 
> >> initialize_ftrace() does this setting. So it must be set.
> >> If you run the ftracetest on old kernel, this feature is not there and
> >> it may cause a trouble. Naveen, can you clarify it?
> 
> Yes, the change to not pause on opening the trace file looks to be the 
> problem.
> 
> > 
> > But for old kernels that do not have "pause-on-trace" it should be the
> > default. The "pause-on-trace" was added when the default was changed to not
> > pause the trace while reading it.
> 
> It looks like the kernel patch was picked up, but Masami's patch for the 
> selftest wasn't backported. I have requested a test with that applied.

Good! That should be backported too.
BTW, which kernel version do you test?

> 
> Separately, before I saw your response, I came up with the below patch 
> to update the selftests to disable tracing before reading the trace 
> file. I have also requested this to be tested.

Yeah, OK. This also looks OK to me.

Thanks,

> 
> 
> - Naveen
> 
> ---
>  .../selftests/ftrace/test.d/ftrace/fgraph-filter-stack.tc     | 4 +++-
>  tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter.tc | 2 ++
>  .../selftests/ftrace/test.d/ftrace/func-filter-notrace-pid.tc | 3 ++-
>  .../testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc | 3 ++-
>  4 files changed, 9 insertions(+), 3 deletions(-)
> 
> 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 cf3ea42b12b09f..7e74df1ef928f9 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
> @@ -39,6 +39,7 @@ disable_tracing
>  clear_trace
>  enable_tracing
>  sleep 1
> +disable_tracing
>  
>  count=`cat trace | grep '()' | grep -v schedule | wc -l`
>  
> @@ -54,8 +55,9 @@ fi
>  
>  echo 0 > /proc/sys/kernel/stack_tracer_enabled
>  clear_trace
> +enable_tracing
>  sleep 1
> -
> +disable_tracing
>  
>  count=`cat trace | grep '()' | grep -v schedule | wc -l`
>  
> 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 b3ccdaec2a61ba..7e65a115054127 100644
> --- a/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter.tc
> +++ b/tools/testing/selftests/ftrace/test.d/ftrace/fgraph-filter.tc
> @@ -24,6 +24,8 @@ fi
>  echo function_graph > current_tracer
>  enable_tracing
>  sleep 1
> +disable_tracing
> +
>  # 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`
> 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 80541964b9270b..9fb0511b5d2eeb 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
> @@ -51,6 +51,7 @@ do_test() {
>  
>      enable_tracing
>      yield
> +    disable_tracing
>  
>      count_pid=`cat trace | grep -v ^# | grep $PID | wc -l`
>      count_other=`cat trace | grep -v ^# | grep -v $PID | wc -l`
> @@ -60,7 +61,6 @@ do_test() {
>  	fail "PID filtering not working? traced task = $count_pid; other tasks = $count_other "
>      fi
>  
> -    disable_tracing
>      clear_trace
>  
>      if [ $do_function_fork -eq 0 ]; then
> @@ -77,6 +77,7 @@ do_test() {
>  
>      enable_tracing
>      yield
> +    disable_tracing
>  
>      count_pid=`cat trace | grep -v ^# | grep $PID | wc -l`
>      count_other=`cat trace | grep -v ^# | grep -v $PID | wc -l`
> 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 2f7211254529ba..c55bcf2fe1966f 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
> @@ -51,6 +51,7 @@ do_test() {
>  
>      enable_tracing
>      yield
> +    disable_tracing
>  
>      count_pid=`cat trace | grep -v ^# | grep $PID | wc -l`
>      count_other=`cat trace | grep -v ^# | grep -v $PID | wc -l`
> @@ -60,7 +61,6 @@ do_test() {
>  	fail "PID filtering not working?"
>      fi
>  
> -    disable_tracing
>      clear_trace
>  
>      if [ $do_function_fork -eq 0 ]; then
> @@ -72,6 +72,7 @@ do_test() {
>  
>      enable_tracing
>      yield
> +    disable_tracing
>  
>      count_pid=`cat trace | grep -v ^# | grep $PID | wc -l`
>      count_other=`cat trace | grep -v ^# | grep -v $PID | wc -l`
> 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>

Re: [PATCH] selftests/ftrace: Limit number of lines processed in 'trace'

[Naveen N. Rao]

Masami Hiramatsu wrote:
> On Wed, 19 Oct 2022 15:15:09 +0530
> "Naveen N. Rao" <naveen.n.rao@linux.vnet.ibm.com> wrote:
> 
>> Steven Rostedt wrote:
>> > On Wed, 19 Oct 2022 00:19:49 +0900
>> > Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:
>> > 
>> >> > You need to make sure that the "pause-on-trace" option is set or tracing_on
>> >> > is set to 0 (disabled). Otherwise, if the tracing is still active, then the
>> >> > reading of the trace file could potentially never end.  
>> >> 
>> >> initialize_ftrace() does this setting. So it must be set.
>> >> If you run the ftracetest on old kernel, this feature is not there and
>> >> it may cause a trouble. Naveen, can you clarify it?
>> 
>> Yes, the change to not pause on opening the trace file looks to be the 
>> problem.
>> 
>> > 
>> > But for old kernels that do not have "pause-on-trace" it should be the
>> > default. The "pause-on-trace" was added when the default was changed to not
>> > pause the trace while reading it.
>> 
>> It looks like the kernel patch was picked up, but Masami's patch for the 
>> selftest wasn't backported. I have requested a test with that applied.
> 
> Good! That should be backported too.
> BTW, which kernel version do you test?

This was reported in internal tests with RHEL kernel.

> 
>> 
>> Separately, before I saw your response, I came up with the below patch 
>> to update the selftests to disable tracing before reading the trace 
>> file. I have also requested this to be tested.
> 
> Yeah, OK. This also looks OK to me.

This patch doesn't seem to be enough - event/subsystem-enable.tc also 
needs updates. In light of that, I'm not sure if the large number of 
disable_tracing statements required makes sense. So, I'm inclined to 
drop this patch in favour of the existing pause-on-trace option.


Thanks,
Naveen

Re: [PATCH] selftests/ftrace: Limit number of lines processed in 'trace'

[Shuah Khan]

On 10/17/22 04:55, Naveen N. Rao wrote:
> On very large machines, ftracetest can seem to hang or otherwise take a
> very long time to complete individual tests. This can be attributed to
> statements that try to process the entire contents of 'trace'.
> 
> Limit the number of lines processed from 'trace' to resolve this. Apart
> from the change in test.d/functions to add TRACENL, this commit is the
> result of running the below command (and fixing some whitespace errors):
>    grep -l -R 'cat trace |' -- ./tools/testing/selftests/ftrace/test.d/ | \
> 	xargs -n 1 sed --in-place -e "s/cat trace |/head -\$\{TRACENL\} trace |/g"
> 
> Reported-by: Akanksha J N <akanksha@linux.vnet.ibm.com>
> Signed-off-by: Naveen N. Rao <naveen.n.rao@linux.vnet.ibm.com>

Please cc linux-kselftest list on all selftest patches.

thanks,
-- Shuah