RCU stall leading to deadlock warning

RCU stall leading to deadlock warning

[Qais Yousef]

Hi Paul

We hit the below splat a couple of days ago in our testing. Sadly I can't
reproduce it. And it was on android-mainline branch..

It's the deadlock message that bothers me. I can't see how we could have ended
there. We detect a stall and when trying to dump the stack LOCKDEP spits the
warning.

Maybe should take this report with a pinch of salt since it wasn't on mainline.
I just thought it might be something worth sharing in case you can actually
spot something obvious that I can't see. If I got more info or a reproducer
I will share them.

The failure was triggered twice on that day running 2 different tests.

[  310.073379] LTP: starting leapsec01
[  345.070123] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  345.076717] rcu:     0-...!: (1 ticks this GP) idle=798/0/0x0 softirq=19187/19187 fqs=0  (false positive?)
[  345.087533]    (detected by 2, t=6502 jiffies, g=57249, q=184)
[  345.093284]
[  345.094797] ============================================
[  345.100139] WARNING: possible recursive locking detected
[  345.105485] 5.10.0-rc7-02296-g3f43bd6f2c3b-ab89 #1 Not tainted
[  345.111349] --------------------------------------------
[  345.116693] swapper/2/0 is trying to acquire lock:
[  345.121515] ffffa00013b50c58 (rcu_node_0){-.-.}-{2:2}, at: rcu_dump_cpu_stacks+0x7c/0x14c
[  345.129813]
[  345.129813] but task is already holding lock:
[  345.135678] ffffa00013b50c58 (rcu_node_0){-.-.}-{2:2}, at: rcu_sched_clock_irq+0x68c/0x11c0
[  345.144143]
[  345.144143] other info that might help us debug this:
[  345.150702]  Possible unsafe locking scenario:
[  345.150702]
[  345.156651]        CPU0
[  345.159119]        ----
[  345.161585]   lock(rcu_node_0);
[  345.164779]   lock(rcu_node_0);
[  345.167973]
[  345.167973]  *** DEADLOCK ***
[  345.167973]
[  345.173923]  May be due to missing lock nesting notation
[  345.173923]
[  345.180746] 1 lock held by swapper/2/0:
[  345.184607]  #0: ffffa00013b50c58 (rcu_node_0){-.-.}-{2:2}, at: rcu_sched_clock_irq+0x68c/0x11c0
[  345.193517]
[  345.193517] stack backtrace:
[  345.197910] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 5.10.0-rc7-02296-g3f43bd6f2c3b-ab89 #1
[  345.206389] Hardware name: ARM LTD ARM Juno Development Platform/ARM Juno Development Platform, BIOS EDK II Oct 19 2019
[  345.217215] Call trace:
[  345.219691]  dump_backtrace+0x0/0x2b8
[  345.223383]  show_stack+0x18/0x68
[  345.226731]  dump_stack+0x110/0x188
[  345.230255]  __lock_acquire+0x23f0/0x2410
[  345.234300]  lock_acquire+0x3b8/0x730
[  345.237997]  _raw_spin_lock_irqsave+0x80/0x168
[  345.242476]  rcu_dump_cpu_stacks+0x7c/0x14c
[  345.246693]  rcu_sched_clock_irq+0xfd4/0x11c0
[  345.251087]  update_process_times+0x84/0xe0
[  345.255306]  tick_sched_handle.isra.0+0x68/0x98
[  345.259871]  tick_sched_timer+0x60/0xd8
[  345.263742]  __hrtimer_run_queues+0x534/0x9e0
[  345.268134]  hrtimer_interrupt+0x1a8/0x398
[  345.272264]  tick_receive_broadcast+0x60/0x88
[  345.276657]  ipi_handler+0x250/0x4b8
[  345.280270]  handle_percpu_devid_fasteoi_ipi+0x138/0x4f0
[  345.285619]  generic_handle_irq+0x4c/0x68
[  345.289661]  __handle_domain_irq+0x9c/0x118
[  345.293880]  gic_handle_irq+0xdc/0x118
[  345.297661]  el1_irq+0xc8/0x180
[  345.300835]  cpuidle_enter_state+0x16c/0x810
[  345.305139]  cpuidle_enter+0x4c/0x78
[  345.308749]  call_cpuidle+0x44/0x88
[  345.312271]  do_idle+0x2d4/0x338
[  345.315532]  cpu_startup_entry+0x24/0x68
[  345.319491]  secondary_start_kernel+0x1d4/0x2d8

Thanks

--
Qais Yousef

Re: RCU stall leading to deadlock warning

