RCU lockup in the SMP idle thread, help...

RCU lockup in the SMP idle thread, help...

[Linus Walleij]

Hi Paul et al,

I have this sporadic lockup in the SMP idle thread on ARM U8500:

root@ME:/
root@ME:/
root@ME:/ INFO: rcu_preempt detected stalls on CPUs/tasks: { 0}
(detected by 1, t=23190 jiffies)
[<c0014710>] (unwind_backtrace+0x0/0xf8) from [<c0068624>]
(rcu_check_callbacks+0x69c/0x6e0)
[<c0068624>] (rcu_check_callbacks+0x69c/0x6e0) from [<c0029cbc>]
(update_process_times+0x38/0x4c)
[<c0029cbc>] (update_process_times+0x38/0x4c) from [<c0055088>]
(tick_sched_timer+0x80/0xe4)
[<c0055088>] (tick_sched_timer+0x80/0xe4) from [<c003c120>]
(__run_hrtimer.isra.18+0x44/0xd0)
[<c003c120>] (__run_hrtimer.isra.18+0x44/0xd0) from [<c003cae0>]
(hrtimer_interrupt+0x118/0x2b4)
[<c003cae0>] (hrtimer_interrupt+0x118/0x2b4) from [<c0013658>]
(twd_handler+0x30/0x44)
[<c0013658>] (twd_handler+0x30/0x44) from [<c0063834>]
(handle_percpu_devid_irq+0x80/0xa0)
[<c0063834>] (handle_percpu_devid_irq+0x80/0xa0) from [<c00601ec>]
(generic_handle_irq+0x2c/0x40)
[<c00601ec>] (generic_handle_irq+0x2c/0x40) from [<c000ef58>]
(handle_IRQ+0x4c/0xac)
[<c000ef58>] (handle_IRQ+0x4c/0xac) from [<c00084bc>] (gic_handle_irq+0x24/0x58)
[<c00084bc>] (gic_handle_irq+0x24/0x58) from [<c000dc80>] (__irq_svc+0x40/0x70)
Exception stack(0xcf851f88 to 0xcf851fd0)
1f80:                   00000020 c05d5920 00000001 00000000 cf850000 cf850000
1fa0: c05f4d48 c02de0b4 c05d8d90 412fc091 cf850000 00000000 01000000 cf851fd0
1fc0: c000f234 c000f238 60000013 ffffffff
[<c000dc80>] (__irq_svc+0x40/0x70) from [<c000f238>] (default_idle+0x28/0x30)
[<c000f238>] (default_idle+0x28/0x30) from [<c000f438>] (cpu_idle+0x98/0xe4)
[<c000f438>] (cpu_idle+0x98/0xe4) from [<002d2ef4>] (0x2d2ef4)

The hangup has been there in the v3.6-rc series for a while (probably
since the merge window).

I haven't been able to bisect out why this is happening, because the bug
is pretty hazardous to check - you have to boot the system and leave it alone
or use it sporadically for a while. Then all of a sudden it happens.

So: reproducible, but not deterministically reproducible (I hate this kind
of thing...)

The code involved seems to be generic kernel code apart from the
ARM GIC and TWD timer drivers.

Any hints or debug options I should switch on?

Yours,
Linus Walleij

Re: RCU lockup in the SMP idle thread, help...

[John Stultz]

