[32/53] usb, xhci: fix lockdep warning on endpoint timeout

From: Greg KH
Date: Tue Nov 22 2011 - 19:56:23 EST

Next message: Greg KH: "[30/53] xhci: Set slot and ep0 flags for address command."
Previous message: Greg KH: "[34/53] USB: option: release new PID for ZTE 3G modem"
In reply to: Greg KH: "[34/53] USB: option: release new PID for ZTE 3G modem"
Next in thread: Greg KH: "[30/53] xhci: Set slot and ep0 flags for address command."
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

3.1-stable review patch. If anyone has any objections, please let me know.

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

From: Don Zickus <dzickus@xxxxxxxxxx>

commit f43d623164022dcbf6750ef220b7a1133a1183eb upstream.

While debugging a usb3 problem, I stumbled upon this lockdep warning.

Oct 18 21:41:17 dhcp47-74 kernel: =================================
Oct 18 21:41:17 dhcp47-74 kernel: [ INFO: inconsistent lock state ]
Oct 18 21:41:17 dhcp47-74 kernel: 3.1.0-rc4nmi+ #456
Oct 18 21:41:17 dhcp47-74 kernel: ---------------------------------
Oct 18 21:41:17 dhcp47-74 kernel: inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
Oct 18 21:41:17 dhcp47-74 kernel: swapper/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
Oct 18 21:41:17 dhcp47-74 kernel: (&(&xhci->lock)->rlock){?.-...}, at: [<ffffffffa0228990>] xhci_stop_endpoint_command_watchdog+0x30/0x340 [xhci_hcd]
Oct 18 21:41:17 dhcp47-74 kernel: {IN-HARDIRQ-W} state was registered at:
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8109a941>] __lock_acquire+0x781/0x1660
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8109bed7>] lock_acquire+0x97/0x170
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81501b46>] _raw_spin_lock+0x46/0x80
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffffa02299fa>] xhci_irq+0x3a/0x1960 [xhci_hcd]
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffffa022b351>] xhci_msi_irq+0x31/0x40 [xhci_hcd]
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff810d2305>] handle_irq_event_percpu+0x85/0x320
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff810d25e8>] handle_irq_event+0x48/0x70
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff810d537d>] handle_edge_irq+0x6d/0x130
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff810048c9>] handle_irq+0x49/0xa0
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8150d56d>] do_IRQ+0x5d/0xe0
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff815029b0>] ret_from_intr+0x0/0x13
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81388aca>] usb_set_device_state+0x8a/0x180
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8138f038>] usb_add_hcd+0x2b8/0x730
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffffa022ed7e>] xhci_pci_probe+0x9e/0xd4 [xhci_hcd]
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8127915f>] local_pci_probe+0x5f/0xd0
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8127a569>] pci_device_probe+0x119/0x120
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81334473>] driver_probe_device+0xa3/0x2c0
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8133473b>] __driver_attach+0xab/0xb0
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8133373c>] bus_for_each_dev+0x6c/0xa0
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff813341fe>] driver_attach+0x1e/0x20
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81333b88>] bus_add_driver+0x1f8/0x2b0
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81334df6>] driver_register+0x76/0x140
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8127a7c6>] __pci_register_driver+0x66/0xe0
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffffa013c04a>] snd_timer_find+0x4a/0x70 [snd_timer]
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffffa013c00e>] snd_timer_find+0xe/0x70 [snd_timer]
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff810001d3>] do_one_initcall+0x43/0x180
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff810a9ed2>] sys_init_module+0x92/0x1f0
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8150ab6b>] system_call_fastpath+0x16/0x1b
Oct 18 21:41:17 dhcp47-74 kernel: irq event stamp: 631984
Oct 18 21:41:17 dhcp47-74 kernel: hardirqs last enabled at (631984): [<ffffffff81502720>] _raw_spin_unlock_irq+0x30/0x50
Oct 18 21:41:17 dhcp47-74 kernel: hardirqs last disabled at (631983): [<ffffffff81501c49>] _raw_spin_lock_irq+0x19/0x90
Oct 18 21:41:17 dhcp47-74 kernel: softirqs last enabled at (631980): [<ffffffff8105ff63>] _local_bh_enable+0x13/0x20
Oct 18 21:41:17 dhcp47-74 kernel: softirqs last disabled at (631981): [<ffffffff8150ce6c>] call_softirq+0x1c/0x30
Oct 18 21:41:17 dhcp47-74 kernel:
Oct 18 21:41:17 dhcp47-74 kernel: other info that might help us debug this:
Oct 18 21:41:17 dhcp47-74 kernel: Possible unsafe locking scenario:
Oct 18 21:41:17 dhcp47-74 kernel:
Oct 18 21:41:17 dhcp47-74 kernel: CPU0
Oct 18 21:41:17 dhcp47-74 kernel: ----
Oct 18 21:41:17 dhcp47-74 kernel: lock(&(&xhci->lock)->rlock);
Oct 18 21:41:17 dhcp47-74 kernel: <Interrupt>
Oct 18 21:41:17 dhcp47-74 kernel: lock(&(&xhci->lock)->rlock);
Oct 18 21:41:17 dhcp47-74 kernel:
Oct 18 21:41:17 dhcp47-74 kernel: *** DEADLOCK ***
Oct 18 21:41:17 dhcp47-74 kernel:
Oct 18 21:41:17 dhcp47-74 kernel: 1 lock held by swapper/0:
Oct 18 21:41:17 dhcp47-74 kernel: #0: (&ep->stop_cmd_timer){+.-...}, at: [<ffffffff8106abf2>] run_timer_softirq+0x162/0x570
Oct 18 21:41:17 dhcp47-74 kernel:
Oct 18 21:41:17 dhcp47-74 kernel: stack backtrace:
Oct 18 21:41:17 dhcp47-74 kernel: Pid: 0, comm: swapper Tainted: G W 3.1.0-rc4nmi+ #456
Oct 18 21:41:17 dhcp47-74 kernel: Call Trace:
Oct 18 21:41:17 dhcp47-74 kernel: <IRQ> [<ffffffff81098ed7>] print_usage_bug+0x227/0x270
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff810999c6>] mark_lock+0x346/0x410
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8109a7de>] __lock_acquire+0x61e/0x1660
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81099893>] ? mark_lock+0x213/0x410
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8109bed7>] lock_acquire+0x97/0x170
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffffa0228990>] ? xhci_stop_endpoint_command_watchdog+0x30/0x340 [xhci_hcd]
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81501b46>] _raw_spin_lock+0x46/0x80
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffffa0228990>] ? xhci_stop_endpoint_command_watchdog+0x30/0x340 [xhci_hcd]
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffffa0228990>] xhci_stop_endpoint_command_watchdog+0x30/0x340 [xhci_hcd]
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8106abf2>] ? run_timer_softirq+0x162/0x570
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8106ac9d>] run_timer_softirq+0x20d/0x570
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8106abf2>] ? run_timer_softirq+0x162/0x570
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffffa0228960>] ? xhci_queue_isoc_tx_prepare+0x8e0/0x8e0 [xhci_hcd]
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff810604d2>] __do_softirq+0xf2/0x3f0
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81020edd>] ? lapic_next_event+0x1d/0x30
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81090d4e>] ? clockevents_program_event+0x5e/0x90
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8150ce6c>] call_softirq+0x1c/0x30
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8100484d>] do_softirq+0x8d/0xc0
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8105ff35>] irq_exit+0xe5/0x100
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8150d65e>] smp_apic_timer_interrupt+0x6e/0x99
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff8150b6f0>] apic_timer_interrupt+0x70/0x80
Oct 18 21:41:17 dhcp47-74 kernel: <EOI> [<ffffffff81095d8d>] ? trace_hardirqs_off+0xd/0x10
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff812ddb76>] ? acpi_idle_enter_bm+0x227/0x25b
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff812ddb71>] ? acpi_idle_enter_bm+0x222/0x25b
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff813eda63>] cpuidle_idle_call+0x103/0x290
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81002155>] cpu_idle+0xe5/0x160
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff814e7f50>] rest_init+0xe0/0xf0
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff814e7e70>] ? csum_partial_copy_generic+0x170/0x170
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81df8e23>] start_kernel+0x3fc/0x407
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81df8321>] x86_64_start_reservations+0x131/0x135
Oct 18 21:41:17 dhcp47-74 kernel: [<ffffffff81df8412>] x86_64_start_kernel+0xed/0xf4
Oct 18 21:41:17 dhcp47-74 kernel: xhci_hcd 0000:00:14.0: xHCI host not responding to stop endpoint command.
Oct 18 21:41:17 dhcp47-74 kernel: xhci_hcd 0000:00:14.0: Assuming host is dying, halting host.
Oct 18 21:41:17 dhcp47-74 kernel: xhci_hcd 0000:00:14.0: HC died; cleaning up
Oct 18 21:41:17 dhcp47-74 kernel: usb 3-4: device descriptor read/8, error -110
Oct 18 21:41:17 dhcp47-74 kernel: usb 3-4: device descriptor read/8, error -22
Oct 18 21:41:17 dhcp47-74 kernel: hub 3-0:1.0: cannot disable port 4 (err = -19)