[Paul E. McKenney]

On Wed, Dec 16, 2020 at 05:29:39PM +0000, Qais Yousef wrote:
> Hi Paul
> 
> We hit the below splat a couple of days ago in our testing. Sadly I can't
> reproduce it. And it was on android-mainline branch..
> 
> It's the deadlock message that bothers me. I can't see how we could have ended
> there. We detect a stall and when trying to dump the stack LOCKDEP spits the
> warning.
> 
> Maybe should take this report with a pinch of salt since it wasn't on mainline.
> I just thought it might be something worth sharing in case you can actually
> spot something obvious that I can't see. If I got more info or a reproducer
> I will share them.
> 
> The failure was triggered twice on that day running 2 different tests.

This looks like the same problem that Mark Rutland's recent patch series
was fixing.  Do you have this series applied?

lore.kernel.org/lkml/20201126123602.23454-1-mark.rutland@arm.com

							Thanx, Paul

> [  310.073379] LTP: starting leapsec01
> [  345.070123] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> [  345.076717] rcu:     0-...!: (1 ticks this GP) idle=798/0/0x0 softirq=19187/19187 fqs=0  (false positive?)
> [  345.087533]    (detected by 2, t=6502 jiffies, g=57249, q=184)
> [  345.093284]
> [  345.094797] ============================================
> [  345.100139] WARNING: possible recursive locking detected
> [  345.105485] 5.10.0-rc7-02296-g3f43bd6f2c3b-ab89 #1 Not tainted
> [  345.111349] --------------------------------------------
> [  345.116693] swapper/2/0 is trying to acquire lock:
> [  345.121515] ffffa00013b50c58 (rcu_node_0){-.-.}-{2:2}, at: rcu_dump_cpu_stacks+0x7c/0x14c
> [  345.129813]
> [  345.129813] but task is already holding lock:
> [  345.135678] ffffa00013b50c58 (rcu_node_0){-.-.}-{2:2}, at: rcu_sched_clock_irq+0x68c/0x11c0
> [  345.144143]
> [  345.144143] other info that might help us debug this:
> [  345.150702]  Possible unsafe locking scenario:
> [  345.150702]
> [  345.156651]        CPU0
> [  345.159119]        ----
> [  345.161585]   lock(rcu_node_0);
> [  345.164779]   lock(rcu_node_0);
> [  345.167973]
> [  345.167973]  *** DEADLOCK ***
> [  345.167973]
> [  345.173923]  May be due to missing lock nesting notation
> [  345.173923]
> [  345.180746] 1 lock held by swapper/2/0:
> [  345.184607]  #0: ffffa00013b50c58 (rcu_node_0){-.-.}-{2:2}, at: rcu_sched_clock_irq+0x68c/0x11c0
> [  345.193517]
> [  345.193517] stack backtrace:
> [  345.197910] CPU: 2 PID: 0 Comm: swapper/2 Not tainted 5.10.0-rc7-02296-g3f43bd6f2c3b-ab89 #1
> [  345.206389] Hardware name: ARM LTD ARM Juno Development Platform/ARM Juno Development Platform, BIOS EDK II Oct 19 2019
> [  345.217215] Call trace:
> [  345.219691]  dump_backtrace+0x0/0x2b8
> [  345.223383]  show_stack+0x18/0x68
> [  345.226731]  dump_stack+0x110/0x188
> [  345.230255]  __lock_acquire+0x23f0/0x2410
> [  345.234300]  lock_acquire+0x3b8/0x730
> [  345.237997]  _raw_spin_lock_irqsave+0x80/0x168
> [  345.242476]  rcu_dump_cpu_stacks+0x7c/0x14c
> [  345.246693]  rcu_sched_clock_irq+0xfd4/0x11c0
> [  345.251087]  update_process_times+0x84/0xe0
> [  345.255306]  tick_sched_handle.isra.0+0x68/0x98
> [  345.259871]  tick_sched_timer+0x60/0xd8
> [  345.263742]  __hrtimer_run_queues+0x534/0x9e0
> [  345.268134]  hrtimer_interrupt+0x1a8/0x398
> [  345.272264]  tick_receive_broadcast+0x60/0x88
> [  345.276657]  ipi_handler+0x250/0x4b8
> [  345.280270]  handle_percpu_devid_fasteoi_ipi+0x138/0x4f0
> [  345.285619]  generic_handle_irq+0x4c/0x68
> [  345.289661]  __handle_domain_irq+0x9c/0x118
> [  345.293880]  gic_handle_irq+0xdc/0x118
> [  345.297661]  el1_irq+0xc8/0x180
> [  345.300835]  cpuidle_enter_state+0x16c/0x810
> [  345.305139]  cpuidle_enter+0x4c/0x78
> [  345.308749]  call_cpuidle+0x44/0x88
> [  345.312271]  do_idle+0x2d4/0x338
> [  345.315532]  cpu_startup_entry+0x24/0x68
> [  345.319491]  secondary_start_kernel+0x1d4/0x2d8
> 
> Thanks
> 
> --
> Qais Yousef

