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

[Paul E. McKenney]

On Tue, Aug 15, 2023 at 02:14:39AM +0000, Joel Fernandes wrote:
> 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@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.)
> 
> 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

Sounds good to me!

Could you please take the version of your patch that I have queued
on -rcu, apply these changes (adding the above to the commit log)
and officially re-send?

							Thanx, Paul

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