From: Don Zickus <dzickus@redhat.com>
Date: Fri, 21 Oct 2011 03:52:14 +0000 (-0400)
Subject: usb, xhci: fix lockdep warning on endpoint timeout
X-Git-Url: https://git.karo-electronics.de/?a=commitdiff_plain;h=f43d623164022dcbf6750ef220b7a1133a1183eb;p=linux-beck.git

usb, xhci: fix lockdep warning on endpoint timeout

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@redhat.com>
Signed-off-by: Sarah Sharp <sarah.a.sharp@linux.intel.com>
Cc: stable@kernel.org
---

diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index 940321b3ec68..9f1d4b15d818 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -816,23 +816,24 @@ void xhci_stop_endpoint_command_watchdog(unsigned long arg)
 	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(unsigned long arg)
 	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(unsigned long arg)
 			}
 		}
 	}
-	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");