On 09/13/2012 05:36 AM, Linus Walleij wrote:
> Hi Paul et al,
>
> I have this sporadic lockup in the SMP idle thread on ARM U8500:
>
> root@ME:/
> root@ME:/
> root@ME:/ INFO: rcu_preempt detected stalls on CPUs/tasks: { 0}
> (detected by 1, t=23190 jiffies)
> [<c0014710>] (unwind_backtrace+0x0/0xf8) from [<c0068624>]
> (rcu_check_callbacks+0x69c/0x6e0)
> [<c0068624>] (rcu_check_callbacks+0x69c/0x6e0) from [<c0029cbc>]
> (update_process_times+0x38/0x4c)
> [<c0029cbc>] (update_process_times+0x38/0x4c) from [<c0055088>]
> (tick_sched_timer+0x80/0xe4)
> [<c0055088>] (tick_sched_timer+0x80/0xe4) from [<c003c120>]
> (__run_hrtimer.isra.18+0x44/0xd0)
> [<c003c120>] (__run_hrtimer.isra.18+0x44/0xd0) from [<c003cae0>]
> (hrtimer_interrupt+0x118/0x2b4)
> [<c003cae0>] (hrtimer_interrupt+0x118/0x2b4) from [<c0013658>]
> (twd_handler+0x30/0x44)
> [<c0013658>] (twd_handler+0x30/0x44) from [<c0063834>]
> (handle_percpu_devid_irq+0x80/0xa0)
> [<c0063834>] (handle_percpu_devid_irq+0x80/0xa0) from [<c00601ec>]
> (generic_handle_irq+0x2c/0x40)
> [<c00601ec>] (generic_handle_irq+0x2c/0x40) from [<c000ef58>]
> (handle_IRQ+0x4c/0xac)
> [<c000ef58>] (handle_IRQ+0x4c/0xac) from [<c00084bc>] (gic_handle_irq+0x24/0x58)
> [<c00084bc>] (gic_handle_irq+0x24/0x58) from [<c000dc80>] (__irq_svc+0x40/0x70)
> Exception stack(0xcf851f88 to 0xcf851fd0)
> 1f80:                   00000020 c05d5920 00000001 00000000 cf850000 cf850000
> 1fa0: c05f4d48 c02de0b4 c05d8d90 412fc091 cf850000 00000000 01000000 cf851fd0
> 1fc0: c000f234 c000f238 60000013 ffffffff
> [<c000dc80>] (__irq_svc+0x40/0x70) from [<c000f238>] (default_idle+0x28/0x30)
> [<c000f238>] (default_idle+0x28/0x30) from [<c000f438>] (cpu_idle+0x98/0xe4)
> [<c000f438>] (cpu_idle+0x98/0xe4) from [<002d2ef4>] (0x2d2ef4)
>
> The hangup has been there in the v3.6-rc series for a while (probably
> since the merge window).
>
> I haven't been able to bisect out why this is happening, because the bug
> is pretty hazardous to check - you have to boot the system and leave it alone
> or use it sporadically for a while. Then all of a sudden it happens.
>
> So: reproducible, but not deterministically reproducible (I hate this kind
> of thing...)
>
> The code involved seems to be generic kernel code apart from the
> ARM GIC and TWD timer drivers.
>
> Any hints or debug options I should switch on?

I saw this once as well testing the fix to Daniel's deep idle hang issue 
(also on 32 bit).

Really briefly looking at the code in rcutree.c, I'm curious if we're 
hitting a false positive on the 5 minute jiffies overflow?

thanks
-john

Re: RCU lockup in the SMP idle thread, help...

[Paul E. McKenney]

On Thu, Sep 13, 2012 at 09:49:14AM -0700, John Stultz wrote:
> On 09/13/2012 05:36 AM, Linus Walleij wrote:
> >Hi Paul et al,
> >
> >I have this sporadic lockup in the SMP idle thread on ARM U8500:
> >
> >root@ME:/
> >root@ME:/
> >root@ME:/ INFO: rcu_preempt detected stalls on CPUs/tasks: { 0}
> >(detected by 1, t=23190 jiffies)
> >[<c0014710>] (unwind_backtrace+0x0/0xf8) from [<c0068624>]
> >(rcu_check_callbacks+0x69c/0x6e0)
> >[<c0068624>] (rcu_check_callbacks+0x69c/0x6e0) from [<c0029cbc>]
> >(update_process_times+0x38/0x4c)
> >[<c0029cbc>] (update_process_times+0x38/0x4c) from [<c0055088>]
> >(tick_sched_timer+0x80/0xe4)
> >[<c0055088>] (tick_sched_timer+0x80/0xe4) from [<c003c120>]
> >(__run_hrtimer.isra.18+0x44/0xd0)
> >[<c003c120>] (__run_hrtimer.isra.18+0x44/0xd0) from [<c003cae0>]
> >(hrtimer_interrupt+0x118/0x2b4)
> >[<c003cae0>] (hrtimer_interrupt+0x118/0x2b4) from [<c0013658>]
> >(twd_handler+0x30/0x44)
> >[<c0013658>] (twd_handler+0x30/0x44) from [<c0063834>]
> >(handle_percpu_devid_irq+0x80/0xa0)
> >[<c0063834>] (handle_percpu_devid_irq+0x80/0xa0) from [<c00601ec>]
> >(generic_handle_irq+0x2c/0x40)
> >[<c00601ec>] (generic_handle_irq+0x2c/0x40) from [<c000ef58>]
> >(handle_IRQ+0x4c/0xac)
> >[<c000ef58>] (handle_IRQ+0x4c/0xac) from [<c00084bc>] (gic_handle_irq+0x24/0x58)
> >[<c00084bc>] (gic_handle_irq+0x24/0x58) from [<c000dc80>] (__irq_svc+0x40/0x70)
> >Exception stack(0xcf851f88 to 0xcf851fd0)
> >1f80:                   00000020 c05d5920 00000001 00000000 cf850000 cf850000
> >1fa0: c05f4d48 c02de0b4 c05d8d90 412fc091 cf850000 00000000 01000000 cf851fd0
> >1fc0: c000f234 c000f238 60000013 ffffffff
> >[<c000dc80>] (__irq_svc+0x40/0x70) from [<c000f238>] (default_idle+0x28/0x30)
> >[<c000f238>] (default_idle+0x28/0x30) from [<c000f438>] (cpu_idle+0x98/0xe4)
> >[<c000f438>] (cpu_idle+0x98/0xe4) from [<002d2ef4>] (0x2d2ef4)
> >
> >The hangup has been there in the v3.6-rc series for a while (probably
> >since the merge window).
> >
> >I haven't been able to bisect out why this is happening, because the bug
> >is pretty hazardous to check - you have to boot the system and leave it alone
> >or use it sporadically for a while. Then all of a sudden it happens.
> >
> >So: reproducible, but not deterministically reproducible (I hate this kind
> >of thing...)
> >
> >The code involved seems to be generic kernel code apart from the
> >ARM GIC and TWD timer drivers.
> >
> >Any hints or debug options I should switch on?
> 
> I saw this once as well testing the fix to Daniel's deep idle hang
> issue (also on 32 bit).
> 
> Really briefly looking at the code in rcutree.c, I'm curious if
> we're hitting a false positive on the 5 minute jiffies overflow?

