Re: Callback not called on bulk out transfer with usbfs

[Alan Stern <stern@xxxxxxxxxxxxxxxxxxx>]

On Thu, 14 Jun 2012, Austin Schuh wrote:

> > Here's something to try. �In ehci-hcd.c:ehci_iaa_watchdog(), change the
> > ehci_vdbg() function call to ehci_warn(), leaving the arguments the
> > same. �This will log a message for each of the lost IAA interrupts, so
> > we'll be able to see a little bit of what's happening.
> 
> Here's your dump.  For completeness, I had ehci->need_io_watchdog = 1
> enabled, on the desktop machine, kernel 2.6.38.8.
> All the other entries look very similar to one of these two.  I can
> give you more of them if you would like.
> 
> Jun 14 13:41:35 aschuh kernel: [  791.577643] usb 1-4: unlink
> qh64-0001/ffff88059fb92800 start 1 [1/0 us]
> Jun 14 13:41:35 aschuh kernel: [  791.632975] ehci_hcd 0000:00:1a.7:
> reused qh ffff88059fb92800 schedule
> Jun 14 13:41:35 aschuh kernel: [  791.632978] usb 1-4: link
> qh64-0001/ffff88059fb92800 start 1 [1/0 us]

Most of this log is all the same, and it is not relevant.

> Jun 14 13:41:36 aschuh kernel: [  792.939975] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status 8028 cmd 10021

> Jun 14 14:01:23 aschuh kernel: [ 1977.839189] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status c028 cmd 10031

Those are the important entries.

> cat /var/log/syslog | IAA
> 
> Jun 14 13:35:10 aschuh kernel: [  407.168318] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status c028 cmd 10031
> Jun 14 13:41:36 aschuh kernel: [  792.939975] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status 8028 cmd 10021
> Jun 14 13:41:54 aschuh kernel: [  810.747858] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status c028 cmd 10031
> Jun 14 13:45:40 aschuh kernel: [ 1036.705444] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status c028 cmd 10031
> Jun 14 13:45:47 aschuh kernel: [ 1042.827822] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status c028 cmd 10031
> Jun 14 13:52:09 aschuh kernel: [ 1424.787116] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status 8028 cmd 10021
> Jun 14 13:56:10 aschuh kernel: [ 1665.323853] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status c028 cmd 10031
> Jun 14 13:57:38 aschuh kernel: [ 1753.762315] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status 8028 cmd 10021
> Jun 14 14:01:23 aschuh kernel: [ 1977.839189] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status c028 cmd 10031
> Jun 14 14:04:01 aschuh kernel: [ 2135.979125] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status c028 cmd 10031
> Jun 14 14:09:31 aschuh kernel: [ 2465.372666] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status 8028 cmd 10021
> Jun 14 14:18:32 aschuh kernel: [ 3005.369987] ehci_hcd 0000:00:1a.7:
> IAA watchdog: status e028 cmd 10031

Those indicate that IRQs are getting lost.  I have no idea why, except
that it probably isn't a problem in the USB hardware.  Maybe something
is wrong with interrupt-handling hardware.  On the other hand, a
hardware problem is unlikely to affect multiple different computer
systems.

To confirm the diagnosis, apply the patch below along with your change
to the iaa_watchdog routine.  It'll generate a lot of output; only the
entries that are close to the IAA watchdog messages will matter.

Alan Stern




Index: v/drivers/usb/host/ehci-hcd.c
===================================================================
--- v.orig/drivers/usb/host/ehci-hcd.c
+++ v/drivers/usb/host/ehci-hcd.c
@@ -851,6 +851,8 @@ static irqreturn_t ehci_irq (struct usb_
 	spin_lock (&ehci->lock);
 
 	status = ehci_readl(ehci, &ehci->regs->status);
+	ehci_info(ehci, "IRQ: status %x cmd %x\n", status,
+			ehci_readl(ehci, &ehci->regs->command));
 
 	/* e.g. cardbus physical eject */
 	if (status == ~(u32) 0) {

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