Basically what is happening is in xhci_stop_endpoint_command_watchdog()
the xhci->lock is grabbed with just spin_lock. What lockdep deduces is
that if an interrupt occurred while in this function it would deadlock
with xhci_irq because that function also grabs the xhci->lock.

Fixing it is trivial by using spin_lock_irqsave instead.

This should be queued to stable kernels as far back as 2.6.33.

Signed-off-by: Don Zickus <dzickus@xxxxxxxxxx>
Signed-off-by: Sarah Sharp <sarah.a.sharp@xxxxxxxxxxxxxxx>
Signed-off-by: Greg Kroah-Hartman <gregkh@xxxxxxx>

---
drivers/usb/host/xhci-ring.c | 13 +++++++------
1 file changed, 7 insertions(+), 6 deletions(-)

--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -816,23 +816,24 @@ void xhci_stop_endpoint_command_watchdog
struct xhci_ring *ring;
struct xhci_td *cur_td;
int ret, i, j;
+ unsigned long flags;

ep = (struct xhci_virt_ep *) arg;
xhci = ep->xhci;

- spin_lock(&xhci->lock);
+ spin_lock_irqsave(&xhci->lock, flags);

ep->stop_cmds_pending--;
if (xhci->xhc_state & XHCI_STATE_DYING) {
xhci_dbg(xhci, "Stop EP timer ran, but another timer marked "
"xHCI as DYING, exiting.\n");
- spin_unlock(&xhci->lock);
+ spin_unlock_irqrestore(&xhci->lock, flags);
return;
}
if (!(ep->stop_cmds_pending == 0 && (ep->ep_state & EP_HALT_PENDING))) {
xhci_dbg(xhci, "Stop EP timer ran, but no command pending, "
"exiting.\n");
- spin_unlock(&xhci->lock);
+ spin_unlock_irqrestore(&xhci->lock, flags);
return;
}

