Running 3.9-rc7-ish, tripped the following (also being seen in FC19
alpha) on ppc64:
[ 117.026196] =========================================================
[ 117.026216] [ INFO: possible irq lock inversion dependency detected ]
[ 117.026238] 3.9.0-rc7+ #8 Not tainted
[ 117.026251] ---------------------------------------------------------
[ 117.026271] swapper/7/0 just changed the state of lock:
[ 117.026286] (&(&tp->lock)->rlock){+.-...}, at: [<c00000000064effc>] .tg3_timer+0x9c/0x10f0
[ 117.026334] but this lock took another, SOFTIRQ-unsafe lock in the past:
[ 117.026353] (devtree_lock){+.+...}
and interrupts could create inverse lock ordering between them.
[ 117.026389]
other info that might help us debug this:
[ 117.026409] Chain exists of:
&(&tp->lock)->rlock --> pci_lock --> devtree_lock
[ 117.026452] Possible interrupt unsafe locking scenario:
[ 117.026472] CPU0 CPU1
[ 117.026488] ---- ----
[ 117.026503] lock(devtree_lock);
[ 117.026521] local_irq_disable();
[ 117.026540] lock(&(&tp->lock)->rlock);
[ 117.026567] lock(pci_lock);
[ 117.026591] <Interrupt>
[ 117.026600] lock(&(&tp->lock)->rlock);
[ 117.026621]
*** DEADLOCK ***
[ 117.026644] 1 lock held by swapper/7/0:
[ 117.026657] #0: ((&tp->timer)){+.-...}, at: [<c0000000000bbc50>] .call_timer_fn+0x0/0x3e0
[ 117.026698]
the shortest dependencies between 2nd lock and 1st lock:
[ 117.026722] -> (devtree_lock){+.+...} ops: 13864154431488 {
[ 117.026758] HARDIRQ-ON-W at:
[ 117.026772] SOFTIRQ-ON-W at:
[ 117.026786] INITIAL USE at:
[ 117.026799] }
[ 117.026809] ... key at: [<c00000000159b208>] devtree_lock+0x18/0x48
[ 117.026835] ... acquired at:
[ 117.026857] -> (pci_lock){......} ops: 3955664879616 {
[ 117.026893] INITIAL USE at:
[ 117.026906] }
[ 117.026915] ... key at: [<c00000000157abe8>] pci_lock+0x18/0x48
[ 117.026942] ... acquired at:
[ 117.026963] -> (&(&tp->lock)->rlock){+.-...} ops: 154618822656 {
[ 117.027001] HARDIRQ-ON-W at:
[ 117.027015] IN-SOFTIRQ-W at:
[ 117.027029] INITIAL USE at:
[ 117.027042] }
[ 117.027051] ... key at: [<c0000000023a0311>] __key.48770+0x0/0x8
[ 117.027078] ... acquired at:
[ 117.027100]
stack backtrace:
[ 117.027116] Call Trace:
[ 117.027129] [c0000003a7c7ad10] [c000000000016ee0] .show_stack+0xd0/0x1f0 (unreliable)
[ 117.027161] [c0000003a7c7ade0] [c000000000137d78] .print_irq_inversion_bug+0x298/0x2f0
[ 117.027189] [c0000003a7c7ae80] [c000000000137e70] .check_usage_forwards+0xa0/0x150
[ 117.027217] [c0000003a7c7af70] [c000000000138b68] .mark_lock+0x258/0x7b0
[ 117.027242] [c0000003a7c7b030] [c0000000001396f8] .__lock_acquire+0x638/0x1c20
[ 117.027270] [c0000003a7c7b1b0] [c00000000013b480] .lock_acquire+0xb0/0x250
[ 117.027296] [c0000003a7c7b290] [c00000000093a1cc] ._raw_spin_lock+0x5c/0xc0
[ 117.027321] [c0000003a7c7b320] [c00000000064effc] .tg3_timer+0x9c/0x10f0
[ 117.027345] [c0000003a7c7b3d0] [c0000000000bbd0c] .call_timer_fn+0xbc/0x3e0
[ 117.027369] [c0000003a7c7b4b0] [c0000000000bc328] .run_timer_softirq+0x2f8/0x440
[ 117.027398] [c0000003a7c7b5c0] [c0000000000afef8] .__do_softirq+0x1b8/0x540
[ 117.027423] [c0000003a7c7b6f0] [c0000000000b04e8] .irq_exit+0xe8/0x100
[ 117.027448] [c0000003a7c7b770] [c000000000020464] .timer_interrupt+0x174/0x510
[ 117.027477] [c0000003a7c7b830] [c0000000000024f4] decrementer_common+0x174/0x180
[ 117.027509] --- Exception: 901 at .plpar_hcall_norets+0x84/0xd4
LR = .check_and_cede_processor+0x48/0x80
[ 117.027544] [c0000003a7c7bb20] [c000000000085168] .check_and_cede_processor+0x18/0x80 (unreliable)
[ 117.027577] [c0000003a7c7bb90] [c000000000085258] .dedicated_cede_loop+0x88/0x150
[ 117.027606] [c0000003a7c7bc50] [c00000000075808c] .cpuidle_enter+0x2c/0x40
[ 117.027632] [c0000003a7c7bcc0] [c0000000007589bc] .cpuidle_idle_call+0xfc/0x4e0
[ 117.027660] [c0000003a7c7bd70] [c000000000074be8] .pSeries_idle+0x18/0x40
[ 117.027685] [c0000003a7c7bde0] [c000000000018ec0] .cpu_idle+0x180/0x360
[ 117.027711] [c0000003a7c7bea0] [c00000000095391c] .start_secondary+0x534/0x53c
[ 117.027739] [c0000003a7c7bf90] [c0000000000097fc] .start_secondary_prolog+0x10/0x14
On 04/19/2013 02:01 PM, Nishanth Aravamudan wrote:
> Running 3.9-rc7-ish, tripped the following (also being seen in FC19
> alpha) on ppc64:
>
> [ 117.026196] =========================================================
> [ 117.026216] [ INFO: possible irq lock inversion dependency detected ]
> [ 117.026238] 3.9.0-rc7+ #8 Not tainted
> [ 117.026251] ---------------------------------------------------------
> [ 117.026271] swapper/7/0 just changed the state of lock:
> [ 117.026286] (&(&tp->lock)->rlock){+.-...}, at: [<c00000000064effc>] .tg3_timer+0x9c/0x10f0
> [ 117.026334] but this lock took another, SOFTIRQ-unsafe lock in the past:
> [ 117.026353] (devtree_lock){+.+...}
>
> and interrupts could create inverse lock ordering between them.
>
> [ 117.026389]
> other info that might help us debug this:
> [ 117.026409] Chain exists of:
> &(&tp->lock)->rlock --> pci_lock --> devtree_lock
>
> [ 117.026452] Possible interrupt unsafe locking scenario:
>
> [ 117.026472] CPU0 CPU1
> [ 117.026488] ---- ----
> [ 117.026503] lock(devtree_lock);
> [ 117.026521] local_irq_disable();
> [ 117.026540] lock(&(&tp->lock)->rlock);
> [ 117.026567] lock(pci_lock);
> [ 117.026591] <Interrupt>
> [ 117.026600] lock(&(&tp->lock)->rlock);
> [ 117.026621]
> *** DEADLOCK ***
>
> [ 117.026644] 1 lock held by swapper/7/0:
> [ 117.026657] #0: ((&tp->timer)){+.-...}, at: [<c0000000000bbc50>] .call_timer_fn+0x0/0x3e0
> [ 117.026698]
> the shortest dependencies between 2nd lock and 1st lock:
> [ 117.026722] -> (devtree_lock){+.+...} ops: 13864154431488 {
> [ 117.026758] HARDIRQ-ON-W at:
> [ 117.026772] SOFTIRQ-ON-W at:
> [ 117.026786] INITIAL USE at:
> [ 117.026799] }
> [ 117.026809] ... key at: [<c00000000159b208>] devtree_lock+0x18/0x48
> [ 117.026835] ... acquired at:
>
> [ 117.026857] -> (pci_lock){......} ops: 3955664879616 {
> [ 117.026893] INITIAL USE at:
> [ 117.026906] }
> [ 117.026915] ... key at: [<c00000000157abe8>] pci_lock+0x18/0x48
> [ 117.026942] ... acquired at:
>
> [ 117.026963] -> (&(&tp->lock)->rlock){+.-...} ops: 154618822656 {
> [ 117.027001] HARDIRQ-ON-W at:
> [ 117.027015] IN-SOFTIRQ-W at:
> [ 117.027029] INITIAL USE at:
> [ 117.027042] }
> [ 117.027051] ... key at: [<c0000000023a0311>] __key.48770+0x0/0x8
> [ 117.027078] ... acquired at:
>
> [ 117.027100]
> stack backtrace:
> [ 117.027116] Call Trace:
> [ 117.027129] [c0000003a7c7ad10] [c000000000016ee0] .show_stack+0xd0/0x1f0 (unreliable)
> [ 117.027161] [c0000003a7c7ade0] [c000000000137d78] .print_irq_inversion_bug+0x298/0x2f0
> [ 117.027189] [c0000003a7c7ae80] [c000000000137e70] .check_usage_forwards+0xa0/0x150
> [ 117.027217] [c0000003a7c7af70] [c000000000138b68] .mark_lock+0x258/0x7b0
> [ 117.027242] [c0000003a7c7b030] [c0000000001396f8] .__lock_acquire+0x638/0x1c20
> [ 117.027270] [c0000003a7c7b1b0] [c00000000013b480] .lock_acquire+0xb0/0x250
> [ 117.027296] [c0000003a7c7b290] [c00000000093a1cc] ._raw_spin_lock+0x5c/0xc0
> [ 117.027321] [c0000003a7c7b320] [c00000000064effc] .tg3_timer+0x9c/0x10f0
> [ 117.027345] [c0000003a7c7b3d0] [c0000000000bbd0c] .call_timer_fn+0xbc/0x3e0
> [ 117.027369] [c0000003a7c7b4b0] [c0000000000bc328] .run_timer_softirq+0x2f8/0x440
> [ 117.027398] [c0000003a7c7b5c0] [c0000000000afef8] .__do_softirq+0x1b8/0x540
> [ 117.027423] [c0000003a7c7b6f0] [c0000000000b04e8] .irq_exit+0xe8/0x100
> [ 117.027448] [c0000003a7c7b770] [c000000000020464] .timer_interrupt+0x174/0x510
> [ 117.027477] [c0000003a7c7b830] [c0000000000024f4] decrementer_common+0x174/0x180
> [ 117.027509] --- Exception: 901 at .plpar_hcall_norets+0x84/0xd4
> LR = .check_and_cede_processor+0x48/0x80
> [ 117.027544] [c0000003a7c7bb20] [c000000000085168] .check_and_cede_processor+0x18/0x80 (unreliable)
> [ 117.027577] [c0000003a7c7bb90] [c000000000085258] .dedicated_cede_loop+0x88/0x150
> [ 117.027606] [c0000003a7c7bc50] [c00000000075808c] .cpuidle_enter+0x2c/0x40
> [ 117.027632] [c0000003a7c7bcc0] [c0000000007589bc] .cpuidle_idle_call+0xfc/0x4e0
> [ 117.027660] [c0000003a7c7bd70] [c000000000074be8] .pSeries_idle+0x18/0x40
> [ 117.027685] [c0000003a7c7bde0] [c000000000018ec0] .cpu_idle+0x180/0x360
> [ 117.027711] [c0000003a7c7bea0] [c00000000095391c] .start_secondary+0x534/0x53c
> [ 117.027739] [c0000003a7c7bf90] [c0000000000097fc] .start_secondary_prolog+0x10/0x14
>
It might be related to this commit. Can you revert and try it.
commit d6d3c4e656513dcea61ce900f0ecb9ca820ee7cd
Author: Thomas Gleixner <[email protected]>
Date: Wed Feb 6 15:30:56 2013 -0500
OF: convert devtree lock from rw_lock to raw spinlock
With the locking cleanup in place (from "OF: Fixup resursive
locking code paths"), we can now do the conversion from the
rw_lock to a raw spinlock as required for preempt-rt.
The previous cleanup and this conversion were originally
separate since they predated when mainline got raw spinlock (in
commit c2f21ce2e31286a "locking: Implement new raw_spinlock").
So, at that point in time, the cleanup was considered plausible
for mainline, but not this conversion. In any case, we've kept
them separate as it makes for easier review and better bisection.
Signed-off-by: Thomas Gleixner <[email protected]>
[PG: taken from preempt-rt, update subject & add a commit log]
Signed-off-by: Paul Gortmaker <[email protected]>
Signed-off-by: Rob Herring <[email protected]>
Hi Rob,
On 19.04.2013 [14:23:21 -0500], Rob Herring wrote:
> On 04/19/2013 02:01 PM, Nishanth Aravamudan wrote:
> > Running 3.9-rc7-ish, tripped the following (also being seen in FC19
> > alpha) on ppc64:
> >
> > [ 117.026196] =========================================================
> > [ 117.026216] [ INFO: possible irq lock inversion dependency detected ]
> > [ 117.026238] 3.9.0-rc7+ #8 Not tainted
> > [ 117.026251] ---------------------------------------------------------
> > [ 117.026271] swapper/7/0 just changed the state of lock:
> > [ 117.026286] (&(&tp->lock)->rlock){+.-...}, at: [<c00000000064effc>] .tg3_timer+0x9c/0x10f0
> > [ 117.026334] but this lock took another, SOFTIRQ-unsafe lock in the past:
> > [ 117.026353] (devtree_lock){+.+...}
> >
> > and interrupts could create inverse lock ordering between them.
> >
> > [ 117.026389]
> > other info that might help us debug this:
> > [ 117.026409] Chain exists of:
> > &(&tp->lock)->rlock --> pci_lock --> devtree_lock
> >
> > [ 117.026452] Possible interrupt unsafe locking scenario:
> >
> > [ 117.026472] CPU0 CPU1
> > [ 117.026488] ---- ----
> > [ 117.026503] lock(devtree_lock);
> > [ 117.026521] local_irq_disable();
> > [ 117.026540] lock(&(&tp->lock)->rlock);
> > [ 117.026567] lock(pci_lock);
> > [ 117.026591] <Interrupt>
> > [ 117.026600] lock(&(&tp->lock)->rlock);
> > [ 117.026621]
> > *** DEADLOCK ***
> >
> > [ 117.026644] 1 lock held by swapper/7/0:
> > [ 117.026657] #0: ((&tp->timer)){+.-...}, at: [<c0000000000bbc50>] .call_timer_fn+0x0/0x3e0
> > [ 117.026698]
> > the shortest dependencies between 2nd lock and 1st lock:
> > [ 117.026722] -> (devtree_lock){+.+...} ops: 13864154431488 {
> > [ 117.026758] HARDIRQ-ON-W at:
> > [ 117.026772] SOFTIRQ-ON-W at:
> > [ 117.026786] INITIAL USE at:
> > [ 117.026799] }
> > [ 117.026809] ... key at: [<c00000000159b208>] devtree_lock+0x18/0x48
> > [ 117.026835] ... acquired at:
> >
> > [ 117.026857] -> (pci_lock){......} ops: 3955664879616 {
> > [ 117.026893] INITIAL USE at:
> > [ 117.026906] }
> > [ 117.026915] ... key at: [<c00000000157abe8>] pci_lock+0x18/0x48
> > [ 117.026942] ... acquired at:
> >
> > [ 117.026963] -> (&(&tp->lock)->rlock){+.-...} ops: 154618822656 {
> > [ 117.027001] HARDIRQ-ON-W at:
> > [ 117.027015] IN-SOFTIRQ-W at:
> > [ 117.027029] INITIAL USE at:
> > [ 117.027042] }
> > [ 117.027051] ... key at: [<c0000000023a0311>] __key.48770+0x0/0x8
> > [ 117.027078] ... acquired at:
> >
> > [ 117.027100]
> > stack backtrace:
> > [ 117.027116] Call Trace:
> > [ 117.027129] [c0000003a7c7ad10] [c000000000016ee0] .show_stack+0xd0/0x1f0 (unreliable)
> > [ 117.027161] [c0000003a7c7ade0] [c000000000137d78] .print_irq_inversion_bug+0x298/0x2f0
> > [ 117.027189] [c0000003a7c7ae80] [c000000000137e70] .check_usage_forwards+0xa0/0x150
> > [ 117.027217] [c0000003a7c7af70] [c000000000138b68] .mark_lock+0x258/0x7b0
> > [ 117.027242] [c0000003a7c7b030] [c0000000001396f8] .__lock_acquire+0x638/0x1c20
> > [ 117.027270] [c0000003a7c7b1b0] [c00000000013b480] .lock_acquire+0xb0/0x250
> > [ 117.027296] [c0000003a7c7b290] [c00000000093a1cc] ._raw_spin_lock+0x5c/0xc0
> > [ 117.027321] [c0000003a7c7b320] [c00000000064effc] .tg3_timer+0x9c/0x10f0
> > [ 117.027345] [c0000003a7c7b3d0] [c0000000000bbd0c] .call_timer_fn+0xbc/0x3e0
> > [ 117.027369] [c0000003a7c7b4b0] [c0000000000bc328] .run_timer_softirq+0x2f8/0x440
> > [ 117.027398] [c0000003a7c7b5c0] [c0000000000afef8] .__do_softirq+0x1b8/0x540
> > [ 117.027423] [c0000003a7c7b6f0] [c0000000000b04e8] .irq_exit+0xe8/0x100
> > [ 117.027448] [c0000003a7c7b770] [c000000000020464] .timer_interrupt+0x174/0x510
> > [ 117.027477] [c0000003a7c7b830] [c0000000000024f4] decrementer_common+0x174/0x180
> > [ 117.027509] --- Exception: 901 at .plpar_hcall_norets+0x84/0xd4
> > LR = .check_and_cede_processor+0x48/0x80
> > [ 117.027544] [c0000003a7c7bb20] [c000000000085168] .check_and_cede_processor+0x18/0x80 (unreliable)
> > [ 117.027577] [c0000003a7c7bb90] [c000000000085258] .dedicated_cede_loop+0x88/0x150
> > [ 117.027606] [c0000003a7c7bc50] [c00000000075808c] .cpuidle_enter+0x2c/0x40
> > [ 117.027632] [c0000003a7c7bcc0] [c0000000007589bc] .cpuidle_idle_call+0xfc/0x4e0
> > [ 117.027660] [c0000003a7c7bd70] [c000000000074be8] .pSeries_idle+0x18/0x40
> > [ 117.027685] [c0000003a7c7bde0] [c000000000018ec0] .cpu_idle+0x180/0x360
> > [ 117.027711] [c0000003a7c7bea0] [c00000000095391c] .start_secondary+0x534/0x53c
> > [ 117.027739] [c0000003a7c7bf90] [c0000000000097fc] .start_secondary_prolog+0x10/0x14
> >
>
> It might be related to this commit. Can you revert and try it.
With commit d6d3c4e656513dcea61ce900f0ecb9ca820ee7cd reverted, I do not see the
message above, but I do see:
[ 1.457095] BUG: spinlock bad magic on CPU#0, swapper/0/1
[ 1.457150] lock: devtree_lock+0x0/0x48, .magic: deaf1eed, .owner: swapper/0/1, .owner_cpu: 0
[ 1.457199] Call Trace:
[ 1.457234] [c0000003a7983710] [c000000000016ee0] .show_stack+0xd0/0x1f0 (unreliable)
[ 1.457302] [c0000003a79837e0] [c00000000094f284] .spin_dump+0x94/0xb0
[ 1.457362] [c0000003a7983860] [c00000000049f104] .do_raw_spin_unlock+0x94/0xf0
[ 1.457426] [c0000003a79838e0] [c00000000093b2b4] ._raw_spin_unlock_irqrestore+0x44/0xd0
[ 1.457487] [c0000003a7983970] [c00000000077ddc8] .of_device_is_available+0x58/0x80
[ 1.457551] [c0000003a7983a00] [c00000000007f4f8] .pseries_eeh_of_probe+0x48/0x350
[ 1.457612] [c0000003a7983af0] [c00000000003f084] .traverse_pci_devices+0xa4/0x170
[ 1.457678] [c0000003a7983b90] [c000000000ccd4a0] .eeh_init+0x104/0x170
[ 1.457734] [c0000003a7983c20] [c00000000000b5d4] .do_one_initcall+0x174/0x1f0
[ 1.457798] [c0000003a7983cd0] [c000000000cb502c] .kernel_init_freeable+0x224/0x314
[ 1.457860] [c0000003a7983db0] [c00000000000bd94] .kernel_init+0x24/0x130
[ 1.457917] [c0000003a7983e30] [c00000000000a1f0] .ret_from_kernel_thread+0x64/0x74
Thanks,
Nish
> Author: Thomas Gleixner <[email protected]>
> Date: Wed Feb 6 15:30:56 2013 -0500
>
> OF: convert devtree lock from rw_lock to raw spinlock
>
> With the locking cleanup in place (from "OF: Fixup resursive
> locking code paths"), we can now do the conversion from the
> rw_lock to a raw spinlock as required for preempt-rt.
>
> The previous cleanup and this conversion were originally
> separate since they predated when mainline got raw spinlock (in
> commit c2f21ce2e31286a "locking: Implement new raw_spinlock").
>
> So, at that point in time, the cleanup was considered plausible
> for mainline, but not this conversion. In any case, we've kept
> them separate as it makes for easier review and better bisection.
>
> Signed-off-by: Thomas Gleixner <[email protected]>
> [PG: taken from preempt-rt, update subject & add a commit log]
> Signed-off-by: Paul Gortmaker <[email protected]>
> Signed-off-by: Rob Herring <[email protected]>
>
On Fri, 19 Apr 2013, Rob Herring wrote:
> On 04/19/2013 02:01 PM, Nishanth Aravamudan wrote:
> > Running 3.9-rc7-ish, tripped the following (also being seen in FC19
> > alpha) on ppc64:
> >
> > [ 117.026196] =========================================================
> > [ 117.026216] [ INFO: possible irq lock inversion dependency detected ]
> > [ 117.026238] 3.9.0-rc7+ #8 Not tainted
> > [ 117.026251] ---------------------------------------------------------
> > [ 117.026271] swapper/7/0 just changed the state of lock:
> > [ 117.026286] (&(&tp->lock)->rlock){+.-...}, at: [<c00000000064effc>] .tg3_timer+0x9c/0x10f0
> > [ 117.026334] but this lock took another, SOFTIRQ-unsafe lock in the past:
> > [ 117.026353] (devtree_lock){+.+...}
Hmm. Looks like a few of the devtree functions do not disable
interrupts. Does the patch below fix the issue?
Thanks,
tglx
diff --git a/drivers/of/base.c b/drivers/of/base.c
index 321d3ef..a218b4c 100644
--- a/drivers/of/base.c
+++ b/drivers/of/base.c
@@ -192,14 +192,15 @@ EXPORT_SYMBOL(of_find_property);
struct device_node *of_find_all_nodes(struct device_node *prev)
{
struct device_node *np;
+ unsigned long flags;
- raw_spin_lock(&devtree_lock);
+ raw_spin_lock_irqsave(&devtree_lock, flags);
np = prev ? prev->allnext : of_allnodes;
for (; np != NULL; np = np->allnext)
if (of_node_get(np))
break;
of_node_put(prev);
- raw_spin_unlock(&devtree_lock);
+ raw_spin_unlock_irqrestore(&devtree_lock, flags);
return np;
}
EXPORT_SYMBOL(of_find_all_nodes);
@@ -420,8 +421,9 @@ struct device_node *of_get_next_available_child(const struct device_node *node,
struct device_node *prev)
{
struct device_node *next;
+ unsigned long flags;
- raw_spin_lock(&devtree_lock);
+ raw_spin_lock_irqsave(&devtree_lock, flags);
next = prev ? prev->sibling : node->child;
for (; next; next = next->sibling) {
if (!__of_device_is_available(next))
@@ -430,7 +432,7 @@ struct device_node *of_get_next_available_child(const struct device_node *node,
break;
}
of_node_put(prev);
- raw_spin_unlock(&devtree_lock);
+ raw_spin_unlock_irqrestore(&devtree_lock, flags);
return next;
}
EXPORT_SYMBOL(of_get_next_available_child);
@@ -734,13 +736,14 @@ EXPORT_SYMBOL_GPL(of_modalias_node);
struct device_node *of_find_node_by_phandle(phandle handle)
{
struct device_node *np;
+ unsigned long flags;
- raw_spin_lock(&devtree_lock);
+ raw_spin_lock_irqsave(&devtree_lock, flags);
for (np = of_allnodes; np; np = np->allnext)
if (np->phandle == handle)
break;
of_node_get(np);
- raw_spin_unlock(&devtree_lock);
+ raw_spin_unlock_irqrestore(&devtree_lock, flags);
return np;
}
EXPORT_SYMBOL(of_find_node_by_phandle);