From: Joel Fernandes (Google) <[email protected]>
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) <[email protected]>
---
v1-v2: Change log updates, "From:" updates.
.../selftests/rcutorture/bin/functions.sh | 24 +++++++++++++++++++
.../selftests/rcutorture/bin/parse-console.sh | 7 ++++++
2 files changed, 31 insertions(+)
mode change 100644 => 100755 tools/testing/selftests/rcutorture/bin/functions.sh
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..2ec4ab87a7f0
--- 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:
+# 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
--
2.41.0.640.ga95def55d0-goog
On Sun, Aug 13, 2023 at 08:36:02PM +0000, Joel Fernandes (Google) wrote:
> From: Joel Fernandes (Google) <[email protected]>
>
> 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) <[email protected]>
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?
Thanx, Paul
------------------------------------------------------------------------
commit ce1cf26540b96fc52aec6f6f8e365960ca79a0ad
Author: Joel Fernandes (Google) <[email protected]>
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
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) <[email protected]>
Signed-off-by: Paul E. McKenney <[email protected]>
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:
+# 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
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 <[email protected]> wrote:
> >
> > On Sun, Aug 13, 2023 at 08:36:02PM +0000, Joel Fernandes (Google) wrote:
> > > From: Joel Fernandes (Google) <[email protected]>
> > >
> > > 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) <[email protected]>
> >
> > 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) <[email protected]>
> > 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) <[email protected]>
> > Signed-off-by: Paul E. McKenney <[email protected]>
> >
> > 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
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 <[email protected]> wrote:
> > > >
> > > > On Sun, Aug 13, 2023 at 08:36:02PM +0000, Joel Fernandes (Google) wrote:
> > > > > From: Joel Fernandes (Google) <[email protected]>
> > > > >
> > > > > 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) <[email protected]>
> > > >
> > > > 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
>