[PATCH] rcu/torture: Change order of warning and trace dump

[PATCH] rcu/torture: Change order of warning and trace dump

[Anna-Maria Behnsen]

Dumping a big ftrace buffer could lead to a RCU stall. So there is the
ftrace buffer and the stall information which needs to be printed. When
there is additionaly a WARN_ON() which describes the reason for the ftrace
buffer dump and the WARN_ON() is executed _after_ ftrace buffer dump, the
information get lost in the middle of the RCU stall information.

Therefore print WARN_ON() message before dumping the ftrace buffer in
rcu_torture_writer().

Signed-off-by: Anna-Maria Behnsen <anna-maria@linutronix.de>
Reviewed-by: Benedikt Spranger <b.spranger@linutronix.de>
---
 kernel/rcu/rcutorture.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index 55d049c39608..cbbe37d7701e 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -1287,8 +1287,8 @@ rcu_torture_writer(void *arg)
 				if (list_empty(&rcu_tortures[i].rtort_free) &&
 				    rcu_access_pointer(rcu_torture_current) !=
 				    &rcu_tortures[i]) {
-					rcu_ftrace_dump(DUMP_ALL);
 					WARN(1, "%s: rtort_pipe_count: %d\n", __func__, rcu_tortures[i].rtort_pipe_count);
+					rcu_ftrace_dump(DUMP_ALL);
 				}
 		if (stutter_waited)
 			sched_set_normal(current, oldnice);
-- 
2.20.1

Re: [PATCH] rcu/torture: Change order of warning and trace dump

[Paul E. McKenney]

On Mon, Apr 11, 2022 at 05:19:03PM +0200, Anna-Maria Behnsen wrote:
> Dumping a big ftrace buffer could lead to a RCU stall. So there is the
> ftrace buffer and the stall information which needs to be printed. When
> there is additionaly a WARN_ON() which describes the reason for the ftrace
> buffer dump and the WARN_ON() is executed _after_ ftrace buffer dump, the
> information get lost in the middle of the RCU stall information.
> 
> Therefore print WARN_ON() message before dumping the ftrace buffer in
> rcu_torture_writer().
> 
> Signed-off-by: Anna-Maria Behnsen <anna-maria@linutronix.de>
> Reviewed-by: Benedikt Spranger <b.spranger@linutronix.de>

Hello, Anna-Maria!

Good point, but we get caught out either way.  Either we take the chance
of losing the WARN() message as you say, or we take the chance of the
activity in the WARN() message overwriting needed information in the
trace buffer.

Would it work to shut off tracing, do the WARN(), and only then do the
rcu_ftrace_dump()?

							Thanx, Paul

> ---
>  kernel/rcu/rcutorture.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> index 55d049c39608..cbbe37d7701e 100644
> --- a/kernel/rcu/rcutorture.c
> +++ b/kernel/rcu/rcutorture.c
> @@ -1287,8 +1287,8 @@ rcu_torture_writer(void *arg)
>  				if (list_empty(&rcu_tortures[i].rtort_free) &&
>  				    rcu_access_pointer(rcu_torture_current) !=
>  				    &rcu_tortures[i]) {
> -					rcu_ftrace_dump(DUMP_ALL);
>  					WARN(1, "%s: rtort_pipe_count: %d\n", __func__, rcu_tortures[i].rtort_pipe_count);
> +					rcu_ftrace_dump(DUMP_ALL);
>  				}
>  		if (stutter_waited)
>  			sched_set_normal(current, oldnice);
> -- 
> 2.20.1
> 

Re: [PATCH] rcu/torture: Change order of warning and trace dump

[Paul E. McKenney]

On Mon, Apr 11, 2022 at 11:09:15AM -0700, Paul E. McKenney wrote:
> On Mon, Apr 11, 2022 at 05:19:03PM +0200, Anna-Maria Behnsen wrote:
> > Dumping a big ftrace buffer could lead to a RCU stall. So there is the
> > ftrace buffer and the stall information which needs to be printed. When
> > there is additionaly a WARN_ON() which describes the reason for the ftrace
> > buffer dump and the WARN_ON() is executed _after_ ftrace buffer dump, the
> > information get lost in the middle of the RCU stall information.
> > 
> > Therefore print WARN_ON() message before dumping the ftrace buffer in
> > rcu_torture_writer().
> > 
> > Signed-off-by: Anna-Maria Behnsen <anna-maria@linutronix.de>
> > Reviewed-by: Benedikt Spranger <b.spranger@linutronix.de>
> 
> Hello, Anna-Maria!
> 
> Good point, but we get caught out either way.  Either we take the chance
> of losing the WARN() message as you say, or we take the chance of the
> activity in the WARN() message overwriting needed information in the
> trace buffer.
> 
> Would it work to shut off tracing, do the WARN(), and only then do the
> rcu_ftrace_dump()?

And presumably you are looking at this because your testing is
triggering it.  This WARN() assumes that the system running rcutorture
is otherwise idle.  If you are (say) running kernel builds while also
running rcutorture, then this WARN() is expected behavior.  So if you need
this sort of testing, we need do something like adding another rcutorture
module parameter (background_load?) that suppresses this warning.

							Thanx, Paul

