Re: [PATCH v2] rcutorture: Copy out ftrace into its own console file

[Joel Fernandes <joel@joelfernandes.org>]

Hi Paul,

On Mon, Aug 14, 2023 at 03:27:33PM -0700, Paul E. McKenney wrote:
> On Mon, Aug 14, 2023 at 06:03:24PM -0400, Joel Fernandes wrote:
> > On Mon, Aug 14, 2023 at 5:27 PM Paul E. McKenney <paulmck@kernel.org> wrote:
> > >
> > > On Sun, Aug 13, 2023 at 08:36:02PM +0000, Joel Fernandes (Google) wrote:
> > > > From: Joel Fernandes (Google) <joel@joelfernandes.org>
> > > >
> > > > Often times during debugging, it is difficult to jump to the ftrace dump
> > > > in the console log and treat it independent of the result of the log file.
> > > > Copy the contents of the buffers into its own file to make it easier to refer
> > > > to the ftrace dump. The original ftrace dump is still available in the
> > > > console log if it is desired to refer to it there.
> > > >
> > > > Signed-off-by: Joel Fernandes (Google) <joel@joelfernandes.org>
> > >
> > > Queued, thank you!  I did the usual wordsmithing, please see below.
> > >
> > > I also fixed up the indentation and spacing.  I don't know about you,
> > > but the initial format made that a bit hard for me to read.  ;-)
> > >
> > > If there are multiple ftrace dumps in a given console.log file, this
> > > will concatenate them.  Is that the intent?
> > 
> > How would you have multiple dumps, do you mean from subsequent
> > (re)boots? If so, yes I am OK with that. I usually look at the latest
> > boot attempt.
> 
> Fair, but how would you separate out the ftrace dump for the most
> recent kernel boot?  (Though please see below.)

It will print the same markers in console.log which can be used. I posted an
updated diff below.

> 
> > I was also thinking of us stopping boot loops. For example, if there
> > is a kernel issue and the system keeps rebooting, it will run forever
> > in the boot loop silently. It would be good for monitoring of
> > console.log and kill the test if the console.log is acting 'weird'.
> > Also it would be good if the console.log had a huge timestamp gap in
> > it like the TREE04 issue. Would such changes be good to make? I can
> > attempt something.
> 
> Boot loops can indeed be irritating.  So I created this commit:
> 
> 10f84c2cfb50 ("torture: Avoid torture-test reboot loops")
> 
> This passes -no-reboot to qemu, which causes qemu to just stop when
> it would otherwise reboot.  Much nicer!
> 
> The multiple-ftrace-dump issue could still appear should some torture
> test decide to turn tracing back on at some point, perhaps in response
> to a yet-as-unthought-of module parameter.
> 
> Should this ever be a problem, one approach would be to leave the
> beginning/end markers and/or number them.

Thanks for doing this! I'll add it to all my trees.

Also let us replace the diff with the below [3] to properly label potential
multiple dumps?  Example for a file like [1], it will extract as [2].

[1]:

foo
foo
Dumping ftrace buffer:
---------------------------------
blah
blah
---------------------------------
more
bar
baz
Dumping ftrace buffer:
---------------------------------
blah2
blah2
---------------------------------
bleh
bleh

[2]:

Ftrace dump 1:
blah
blah

Ftrace dump 2:
blah2
blah2

---8<-----------------------
[3]

diff --git a/tools/testing/selftests/rcutorture/bin/functions.sh b/tools/testing/selftests/rcutorture/bin/functions.sh
old mode 100644
new mode 100755
index b8e2ea23cb3f..a5c74e508e41
--- a/tools/testing/selftests/rcutorture/bin/functions.sh
+++ b/tools/testing/selftests/rcutorture/bin/functions.sh
@@ -331,3 +331,30 @@ specify_qemu_net () {
 		echo $1 -net none
 	fi
 }
+
+# Extract the ftrace output from the console log output
+# The ftrace output in the original logs look like:
+# Dumping ftrace buffer:
+# ---------------------------------
+# [...]
+# ---------------------------------
+extract_ftrace_from_console() {
+        awk '
+        /Dumping ftrace buffer:/ {
+        buffer_count++
+        print "Ftrace dump " buffer_count ":"
+        capture = 1
+        next
+    }
+    /---------------------------------/ {
+        if(capture == 1) {
+            capture = 2
+            next
+        } else if(capture == 2) {
+            capture = 0
+            print ""
+        }
+    }
+    capture == 2
+    ' "$1";
+}
diff --git a/tools/testing/selftests/rcutorture/bin/parse-console.sh b/tools/testing/selftests/rcutorture/bin/parse-console.sh
index 9ab0f6bc172c..e3d2f69ec0fb 100755
--- a/tools/testing/selftests/rcutorture/bin/parse-console.sh
+++ b/tools/testing/selftests/rcutorture/bin/parse-console.sh
@@ -182,3 +182,10 @@ if ! test -s $file.diags
 then
 	rm -f $file.diags
 fi
+
+# Call extract_ftrace_from_console function, if the output is empty,
+# don't create $file.ftrace. Otherwise output the results to $file.ftrace
+extract_ftrace_from_console $file > $file.ftrace
+if [ ! -s $file.ftrace ]; then
+	rm -f $file.ftrace
+fi
-- 
2.41.0.694.ge786442a9b-goog