| Message ID | 20230813203602.GA696907@google.com (mailing list archive) |
|---|---|
| State | Superseded |
| Headers | show |
| Series | [v2] rcutorture: Copy out ftrace into its own console file | expand |
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? Thanx, Paul ------------------------------------------------------------------------ commit ce1cf26540b96fc52aec6f6f8e365960ca79a0ad Author: Joel Fernandes (Google) <joel@joelfernandes.org> 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) <joel@joelfernandes.org> Signed-off-by: Paul E. McKenney <paulmck@kernel.org> 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 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. 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. > commit ce1cf26540b96fc52aec6f6f8e365960ca79a0ad > Author: Joel Fernandes (Google) <joel@joelfernandes.org> > 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. > 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@joelfernandes.org> > Signed-off-by: Paul E. McKenney <paulmck@kernel.org> > > 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/ 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 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.) > 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@joelfernandes.org> > > 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@joelfernandes.org> > > Signed-off-by: Paul E. McKenney <paulmck@kernel.org> > > > > 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
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
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@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 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 >
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