> > ---
> >  kernel/rcu/rcutorture.c | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> > 
> > diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> > index 55d049c39608..cbbe37d7701e 100644
> > --- a/kernel/rcu/rcutorture.c
> > +++ b/kernel/rcu/rcutorture.c
> > @@ -1287,8 +1287,8 @@ rcu_torture_writer(void *arg)
> >  				if (list_empty(&rcu_tortures[i].rtort_free) &&
> >  				    rcu_access_pointer(rcu_torture_current) !=
> >  				    &rcu_tortures[i]) {
> > -					rcu_ftrace_dump(DUMP_ALL);
> >  					WARN(1, "%s: rtort_pipe_count: %d\n", __func__, rcu_tortures[i].rtort_pipe_count);
> > +					rcu_ftrace_dump(DUMP_ALL);
> >  				}
> >  		if (stutter_waited)
> >  			sched_set_normal(current, oldnice);
> > -- 
> > 2.20.1
> > 

Re: [PATCH] rcu/torture: Change order of warning and trace dump

[Anna-Maria Behnsen]

On Tue, 12 Apr 2022, Paul E. McKenney wrote:

> On Mon, Apr 11, 2022 at 11:09:15AM -0700, Paul E. McKenney wrote:
> > On Mon, Apr 11, 2022 at 05:19:03PM +0200, Anna-Maria Behnsen wrote:
> > > Dumping a big ftrace buffer could lead to a RCU stall. So there is the
> > > ftrace buffer and the stall information which needs to be printed. When
> > > there is additionaly a WARN_ON() which describes the reason for the ftrace
> > > buffer dump and the WARN_ON() is executed _after_ ftrace buffer dump, the
> > > information get lost in the middle of the RCU stall information.
> > > 
> > > Therefore print WARN_ON() message before dumping the ftrace buffer in
> > > rcu_torture_writer().
> > > 
> > > Signed-off-by: Anna-Maria Behnsen <anna-maria@linutronix.de>
> > > Reviewed-by: Benedikt Spranger <b.spranger@linutronix.de>
> > 
> > Hello, Anna-Maria!
> > 
> > Good point, but we get caught out either way.  Either we take the chance
> > of losing the WARN() message as you say, or we take the chance of the
> > activity in the WARN() message overwriting needed information in the
> > trace buffer.
> > 
> > Would it work to shut off tracing, do the WARN(), and only then do the
> > rcu_ftrace_dump()?
> 
> And presumably you are looking at this because your testing is
> triggering it.  This WARN() assumes that the system running rcutorture
> is otherwise idle.  If you are (say) running kernel builds while also
> running rcutorture, then this WARN() is expected behavior.  So if you need
> this sort of testing, we need do something like adding another rcutorture
> module parameter (background_load?) that suppresses this warning.
> 

I ran into this while testing with rcutorture kvm script. And I was the
only one working on the machine. So I do not need a parameter right
now. I'll come back to you when my testing requirements will change :)

Thanks,

	Anna-Maria

Re: [PATCH] rcu/torture: Change order of warning and trace dump

[Paul E. McKenney]

On Tue, Apr 19, 2022 at 08:53:38AM +0200, Anna-Maria Behnsen wrote:
> On Tue, 12 Apr 2022, Paul E. McKenney wrote:
> 
> > On Mon, Apr 11, 2022 at 11:09:15AM -0700, Paul E. McKenney wrote:
> > > On Mon, Apr 11, 2022 at 05:19:03PM +0200, Anna-Maria Behnsen wrote:
> > > > Dumping a big ftrace buffer could lead to a RCU stall. So there is the
> > > > ftrace buffer and the stall information which needs to be printed. When
> > > > there is additionaly a WARN_ON() which describes the reason for the ftrace
> > > > buffer dump and the WARN_ON() is executed _after_ ftrace buffer dump, the
> > > > information get lost in the middle of the RCU stall information.
> > > > 
> > > > Therefore print WARN_ON() message before dumping the ftrace buffer in
> > > > rcu_torture_writer().
> > > > 
> > > > Signed-off-by: Anna-Maria Behnsen <anna-maria@linutronix.de>
> > > > Reviewed-by: Benedikt Spranger <b.spranger@linutronix.de>
> > > 
> > > Hello, Anna-Maria!
> > > 
> > > Good point, but we get caught out either way.  Either we take the chance
> > > of losing the WARN() message as you say, or we take the chance of the
> > > activity in the WARN() message overwriting needed information in the
> > > trace buffer.
> > > 
> > > Would it work to shut off tracing, do the WARN(), and only then do the
> > > rcu_ftrace_dump()?
> > 
> > And presumably you are looking at this because your testing is
> > triggering it.  This WARN() assumes that the system running rcutorture
> > is otherwise idle.  If you are (say) running kernel builds while also
> > running rcutorture, then this WARN() is expected behavior.  So if you need
> > this sort of testing, we need do something like adding another rcutorture
> > module parameter (background_load?) that suppresses this warning.
> 
> I ran into this while testing with rcutorture kvm script. And I was the
> only one working on the machine. So I do not need a parameter right
> now. I'll come back to you when my testing requirements will change :)