Re: RCU stall leading to deadlock warning

[Paul E. McKenney]

On Wed, Dec 16, 2020 at 09:54:42AM -0800, Paul E. McKenney wrote:
> On Wed, Dec 16, 2020 at 05:29:39PM +0000, Qais Yousef wrote:
> > Hi Paul
> > 
> > We hit the below splat a couple of days ago in our testing. Sadly I can't
> > reproduce it. And it was on android-mainline branch..
> > 
> > It's the deadlock message that bothers me. I can't see how we could have ended
> > there. We detect a stall and when trying to dump the stack LOCKDEP spits the
> > warning.
> > 
> > Maybe should take this report with a pinch of salt since it wasn't on mainline.
> > I just thought it might be something worth sharing in case you can actually
> > spot something obvious that I can't see. If I got more info or a reproducer
> > I will share them.
> > 
> > The failure was triggered twice on that day running 2 different tests.
> 
> This looks like the same problem that Mark Rutland's recent patch series
> was fixing.  Do you have this series applied?
> 
> lore.kernel.org/lkml/20201126123602.23454-1-mark.rutland@arm.com

I would not expect the patch below to help given what your RCU CPU stall
warning looks like, but just in case...

(Full disclosure: Peter fixed a bug of mine, filenames notwithstanding.)

							Thanx, Paul

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

commit f355d19f94bf4361d641fb3dbb9ece0fbac766f8
Author: Peter Zijlstra <peterz@infradead.org>
Date:   Sat Aug 29 10:22:24 2020 -0700

    sched/core: Allow try_invoke_on_locked_down_task() with irqs disabled
    
    The try_invoke_on_locked_down_task() function currently requires
    that interrupts be enabled, but it is called with interrupts
    disabled from rcu_print_task_stall(), resulting in an "IRQs not
    enabled as expected" diagnostic.  This commit therefore updates
    try_invoke_on_locked_down_task() to use raw_spin_lock_irqsave() instead
    of raw_spin_lock_irq(), thus allowing use from either context.
    
    Link: https://lore.kernel.org/lkml/000000000000903d5805ab908fc4@google.com/
    Link: https://lore.kernel.org/lkml/20200928075729.GC2611@hirez.programming.kicks-ass.net/
    Reported-by: syzbot+cb3b69ae80afd6535b0e@syzkaller.appspotmail.com
    Signed-off-by: Peter Zijlstra <peterz@infradead.org>
    Signed-off-by: Paul E. McKenney <paulmck@kernel.org>

diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index b2d6898..4abf041 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -2989,7 +2989,7 @@ try_to_wake_up(struct task_struct *p, unsigned int state, int wake_flags)
 
 /**
  * try_invoke_on_locked_down_task - Invoke a function on task in fixed state
- * @p: Process for which the function is to be invoked.
+ * @p: Process for which the function is to be invoked, can be @current.
  * @func: Function to invoke.
  * @arg: Argument to function.
  *
@@ -3007,12 +3007,11 @@ try_to_wake_up(struct task_struct *p, unsigned int state, int wake_flags)
  */
 bool try_invoke_on_locked_down_task(struct task_struct *p, bool (*func)(struct task_struct *t, void *arg), void *arg)
 {
-	bool ret = false;
 	struct rq_flags rf;
+	bool ret = false;
 	struct rq *rq;
 
-	lockdep_assert_irqs_enabled();
-	raw_spin_lock_irq(&p->pi_lock);
+	raw_spin_lock_irqsave(&p->pi_lock, rf.flags);
 	if (p->on_rq) {
 		rq = __task_rq_lock(p, &rf);
 		if (task_rq(p) == rq)
@@ -3029,7 +3028,7 @@ bool try_invoke_on_locked_down_task(struct task_struct *p, bool (*func)(struct t
 				ret = func(p, arg);
 		}
 	}
-	raw_spin_unlock_irq(&p->pi_lock);
+	raw_spin_unlock_irqrestore(&p->pi_lock, rf.flags);
 	return ret;
 }
 

Re: RCU stall leading to deadlock warning

[Qais Yousef]

On 12/16/20 10:00, Paul E. McKenney wrote:
> On Wed, Dec 16, 2020 at 09:54:42AM -0800, Paul E. McKenney wrote:
> > On Wed, Dec 16, 2020 at 05:29:39PM +0000, Qais Yousef wrote:
> > > Hi Paul
> > > 
> > > We hit the below splat a couple of days ago in our testing. Sadly I can't
> > > reproduce it. And it was on android-mainline branch..
> > > 
> > > It's the deadlock message that bothers me. I can't see how we could have ended
> > > there. We detect a stall and when trying to dump the stack LOCKDEP spits the
> > > warning.
> > > 
> > > Maybe should take this report with a pinch of salt since it wasn't on mainline.
> > > I just thought it might be something worth sharing in case you can actually
> > > spot something obvious that I can't see. If I got more info or a reproducer
> > > I will share them.
> > > 
> > > The failure was triggered twice on that day running 2 different tests.
> > 
> > This looks like the same problem that Mark Rutland's recent patch series
> > was fixing.  Do you have this series applied?
> > 
> > lore.kernel.org/lkml/20201126123602.23454-1-mark.rutland@arm.com

Oh yeah I remember this one. Yes it could be relevant. I don't see the series
in the tree. If it wasn't merged (which AFAICS it isn't), it won't appear
there.

