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

[Paul E. McKenney]

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@xxxxxxxxxx> wrote:
> >
> > On Sun, Aug 13, 2023 at 08:36:02PM +0000, Joel Fernandes (Google) wrote:
> > > From: Joel Fernandes (Google) <joel@xxxxxxxxxxxxxxxxx>
> > >
> > > 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@xxxxxxxxxxxxxxxxx>
> >
> > 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.)

> 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.

> > commit ce1cf26540b96fc52aec6f6f8e365960ca79a0ad
> > Author: Joel Fernandes (Google) <joel@xxxxxxxxxxxxxxxxx>
> > Date:   Sun Aug 13 20:36:02 2023 +0000
> >
> >     rcutorture: Copy out ftrace into its own console file
> >
> >     When debugging it can be difficult to quickly find the ftrace dump
> >     withiin the console log, which in turn makes it difficult to process it
> 
> Nit: within.

Ouch, will fix on next rebase.

> >     independent of the result of the console output.  This commit therefore
> >     copies the contents of the buffers into its own file to make it easier
> >     to locate and process the ftrace dump. The original ftrace dump is still
> >     available in the console log in cases where it is more convenient to
> >     process it there, for example, when you have a script that processes
> >     console output as well as ftrace-dump data.
> >
> >     Signed-off-by: Joel Fernandes (Google) <joel@xxxxxxxxxxxxxxxxx>
> >     Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxx>
> >
> > 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..40bcddf5f197
> > --- a/tools/testing/selftests/rcutorture/bin/functions.sh
> > +++ b/tools/testing/selftests/rcutorture/bin/functions.sh
> > @@ -331,3 +331,27 @@ specify_qemu_net () {
> >                 echo $1 -net none
> >         fi
> >  }
> > +
> > +# Extract the ftrace output from the console log output
> > +# The ftrace output looks in the logs looks like:
> 
> My bad:  s/output looks/output/

Will fix on next rebase.

It is the "simple" ones that bite you!  ;-)

							Thanx, Paul

> Thanks,
> 
>  - Joel
> 
> 
> > +# Dumping ftrace buffer:
> > +# ---------------------------------
> > +# [...]
> > +# ---------------------------------
> > +extract_ftrace_from_console() {
> > +       awk '
> > +       /Dumping ftrace buffer:/ {
> > +               capture = 1
> > +               next
> > +       }
> > +       /---------------------------------/ {
> > +               if (capture == 1) {
> > +                       capture = 2
> > +                       next
> > +               } else if (capture == 2) {
> > +                       capture = 0
> > +               }
> > +       }
> > +       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