@@ -844,11 +845,11 @@ void xhci_stop_endpoint_command_watchdog
xhci->xhc_state |= XHCI_STATE_DYING;
/* Disable interrupts from the host controller and start halting it */
xhci_quiesce(xhci);
- spin_unlock(&xhci->lock);
+ spin_unlock_irqrestore(&xhci->lock, flags);

ret = xhci_halt(xhci);

- spin_lock(&xhci->lock);
+ spin_lock_irqsave(&xhci->lock, flags);
if (ret < 0) {
/* This is bad; the host is not responding to commands and it's
* not allowing itself to be halted. At least interrupts are
@@ -896,7 +897,7 @@ void xhci_stop_endpoint_command_watchdog
}
}
}
- spin_unlock(&xhci->lock);
+ spin_unlock_irqrestore(&xhci->lock, flags);
xhci_dbg(xhci, "Calling usb_hc_died()\n");
usb_hc_died(xhci_to_hcd(xhci)->primary_hcd);
xhci_dbg(xhci, "xHCI host controller is dead.\n");

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Greg KH: "[30/53] xhci: Set slot and ep0 flags for address command."
Previous message: Greg KH: "[34/53] USB: option: release new PID for ZTE 3G modem"
In reply to: Greg KH: "[34/53] USB: option: release new PID for ZTE 3G modem"
Next in thread: Greg KH: "[30/53] xhci: Set slot and ep0 flags for address command."
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]