> I would not expect the patch below to help given what your RCU CPU stall
> warning looks like, but just in case...

Thanks. If I manage to find a reproducer I will give it a go. Still no luck in
triggering it in my test env :(

Thanks

--
Qais Yousef

> 
> (Full disclosure: Peter fixed a bug of mine, filenames notwithstanding.)
> 
> 							Thanx, Paul
> 
> ------------------------------------------------------------------------
> 
> commit f355d19f94bf4361d641fb3dbb9ece0fbac766f8
> Author: Peter Zijlstra <peterz@infradead.org>
> Date:   Sat Aug 29 10:22:24 2020 -0700
> 
>     sched/core: Allow try_invoke_on_locked_down_task() with irqs disabled
>     
>     The try_invoke_on_locked_down_task() function currently requires
>     that interrupts be enabled, but it is called with interrupts
>     disabled from rcu_print_task_stall(), resulting in an "IRQs not
>     enabled as expected" diagnostic.  This commit therefore updates
>     try_invoke_on_locked_down_task() to use raw_spin_lock_irqsave() instead
>     of raw_spin_lock_irq(), thus allowing use from either context.
>     
>     Link: https://lore.kernel.org/lkml/000000000000903d5805ab908fc4@google.com/
>     Link: https://lore.kernel.org/lkml/20200928075729.GC2611@hirez.programming.kicks-ass.net/
>     Reported-by: syzbot+cb3b69ae80afd6535b0e@syzkaller.appspotmail.com
>     Signed-off-by: Peter Zijlstra <peterz@infradead.org>
>     Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> 
> diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> index b2d6898..4abf041 100644
> --- a/kernel/sched/core.c
> +++ b/kernel/sched/core.c
> @@ -2989,7 +2989,7 @@ try_to_wake_up(struct task_struct *p, unsigned int state, int wake_flags)
>  
>  /**
>   * try_invoke_on_locked_down_task - Invoke a function on task in fixed state
> - * @p: Process for which the function is to be invoked.
> + * @p: Process for which the function is to be invoked, can be @current.
>   * @func: Function to invoke.
>   * @arg: Argument to function.
>   *
> @@ -3007,12 +3007,11 @@ try_to_wake_up(struct task_struct *p, unsigned int state, int wake_flags)
>   */
>  bool try_invoke_on_locked_down_task(struct task_struct *p, bool (*func)(struct task_struct *t, void *arg), void *arg)
>  {
> -	bool ret = false;
>  	struct rq_flags rf;
> +	bool ret = false;
>  	struct rq *rq;
>  
> -	lockdep_assert_irqs_enabled();
> -	raw_spin_lock_irq(&p->pi_lock);
> +	raw_spin_lock_irqsave(&p->pi_lock, rf.flags);
>  	if (p->on_rq) {
>  		rq = __task_rq_lock(p, &rf);
>  		if (task_rq(p) == rq)
> @@ -3029,7 +3028,7 @@ bool try_invoke_on_locked_down_task(struct task_struct *p, bool (*func)(struct t
>  				ret = func(p, arg);
>  		}
>  	}
> -	raw_spin_unlock_irq(&p->pi_lock);
> +	raw_spin_unlock_irqrestore(&p->pi_lock, rf.flags);
>  	return ret;
>  }
>