On Wed, Jun 20, 2012 at 11:58 AM, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote:
> On Wed, 20 Jun 2012, Austin Schuh wrote:
>
>> > The IAA interrupts aren't getting lost. Instead we're seeing early
>> > timer expirations, probably caused by imprecise timer values. What do
>> > you have CONFIG_HZ set to
>>
>> CONFIG_HZ=100
>
> Yes, that explains it. The timer values would be too imprecise for any
> CONFIG_HZ value smaller than 200. Okay, never mind the IAA stuff...
>
>> Ok. Here's the trace. I might have an extra print or two in there
>> from some of my other debugging, but it should be pretty clean.
>
> ...
>> [ 430.268189] usb 1-4: usbdev_do_ioctl: SUBMITURB
>> [ 430.268196] usb 1-4: userurb 00007f1c3881e250, ep2 bulk-out, length 12
>> [ 430.268199] data: 0c 00 00 00 01 00 16 91 25 00 00 00
>> ........%...
>> [ 430.268324] ehci_hcd 0000:00:1a.7: IRQ: status c009 cmd 10021
>>
>> $ cat 0000\:00\:1a.7/async
>> qh/ffff88055e366980 dev7 hs ep2 42002207 40000000 (00008c00 data0 nak4)
>> ffff880037801240 out len=0 00008c00 urb ffff880522de5c80
>
> That's the smoking gun. There _was_ an interrupt, and the STS_INT bit
> (the 0x01 bit) in the status register was set. That should have caused
> ehci_irq to call ehci_work -> scan_async -> qh_completions.
>
> qh_completions should have seen that the QTD_STS_ACTIVE bit wasn't set
> in the qTD token (the 0x80 bit in the low-order byte of the 00008c00
> word in the second line of the "async" file). That would tell it the
> transfer was complete.
>
> Here's a patch to print out the values of the qTD tokens. Let's see
> what it shows when your transfer hangs up. Leave the "IRQ:" message in
> place.
>
> Index: usb-3.4/drivers/usb/host/ehci-q.c
> ===================================================================
> --- usb-3.4.orig/drivers/usb/host/ehci-q.c
> +++ usb-3.4/drivers/usb/host/ehci-q.c
> @@ -364,6 +364,7 @@ qh_completions (struct ehci_hcd *ehci, s
> /* hardware copies qtd out of qh overlay */
> rmb ();
> token = hc32_to_cpu(ehci, qtd->hw_token);
> +ehci_dbg(ehci, "qh %p qtd %p token %x\n", qh, qtd, token);
>
> /* always clean up qtds the hc de-activated */
> retry_xacterr:
>
Here's the output with your latest patch.
[ 431.231304] ehci_hcd 0000:00:1a.7: IRQ: status 6009 cmd 10011
[ 431.231314] ehci_hcd 0000:00:1a.7: qh ffff88056bc40d00 qtd
ffff880037801240 token 108d00
[ 431.231320] usb 1-4: urb complete
[ 431.231323] usb 1-4: userurb 00007f8887b60020, ep3 int-in,
actual_length 16 status -121
[ 431.231327] data: 10 00 00 00 04 00 01 c1 ff ff ff ff 00 00 00 00
................
[ 431.231350] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 431.231482] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 431.231488] usb 1-4: userurb 00007f8887b60090, ep2 bulk-out, length 12
[ 431.231491] data: 0c 00 00 00 01 00 16 91 24 00 00 00
........$...
[ 431.231672] ehci_hcd 0000:00:1a.7: IRQ: status c009 cmd 10021
[ 431.231678] ehci_hcd 0000:00:1a.7: qh ffff88055a83b180 qtd
ffff8800378010c0 token 80008c00
[ 431.231683] usb 1-4: urb complete
[ 431.231686] usb 1-4: userurb 00007f8887b60090, ep2 bulk-out,
actual_length 12 status 0
[ 431.231702] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 431.231731] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 431.231738] usb 1-4: userurb 00007f8888b15420, ep1 bulk-in, length 16384
[ 431.231744] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 431.231748] usb 1-4: userurb 00007f8888b15458, ep1 bulk-in, length 16384
[ 431.232912] ehci_hcd 0000:00:1a.7: IRQ: status 8009 cmd 10021
[ 431.232918] ehci_hcd 0000:00:1a.7: qh ffff88056bf45680 qtd
ffff880037801060 token 3fc88d00
[ 431.232926] usb 1-4: urb complete
[ 431.232929] usb 1-4: userurb 00007f8888b15420, ep1 bulk-in,
actual_length 56 status -121
[ 431.232933] data: 38 00 00 00 02 00 16 91 24 00 00 00 14 00 00 00
8a c1 00 00 d4 d1 00 00 07 00 00 00 00 00 00 00
8.......$.......................
[ 431.232936] data: 10 00 00 00 89 c1 00 00 c3 d1 00 00 00 00 00 00
08 00 00 00 00 00 00 00
........................
[ 431.232945] ehci_hcd 0000:00:1a.7: qh ffff88056bf45680 qtd
ffff8800378010c0 token 40008d80
[ 431.232951] usb 1-4: urb complete
[ 431.232954] usb 1-4: userurb 00007f8888b15458, ep1 bulk-in,
actual_length 0 status -104
[ 431.232974] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 431.232979] usb 1-4: usbdev_do_ioctl: DISCARDURB
[ 431.232990] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 431.232995] ehci_hcd 0000:00:1a.7: IRQ: status 8028 cmd 10021
[ 431.233036] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 431.233042] usb 1-4: userurb 00007f8888ad4200, ep1 bulk-in, length 16384
[ 431.233048] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 431.233051] usb 1-4: userurb 00007f8888ad4238, ep1 bulk-in, length 16384
[ 431.233662] ehci_hcd 0000:00:1a.7: IRQ: status 8009 cmd 10021
[ 431.233669] ehci_hcd 0000:00:1a.7: qh ffff88056bf45680 qtd
ffff880037801180 token bff48d00
[ 431.233676] usb 1-4: urb complete
[ 431.233679] usb 1-4: userurb 00007f8888ad4200, ep1 bulk-in,
actual_length 12 status -121
[ 431.233683] data: 0c 00 00 00 03 00 01 20 24 00 00 00
....... $...
[ 431.233690] ehci_hcd 0000:00:1a.7: qh ffff88056bf45680 qtd
ffff8800378010c0 token 40008d80
[ 431.233696] usb 1-4: urb complete
[ 431.233699] usb 1-4: userurb 00007f8888ad4238, ep1 bulk-in,
actual_length 0 status -104
[ 431.233715] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 431.233721] usb 1-4: usbdev_do_ioctl: DISCARDURB
[ 431.233731] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 431.233744] ehci_hcd 0000:00:1a.7: IRQ: status 8028 cmd 10021
[ 431.233814] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 431.233820] usb 1-4: userurb 00007f8888b03c20, ep3 int-in, length 32
[ 431.233827] usb 1-4: link qh64-0001/ffff88056bc40d00 start 1 [1/0 us]
[ 431.247524] ehci_hcd 0000:00:1a.7: IRQ: status c028 cmd 10031
[ 431.297262] ehci_hcd 0000:00:1a.7: qh ffff88056bc40d00 qtd
ffff8800378011e0 token 208d80
[ 431.297268] ehci_hcd 0000:00:1a.7: qh ffff88056bc40d00 qtd
ffff8800378011e0 token 208d80
[ 431.297273] ehci_hcd 0000:00:1a.7: qh ffff88056bc40d00 qtd
ffff8800378011e0 token 208d80
[ 431.297277] ehci_hcd 0000:00:1a.7: qh ffff88056bc40d00 qtd
ffff8800378011e0 token 208d80
[ 431.297280] ehci_hcd 0000:00:1a.7: qh ffff88056bc40d00 qtd
ffff8800378011e0 token 208d80
[ 431.297283] ehci_hcd 0000:00:1a.7: qh ffff88056bc40d00 qtd
ffff8800378011e0 token 208d80
[ 431.297286] ehci_hcd 0000:00:1a.7: qh ffff88056bc40d00 qtd
ffff8800378011e0 token 208d80
[ 431.297289] ehci_hcd 0000:00:1a.7: qh ffff88056bc40d00 qtd
ffff8800378011e0 token 208d80
[ 433.276713] ehci_hcd 0000:00:1a.7: IRQ: status 6009 cmd 10011
[ 433.276726] ehci_hcd 0000:00:1a.7: qh ffff88056bc40d00 qtd
ffff8800378011e0 token 80108d00
[ 433.276732] usb 1-4: urb complete
[ 433.276735] usb 1-4: userurb 00007f8888b03c20, ep3 int-in,
actual_length 16 status -121
[ 433.276739] data: 10 00 00 00 04 00 01 c1 ff ff ff ff 00 00 00 00
................
[ 433.276764] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 433.276972] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 433.276979] usb 1-4: userurb 00007f8888b02090, ep2 bulk-out, length 12
[ 433.276982] data: 0c 00 00 00 01 00 16 91 25 00 00 00
........%...
[ 433.277051] ehci_hcd 0000:00:1a.7: IRQ: status c009 cmd 10021
$ cat 0000\:00\:1a.7/async
qh/ffff88055a83b180 dev4 hs ep2 42002204 40000000 (00008c00 data0 nak4)
ffff880037801240 out len=0 00008c00 urb ffff8805709bef00
Austin Schuh
--
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