Sounds good, and thank you for the info!

							Thanx, Paul

Re: [PATCH] rcu/torture: Change order of warning and trace dump

[Paul E. McKenney]

On Mon, Apr 11, 2022 at 11:09:15AM -0700, Paul E. McKenney wrote:
> On Mon, Apr 11, 2022 at 05:19:03PM +0200, Anna-Maria Behnsen wrote:
> > Dumping a big ftrace buffer could lead to a RCU stall. So there is the
> > ftrace buffer and the stall information which needs to be printed. When
> > there is additionaly a WARN_ON() which describes the reason for the ftrace
> > buffer dump and the WARN_ON() is executed _after_ ftrace buffer dump, the
> > information get lost in the middle of the RCU stall information.
> > 
> > Therefore print WARN_ON() message before dumping the ftrace buffer in
> > rcu_torture_writer().
> > 
> > Signed-off-by: Anna-Maria Behnsen <anna-maria@linutronix.de>
> > Reviewed-by: Benedikt Spranger <b.spranger@linutronix.de>
> 
> Hello, Anna-Maria!
> 
> Good point, but we get caught out either way.  Either we take the chance
> of losing the WARN() message as you say, or we take the chance of the
> activity in the WARN() message overwriting needed information in the
> trace buffer.
> 
> Would it work to shut off tracing, do the WARN(), and only then do the
> rcu_ftrace_dump()?

For example, as shown the the updated patch below currently queued on -rcu
for further review and testing?

If this is problematic, please let me know!

							Thanx, Paul

------------------------------------------------------------------------

commit cdbc93534da1bba3f498783473361b2f26dc65d6
Author: Anna-Maria Behnsen <anna-maria@linutronix.de>
Date:   Mon Apr 11 17:19:03 2022 +0200

    rcu/torture: Change order of warning and trace dump
    
    Dumping a big ftrace buffer could lead to a RCU stall. So there is the
    ftrace buffer and the stall information which needs to be printed. When
    there is additionaly a WARN_ON() which describes the reason for the ftrace
    buffer dump and the WARN_ON() is executed _after_ ftrace buffer dump, the
    information get lost in the middle of the RCU stall information.
    
    Therefore print WARN_ON() message before dumping the ftrace buffer in
    rcu_torture_writer().
    
    [ paulmck: Add tracing_off() to avoid cruft from WARN(). ]
    
    Signed-off-by: Anna-Maria Behnsen <anna-maria@linutronix.de>
    Reviewed-by: Benedikt Spranger <b.spranger@linutronix.de>
    Signed-off-by: Paul E. McKenney <paulmck@kernel.org>

diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index 2b40a8f6d2a0..0885a66f9d76 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -1369,8 +1369,9 @@ rcu_torture_writer(void *arg)
 				if (list_empty(&rcu_tortures[i].rtort_free) &&
 				    rcu_access_pointer(rcu_torture_current) !=
 				    &rcu_tortures[i]) {
-					rcu_ftrace_dump(DUMP_ALL);
+					tracing_off();
 					WARN(1, "%s: rtort_pipe_count: %d\n", __func__, rcu_tortures[i].rtort_pipe_count);
+					rcu_ftrace_dump(DUMP_ALL);
 				}
 		if (stutter_waited)
 			sched_set_normal(current, oldnice);

Re: [PATCH] rcu/torture: Change order of warning and trace dump

[Anna-Maria Behnsen]

On Mon, 18 Apr 2022, Paul E. McKenney wrote:

> On Mon, Apr 11, 2022 at 11:09:15AM -0700, Paul E. McKenney wrote:
> > On Mon, Apr 11, 2022 at 05:19:03PM +0200, Anna-Maria Behnsen wrote:
> > > Dumping a big ftrace buffer could lead to a RCU stall. So there is the
> > > ftrace buffer and the stall information which needs to be printed. When
> > > there is additionaly a WARN_ON() which describes the reason for the ftrace
> > > buffer dump and the WARN_ON() is executed _after_ ftrace buffer dump, the
> > > information get lost in the middle of the RCU stall information.
> > > 
> > > Therefore print WARN_ON() message before dumping the ftrace buffer in
> > > rcu_torture_writer().
> > > 
> > > Signed-off-by: Anna-Maria Behnsen <anna-maria@linutronix.de>
> > > Reviewed-by: Benedikt Spranger <b.spranger@linutronix.de>
> > 
> > Hello, Anna-Maria!
> > 
> > Good point, but we get caught out either way.  Either we take the chance
> > of losing the WARN() message as you say, or we take the chance of the
> > activity in the WARN() message overwriting needed information in the
> > trace buffer.
> > 
> > Would it work to shut off tracing, do the WARN(), and only then do the
> > rcu_ftrace_dump()?
> 
> For example, as shown the the updated patch below currently queued on -rcu
> for further review and testing?
> 
> If this is problematic, please let me know!
> 

Hi Paul,

sorry for the late reply - I was busy with other things last week...

This solution is totally fine for me!

Thanks,

	Anna-Maria