Hmmm...  Might be.  Does the patch below help?

							Thanx, Paul

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

rcu: Avoid spurious RCU CPU stall warnings

If a given CPU avoids the idle loop but also avoids starting a new
RCU grace period for a full minute, RCU can issue spurious RCU CPU
stall warnings.  This commit fixes this issue by adding a check for
ongoing grace period to avoid these spurious stall warnings.

Reported-by: Becky Bruce <bgillbruce@gmail.com>
Signed-off-by: Paul E. McKenney <paul.mckenney@linaro.org>
Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Reviewed-by: Josh Triplett <josh@joshtriplett.org>

diff --git a/kernel/rcutree.c b/kernel/rcutree.c
index 3d63d1c..aea3157 100644
--- a/kernel/rcutree.c
+++ b/kernel/rcutree.c
@@ -819,7 +819,8 @@ static void check_cpu_stall(struct rcu_state *rsp, struct rcu_data *rdp)
 	j = ACCESS_ONCE(jiffies);
 	js = ACCESS_ONCE(rsp->jiffies_stall);
 	rnp = rdp->mynode;
-	if ((ACCESS_ONCE(rnp->qsmask) & rdp->grpmask) && ULONG_CMP_GE(j, js)) {
+	if (rcu_gp_in_progress(rsp) &&
+	    (ACCESS_ONCE(rnp->qsmask) & rdp->grpmask) && ULONG_CMP_GE(j, js)) {
 
 		/* We haven't checked in, so go dump stack. */
 		print_cpu_stall(rsp);

Re: RCU lockup in the SMP idle thread, help...

[Linus Walleij]

On Thu, Sep 13, 2012 at 6:58 PM, Paul E. McKenney
<paulmck@linux.vnet.ibm.com> wrote:
> On Thu, Sep 13, 2012 at 09:49:14AM -0700, John Stultz wrote:
>> I saw this once as well testing the fix to Daniel's deep idle hang
>> issue (also on 32 bit).

John, what system was this? If it's not Snowball/ux500 we can atleast
conclude that
it's a generic bug, not machine-specific...

>> Really briefly looking at the code in rcutree.c, I'm curious if
>> we're hitting a false positive on the 5 minute jiffies overflow?
>
> Hmmm...  Might be.  Does the patch below help?

Sorry, nope, I get this:

root@ME:/
root@ME:/ INFO: rcu_preempt detected stalls on CPUs/tasks: { 0}
(detected by 1, t=29545 jiffies)
[<c0014710>] (unwind_backtrace+0x0/0xf8) from [<c00686fc>]
(rcu_check_callbacks+0x6e0/0x76c)
[<c00686fc>] (rcu_check_callbacks+0x6e0/0x76c) from [<c0029cbc>]
(update_process_times+0x38/0x4c)
[<c0029cbc>] (update_process_times+0x38/0x4c) from [<c0055088>]
(tick_sched_timer+0x80/0xe4)
[<c0055088>] (tick_sched_timer+0x80/0xe4) from [<c003c120>]
(__run_hrtimer.isra.18+0x44/0xd0)
[<c003c120>] (__run_hrtimer.isra.18+0x44/0xd0) from [<c003cae0>]
(hrtimer_interrupt+0x118/0x2b4)
[<c003cae0>] (hrtimer_interrupt+0x118/0x2b4) from [<c0013658>]
(twd_handler+0x30/0x44)
[<c0013658>] (twd_handler+0x30/0x44) from [<c00638c8>]
(handle_percpu_devid_irq+0x80/0xa0)
[<c00638c8>] (handle_percpu_devid_irq+0x80/0xa0) from [<c00603b8>]
(generic_handle_irq+0x20/0x30)
[<c00603b8>] (generic_handle_irq+0x20/0x30) from [<c000ef58>]
(handle_IRQ+0x4c/0xac)
[<c000ef58>] (handle_IRQ+0x4c/0xac) from [<c00084bc>] (gic_handle_irq+0x24/0x58)
[<c00084bc>] (gic_handle_irq+0x24/0x58) from [<c000dc80>] (__irq_svc+0x40/0x70)
Exception stack(0xcf865f88 to 0xcf865fd0)
5f80:                   00000020 c05c0a20 00000001 00000000 cf864000 cf864000
5fa0: c05dfe48 c02de0bc c05c3e90 412fc091 cf864000 00000000 01000000 cf865fd0
5fc0: c000f234 c000f238 60000013 ffffffff
[<c000dc80>] (__irq_svc+0x40/0x70) from [<c000f238>] (default_idle+0x28/0x30)
[<c000f238>] (default_idle+0x28/0x30) from [<c000f438>] (cpu_idle+0x98/0xe4)
[<c000f438>] (cpu_idle+0x98/0xe4) from [<002d3094>] (0x2d3094)
INFO: rcu_preempt detected stalls on CPUs/tasks: { 0} (detected by 1,
t=30029 jiffies)
[<c0014710>] (unwind_backtrace+0x0/0xf8) from [<c00686fc>]
(rcu_check_callbacks+0x6e0/0x76c)
[<c00686fc>] (rcu_check_callbacks+0x6e0/0x76c) from [<c0029cbc>]
(update_process_times+0x38/0x4c)
[<c0029cbc>] (update_process_times+0x38/0x4c) from [<c0055088>]
(tick_sched_timer+0x80/0xe4)
[<c0055088>] (tick_sched_timer+0x80/0xe4) from [<c003c120>]
(__run_hrtimer.isra.18+0x44/0xd0)
[<c003c120>] (__run_hrtimer.isra.18+0x44/0xd0) from [<c003cae0>]
(hrtimer_interrupt+0x118/0x2b4)
[<c003cae0>] (hrtimer_interrupt+0x118/0x2b4) from [<c0013658>]
(twd_handler+0x30/0x44)
[<c0013658>] (twd_handler+0x30/0x44) from [<c00638c8>]
(handle_percpu_devid_irq+0x80/0xa0)
[<c00638c8>] (handle_percpu_devid_irq+0x80/0xa0) from [<c00603b8>]
(generic_handle_irq+0x20/0x30)
[<c00603b8>] (generic_handle_irq+0x20/0x30) from [<c000ef58>]
(handle_IRQ+0x4c/0xac)
[<c000ef58>] (handle_IRQ+0x4c/0xac) from [<c00084bc>] (gic_handle_irq+0x24/0x58)
[<c00084bc>] (gic_handle_irq+0x24/0x58) from [<c000dc80>] (__irq_svc+0x40/0x70)
Exception stack(0xcf865f88 to 0xcf865fd0)
5f80:                   00000020 c05c0a20 00000001 00000000 cf864000 cf864000
5fa0: c05dfe48 c02de0bc c05c3e90 412fc091 cf864000 00000000 01000000 cf865fd0
5fc0: c000f234 c000f238 60000013 ffffffff
[<c000dc80>] (__irq_svc+0x40/0x70) from [<c000f238>] (default_idle+0x28/0x30)
[<c000f238>] (default_idle+0x28/0x30) from [<c000f438>] (cpu_idle+0x98/0xe4)
[<c000f438>] (cpu_idle+0x98/0xe4) from [<002d3094>] (0x2d3094)

I'm all confused ..

Yours,
Linus Walleij

Re: RCU lockup in the SMP idle thread, help...

[Paul E. McKenney]

On Fri, Sep 14, 2012 at 09:27:32AM +0200, Linus Walleij wrote:
> On Thu, Sep 13, 2012 at 6:58 PM, Paul E. McKenney
> <paulmck@linux.vnet.ibm.com> wrote:
> > On Thu, Sep 13, 2012 at 09:49:14AM -0700, John Stultz wrote:
> >> I saw this once as well testing the fix to Daniel's deep idle hang
> >> issue (also on 32 bit).
> 
> John, what system was this? If it's not Snowball/ux500 we can atleast
> conclude that
> it's a generic bug, not machine-specific...
> 
> >> Really briefly looking at the code in rcutree.c, I'm curious if
> >> we're hitting a false positive on the 5 minute jiffies overflow?
> >
> > Hmmm...  Might be.  Does the patch below help?
> 
> Sorry, nope, I get this:

Could you please try reproducing with CONFIG_RCU_CPU_STALL_INFO=y?

							Thanx, Paul

> root@ME:/
> root@ME:/ INFO: rcu_preempt detected stalls on CPUs/tasks: { 0}
> (detected by 1, t=29545 jiffies)
> [<c0014710>] (unwind_backtrace+0x0/0xf8) from [<c00686fc>]
> (rcu_check_callbacks+0x6e0/0x76c)
> [<c00686fc>] (rcu_check_callbacks+0x6e0/0x76c) from [<c0029cbc>]
> (update_process_times+0x38/0x4c)
> [<c0029cbc>] (update_process_times+0x38/0x4c) from [<c0055088>]
> (tick_sched_timer+0x80/0xe4)
> [<c0055088>] (tick_sched_timer+0x80/0xe4) from [<c003c120>]
> (__run_hrtimer.isra.18+0x44/0xd0)
> [<c003c120>] (__run_hrtimer.isra.18+0x44/0xd0) from [<c003cae0>]
> (hrtimer_interrupt+0x118/0x2b4)
> [<c003cae0>] (hrtimer_interrupt+0x118/0x2b4) from [<c0013658>]
> (twd_handler+0x30/0x44)
> [<c0013658>] (twd_handler+0x30/0x44) from [<c00638c8>]
> (handle_percpu_devid_irq+0x80/0xa0)
> [<c00638c8>] (handle_percpu_devid_irq+0x80/0xa0) from [<c00603b8>]
> (generic_handle_irq+0x20/0x30)
> [<c00603b8>] (generic_handle_irq+0x20/0x30) from [<c000ef58>]
> (handle_IRQ+0x4c/0xac)
> [<c000ef58>] (handle_IRQ+0x4c/0xac) from [<c00084bc>] (gic_handle_irq+0x24/0x58)
> [<c00084bc>] (gic_handle_irq+0x24/0x58) from [<c000dc80>] (__irq_svc+0x40/0x70)
> Exception stack(0xcf865f88 to 0xcf865fd0)
> 5f80:                   00000020 c05c0a20 00000001 00000000 cf864000 cf864000
> 5fa0: c05dfe48 c02de0bc c05c3e90 412fc091 cf864000 00000000 01000000 cf865fd0
> 5fc0: c000f234 c000f238 60000013 ffffffff
> [<c000dc80>] (__irq_svc+0x40/0x70) from [<c000f238>] (default_idle+0x28/0x30)
> [<c000f238>] (default_idle+0x28/0x30) from [<c000f438>] (cpu_idle+0x98/0xe4)
> [<c000f438>] (cpu_idle+0x98/0xe4) from [<002d3094>] (0x2d3094)
> INFO: rcu_preempt detected stalls on CPUs/tasks: { 0} (detected by 1,
> t=30029 jiffies)
> [<c0014710>] (unwind_backtrace+0x0/0xf8) from [<c00686fc>]
> (rcu_check_callbacks+0x6e0/0x76c)
> [<c00686fc>] (rcu_check_callbacks+0x6e0/0x76c) from [<c0029cbc>]
> (update_process_times+0x38/0x4c)
> [<c0029cbc>] (update_process_times+0x38/0x4c) from [<c0055088>]
> (tick_sched_timer+0x80/0xe4)
> [<c0055088>] (tick_sched_timer+0x80/0xe4) from [<c003c120>]
> (__run_hrtimer.isra.18+0x44/0xd0)
> [<c003c120>] (__run_hrtimer.isra.18+0x44/0xd0) from [<c003cae0>]
> (hrtimer_interrupt+0x118/0x2b4)
> [<c003cae0>] (hrtimer_interrupt+0x118/0x2b4) from [<c0013658>]
> (twd_handler+0x30/0x44)
> [<c0013658>] (twd_handler+0x30/0x44) from [<c00638c8>]
> (handle_percpu_devid_irq+0x80/0xa0)
> [<c00638c8>] (handle_percpu_devid_irq+0x80/0xa0) from [<c00603b8>]
> (generic_handle_irq+0x20/0x30)
> [<c00603b8>] (generic_handle_irq+0x20/0x30) from [<c000ef58>]
> (handle_IRQ+0x4c/0xac)
> [<c000ef58>] (handle_IRQ+0x4c/0xac) from [<c00084bc>] (gic_handle_irq+0x24/0x58)
> [<c00084bc>] (gic_handle_irq+0x24/0x58) from [<c000dc80>] (__irq_svc+0x40/0x70)
> Exception stack(0xcf865f88 to 0xcf865fd0)
> 5f80:                   00000020 c05c0a20 00000001 00000000 cf864000 cf864000
> 5fa0: c05dfe48 c02de0bc c05c3e90 412fc091 cf864000 00000000 01000000 cf865fd0
> 5fc0: c000f234 c000f238 60000013 ffffffff
> [<c000dc80>] (__irq_svc+0x40/0x70) from [<c000f238>] (default_idle+0x28/0x30)
> [<c000f238>] (default_idle+0x28/0x30) from [<c000f438>] (cpu_idle+0x98/0xe4)
> [<c000f438>] (cpu_idle+0x98/0xe4) from [<002d3094>] (0x2d3094)
> 
> I'm all confused ..
> 
> Yours,
> Linus Walleij
> 

Re: RCU lockup in the SMP idle thread, help...

[Linus Walleij]

On Fri, Sep 14, 2012 at 7:53 PM, Paul E. McKenney
<paulmck@linux.vnet.ibm.com> wrote:

> Could you please try reproducing with CONFIG_RCU_CPU_STALL_INFO=y?

Yep: looks like this:

INFO: rcu_preempt detected stalls on CPUs/tasks:
        0: (0 ticks this GP) idle=458/0/0
        (detected by 1, t=29904 jiffies)
[<c0014710>] (unwind_backtrace+0x0/0xf8) from [<c00687dc>]
(rcu_check_callbacks+0x6f8/0x730)
[<c00687dc>] (rcu_check_callbacks+0x6f8/0x730) from [<c0029cbc>]
(update_process_times+0x38/0x4c)
[<c0029cbc>] (update_process_times+0x38/0x4c) from [<c0055088>]
(tick_sched_timer+0x80/0xe4)
[<c0055088>] (tick_sched_timer+0x80/0xe4) from [<c003c120>]
(__run_hrtimer.isra.18+0x44/0xd0)
[<c003c120>] (__run_hrtimer.isra.18+0x44/0xd0) from [<c003cae0>]
(hrtimer_interrupt+0x118/0x2b4)
[<c003cae0>] (hrtimer_interrupt+0x118/0x2b4) from [<c0013658>]
(twd_handler+0x30/0x44)
[<c0013658>] (twd_handler+0x30/0x44) from [<c00638c8>]
(handle_percpu_devid_irq+0x80/0xa0)
[<c00638c8>] (handle_percpu_devid_irq+0x80/0xa0) from [<c00603b8>]
(generic_handle_irq+0x20/0x30)
[<c00603b8>] (generic_handle_irq+0x20/0x30) from [<c000ef58>]
(handle_IRQ+0x4c/0xac)
[<c000ef58>] (handle_IRQ+0x4c/0xac) from [<c00084bc>] (gic_handle_irq+0x24/0x58)
[<c00084bc>] (gic_handle_irq+0x24/0x58) from [<c000dc80>] (__irq_svc+0x40/0x70)
Exception stack(0xcf865f88 to 0xcf865fd0)
5f80:                   00000020 c05c0a20 00000001 00000000 cf864000 cf864000
5fa0: c05dfe48 c02de0b4 c05c3e90 412fc091 cf864000 00000000 01000000 cf865fd0
5fc0: c000f234 c000f238 60000013 ffffffff
[<c000dc80>] (__irq_svc+0x40/0x70) from [<c000f238>] (default_idle+0x28/0x30)
[<c000f238>] (default_idle+0x28/0x30) from [<c000f438>] (cpu_idle+0x98/0xe4)
[<c000f438>] (cpu_idle+0x98/0xe4) from [<002d3114>] (0x2d3114)

Yours,
Linus Walleij

Re: RCU lockup in the SMP idle thread, help...

[Paul E. McKenney]

On Mon, Sep 17, 2012 at 11:10:30AM +0200, Linus Walleij wrote:
> On Fri, Sep 14, 2012 at 7:53 PM, Paul E. McKenney
> <paulmck@linux.vnet.ibm.com> wrote:
> 
> > Could you please try reproducing with CONFIG_RCU_CPU_STALL_INFO=y?
> 
> Yep: looks like this:
> 
> INFO: rcu_preempt detected stalls on CPUs/tasks:
>         0: (0 ticks this GP) idle=458/0/0
>         (detected by 1, t=29904 jiffies)
> [<c0014710>] (unwind_backtrace+0x0/0xf8) from [<c00687dc>]
> (rcu_check_callbacks+0x6f8/0x730)
> [<c00687dc>] (rcu_check_callbacks+0x6f8/0x730) from [<c0029cbc>]
> (update_process_times+0x38/0x4c)
> [<c0029cbc>] (update_process_times+0x38/0x4c) from [<c0055088>]
> (tick_sched_timer+0x80/0xe4)
> [<c0055088>] (tick_sched_timer+0x80/0xe4) from [<c003c120>]
> (__run_hrtimer.isra.18+0x44/0xd0)
> [<c003c120>] (__run_hrtimer.isra.18+0x44/0xd0) from [<c003cae0>]
> (hrtimer_interrupt+0x118/0x2b4)
> [<c003cae0>] (hrtimer_interrupt+0x118/0x2b4) from [<c0013658>]
> (twd_handler+0x30/0x44)
> [<c0013658>] (twd_handler+0x30/0x44) from [<c00638c8>]
> (handle_percpu_devid_irq+0x80/0xa0)
> [<c00638c8>] (handle_percpu_devid_irq+0x80/0xa0) from [<c00603b8>]
> (generic_handle_irq+0x20/0x30)
> [<c00603b8>] (generic_handle_irq+0x20/0x30) from [<c000ef58>]
> (handle_IRQ+0x4c/0xac)
> [<c000ef58>] (handle_IRQ+0x4c/0xac) from [<c00084bc>] (gic_handle_irq+0x24/0x58)
> [<c00084bc>] (gic_handle_irq+0x24/0x58) from [<c000dc80>] (__irq_svc+0x40/0x70)
> Exception stack(0xcf865f88 to 0xcf865fd0)
> 5f80:                   00000020 c05c0a20 00000001 00000000 cf864000 cf864000
> 5fa0: c05dfe48 c02de0b4 c05c3e90 412fc091 cf864000 00000000 01000000 cf865fd0
> 5fc0: c000f234 c000f238 60000013 ffffffff
> [<c000dc80>] (__irq_svc+0x40/0x70) from [<c000f238>] (default_idle+0x28/0x30)
> [<c000f238>] (default_idle+0x28/0x30) from [<c000f438>] (cpu_idle+0x98/0xe4)
> [<c000f438>] (cpu_idle+0x98/0xe4) from [<002d3114>] (0x2d3114)

Ah!!!  If I understand correctly, ARM does not implement the NMI-based
trigger_all_cpu_backtrace() facility that RCU uses to get stack backtraces
out of all CPUs.  In this case, trigger_all_cpu_backtrace() returns
failure, so RCU falls back to dumping a stack trace of the current CPU,
which in this case is CPU 1.  Unfortunately, this stack backtrace says
nothing about the state of CPU 0, which is the one that is stalling.

So, yes, CPU 1 was interrupted out of idle, but it was CPU 0 that was
responsible for the stall.

I could hack together something that used IPIs to get the backtrace, but
this is unlikely to work.  The thing is that RCU waits an additional
two jiffies before allowing a CPU to complain about some other CPU's
stall.  This means that unless CPU 0 halted the scheduling-clock
interrupt, the most likely failure mode is that CPU 0 was spinning
with interrupts disabled, which would render IPIs ineffective.  Which is
why trigger_all_cpu_backtrace() uses NMIs.

Any thoughts on the feasibility of implementing NMI-based stack backtraces
for ARM?

In the meantime, a crude fallback is for the CPU that detected the stall
to trace the stack of the task running on the other CPU.  See below for
a crude (and untested) patch.

							Thanx, Paul

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

rcu: Print remote CPU's stacks in stall warnings

The RCU CPU stall warnings rely on trigger_all_cpu_backtrace() to
do NMI-based dump of the stack traces of all CPUs.  Unfortunately, a
number of architectures do not implement trigger_all_cpu_backtrace(), in
which case RCU falls back to just dumping the stack of the running CPU.
This is unhelpful in the case where the running CPU has detected that
some other CPU has stalled.

This commit therefore makes the running CPU dump the stacks of the
tasks running on the stalled CPUs.

Not-yet-signed-off-by: Paul E. McKenney <paul.mckenney@linaro.org>
Not-yet-signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

diff --git a/include/linux/sched.h b/include/linux/sched.h
index cdaeeff..02df81a 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -149,6 +149,8 @@ extern void update_cpu_load_nohz(void);
 
 extern unsigned long get_parent_ip(unsigned long addr);
 
+extern void dump_cpu_task(int cpu);
+
 struct seq_file;
 struct cfs_rq;
 struct task_group;
diff --git a/kernel/rcutree.c b/kernel/rcutree.c
index 6eff63d..ea42da1 100644
--- a/kernel/rcutree.c
+++ b/kernel/rcutree.c
@@ -851,6 +851,29 @@ static void record_gp_stall_check_time(struct rcu_state *rsp)
 	rsp->jiffies_stall = jiffies + jiffies_till_stall_check();
 }
 
+/*
+ * Dump stacks of all tasks running on stalled CPUs.  This is a fallback
+ * for architectures that do not implement trigger_all_cpu_backtrace().
+ * The NMI-triggered stack traces are more accurate because they are
+ * printed by the target CPU.
+ */
+static void rcu_dump_cpu_stacks(struct rcu_state *rsp)
+{
+	int cpu;
+	unsigned long flags;
+	struct rcu_node *rnp;
+
+	rcu_for_each_leaf_node(rsp, rnp) {
+		raw_spin_lock_irqsave(&rnp->lock, flags);
+		if (rnp->qsmask != 0) {
+			for (cpu = 0; cpu <= rnp->grphi - rnp->grplo; cpu++)
+				if (rnp->qsmask & (1UL << cpu))
+					dump_cpu_task(rnp->grplo + cpu);
+		}
+		raw_spin_unlock_irqrestore(&rnp->lock, flags);
+	}
+}
+
 static void print_other_cpu_stall(struct rcu_state *rsp)
 {
 	int cpu;
@@ -907,7 +930,7 @@ static void print_other_cpu_stall(struct rcu_state *rsp)
 	if (ndetected == 0)
 		printk(KERN_ERR "INFO: Stall ended before state dump start\n");
 	else if (!trigger_all_cpu_backtrace())
-		dump_stack();
+		rcu_dump_cpu_stacks(rsp);
 
 	/* Complain about tasks blocking the grace period. */
 
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index ce685da..b5c27a7 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -8610,3 +8610,9 @@ struct cgroup_subsys cpuacct_subsys = {
 	.base_cftypes = files,
 };
 #endif	/* CONFIG_CGROUP_CPUACCT */
+
+void dump_cpu_task(int cpu)
+{
+	pr_info("Task dump for CPU %d:\n", cpu);
+	sched_show_task(cpu_curr(cpu));
+}

Re: RCU lockup in the SMP idle thread, help...

[Linus Walleij]

On Thu, Sep 20, 2012 at 2:03 AM, Paul E. McKenney
<paulmck@linux.vnet.ibm.com> wrote:

> Any thoughts on the feasibility of implementing NMI-based stack backtraces
> for ARM?

Nico's department, so let's page him.

In IIRC ux500 all NMIs are reserved for the secure world, so it's
basically a no can do. :-(

And I'm told this is the case in some other ARMv7 arches too.

> In the meantime, a crude fallback is for the CPU that detected the stall
> to trace the stack of the task running on the other CPU.  See below for
> a crude (and untested) patch.

I'll test!

Thanks,
Linus Walleij

Re: RCU lockup in the SMP idle thread, help...

[Nicolas Pitre]

On Thu, 20 Sep 2012, Linus Walleij wrote:

> On Thu, Sep 20, 2012 at 2:03 AM, Paul E. McKenney
> <paulmck@linux.vnet.ibm.com> wrote:
> 
> > Any thoughts on the feasibility of implementing NMI-based stack backtraces
> > for ARM?
> 
> Nico's department, so let's page him.

That _could_ be done, at least in theory, with some restrictions.  

However in practice ...

> In IIRC ux500 all NMIs are reserved for the secure world, so it's
> basically a no can do. :-(

That's the main issue here: not all platforms allow FIQs ( a FIQ is the 
closest to a NMI on ARM) to be available to the operating system.

However, for where this is possible, there is a patch series from Anton 
Vorontsov implementing FIQ based KGDB support which might be useful 
here.


Nicolas

Re: RCU lockup in the SMP idle thread, help...

[Linus Walleij]

On Thu, Sep 20, 2012 at 2:03 AM, Paul E. McKenney
<paulmck@linux.vnet.ibm.com> wrote:

> In the meantime, a crude fallback is for the CPU that detected the stall
> to trace the stack of the task running on the other CPU.  See below for
> a crude (and untested) patch.

OK now I get this:

 INFO: rcu_preempt detected stalls on CPUs/tasks: { 0} (detected by 1,
t=29508 jiffies)
Task dump for CPU 0:
swapper/0       R running      0     0      0 0x00000000
[<c02da614>] (__schedule+0x238/0x52c) from [<c000f238>] (default_idle+0x28/0x30)
[<c000f238>] (default_idle+0x28/0x30) from [<ffffffff>] (0xffffffff)
INFO: rcu_preempt detected stalls on CPUs/tasks: { 0} (detected by 1,
t=29851 jiffies)
Task dump for CPU 0:
swapper/0       R running      0     0      0 0x00000000
[<c02da614>] (__schedule+0x238/0x52c) from [<c000f238>] (default_idle+0x28/0x30)
[<c000f238>] (default_idle+0x28/0x30) from [<ffffffff>] (0xffffffff)

So the swapper thread is the culprit?
Hm, I'm not very smart with this no...

Yours,
Linus Walleij

Re: RCU lockup in the SMP idle thread, help...

[Paul E. McKenney]

On Thu, Sep 20, 2012 at 11:07:37AM +0200, Linus Walleij wrote:
> On Thu, Sep 20, 2012 at 2:03 AM, Paul E. McKenney
> <paulmck@linux.vnet.ibm.com> wrote:
> 
> > In the meantime, a crude fallback is for the CPU that detected the stall
> > to trace the stack of the task running on the other CPU.  See below for
> > a crude (and untested) patch.
> 
> OK now I get this:
> 
>  INFO: rcu_preempt detected stalls on CPUs/tasks: { 0} (detected by 1,
> t=29508 jiffies)
> Task dump for CPU 0:
> swapper/0       R running      0     0      0 0x00000000
> [<c02da614>] (__schedule+0x238/0x52c) from [<c000f238>] (default_idle+0x28/0x30)
> [<c000f238>] (default_idle+0x28/0x30) from [<ffffffff>] (0xffffffff)
> INFO: rcu_preempt detected stalls on CPUs/tasks: { 0} (detected by 1,
> t=29851 jiffies)
> Task dump for CPU 0:
> swapper/0       R running      0     0      0 0x00000000
> [<c02da614>] (__schedule+0x238/0x52c) from [<c000f238>] (default_idle+0x28/0x30)
> [<c000f238>] (default_idle+0x28/0x30) from [<ffffffff>] (0xffffffff)
> 
> So the swapper thread is the culprit?
> Hm, I'm not very smart with this no...

Can we convince ARM to dump the stack of the swapper thread in this case?
That would get us valuable information.

							Thanx, Paul