On Wed, Jun 20, 2012 at 9:02 AM, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote:
> On Tue, 19 Jun 2012, Austin Schuh wrote:
>
>> Sorry for the delay. I added a print in like you requested, and
>> here's a lot more context this time. FYI, there might have been a
>> couple of lines of IAA watchdog that I missed here.
>>
>> $ dmesg | grep -C 10 "IAA watchdog"
>> [ 336.474635] ehci_hcd 0000:00:1a.7: IRQ: status c009 cmd 10031
>> [ 336.488135] ehci_hcd 0000:00:1a.7: start_unlink_async: IAAD
>> [ 336.488243] ehci_hcd 0000:00:1a.7: IRQ: status c028 cmd 10031
>> [ 336.593234] ehci_hcd 0000:00:1a.7: IRQ: status c009 cmd 10031
>> [ 336.593253] ehci_hcd 0000:00:1a.7: start_unlink_async: IAAD
>> [ 336.593326] ehci_hcd 0000:00:1a.7: IRQ: status c028 cmd 10031
>> [ 336.596105] ehci_hcd 0000:00:1a.7: IRQ: status c009 cmd 10031
>> [ 336.596365] ehci_hcd 0000:00:1a.7: IRQ: status c009 cmd 10021
>> [ 336.597854] ehci_hcd 0000:00:1a.7: IRQ: status 8009 cmd 10021
>> [ 336.597873] ehci_hcd 0000:00:1a.7: start_unlink_async: IAAD
>> [ 336.597925] ehci_hcd 0000:00:1a.7: IAA watchdog: status 8028 cmd 10021
>
> That's good enough. Unfortunately, it doesn't help solve our problem!
Bummer!
> 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
> I have been working on using high-resolution timers in ehci-hcd, which
> ought to fix this problem. But for now, this doesn't explain why your
> bulk-out completion interrupts don't occur on time.
>
> Tell you what... Get rid of the IAAD: message, but keep the IRQ:
> message in ehci_irq(). Run your usbfs program, and let's see what the
> log shows for the time period when your completion is lost.
>
> To help synchronize your usbfs I/O with the EHCI debugging lines, leave
> usbfs snooping on while running the test.
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.
[ 428.046218] ehci_hcd 0000:00:1a.7: IRQ: status c028 cmd 10031
[ 428.056870] ehci_hcd 0000:00:1a.7: IRQ: status c028 cmd 10031
[ 428.222555] ehci_hcd 0000:00:1a.7: IRQ: status 6009 cmd 10011
[ 428.222567] usb 1-4: urb complete
[ 428.222571] usb 1-4: userurb 00007f1c397374b0, ep3 int-in,
actual_length 16 status -121
[ 428.222575] data: 10 00 00 00 04 00 01 c1 ff ff ff ff 00 00 00 00
................
[ 428.222596] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 428.222715] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 428.222721] usb 1-4: userurb 00007f1c3881e1e0, ep2 bulk-out, length 12
[ 428.222724] data: 0c 00 00 00 01 00 16 91 24 00 00 00
........$...
[ 428.222912] ehci_hcd 0000:00:1a.7: IRQ: status c009 cmd 10021
[ 428.222919] usb 1-4: urb complete
[ 428.222922] usb 1-4: userurb 00007f1c3881e1e0, ep2 bulk-out,
actual_length 12 status 0
[ 428.222939] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 428.222969] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 428.222976] usb 1-4: userurb 00007f1c398845c0, ep1 bulk-in, length 16384
[ 428.222982] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 428.222986] usb 1-4: userurb 00007f1c398845f8, ep1 bulk-in, length 16384
[ 428.228277] ehci_hcd 0000:00:1a.7: IRQ: status 8009 cmd 10021
[ 428.228286] usb 1-4: urb complete
[ 428.228290] usb 1-4: userurb 00007f1c398845c0, ep1 bulk-in,
actual_length 56 status -121
[ 428.228294] 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.......$.......................
[ 428.228298] 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
........................
[ 428.228308] usb 1-4: urb complete
[ 428.228312] usb 1-4: userurb 00007f1c398845f8, ep1 bulk-in,
actual_length 0 status -104
[ 428.228328] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 428.228333] usb 1-4: usbdev_do_ioctl: DISCARDURB
[ 428.228344] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 428.228362] ehci_hcd 0000:00:1a.7: IRQ: status 8028 cmd 10021
[ 428.228391] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 428.228397] usb 1-4: userurb 00007f1c388e62a0, ep1 bulk-in, length 16384
[ 428.228403] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 428.228407] usb 1-4: userurb 00007f1c388e62d8, ep1 bulk-in, length 16384
[ 428.229153] ehci_hcd 0000:00:1a.7: IRQ: status 8009 cmd 10021
[ 428.229162] usb 1-4: urb complete
[ 428.229166] usb 1-4: userurb 00007f1c388e62a0, ep1 bulk-in,
actual_length 12 status -121
[ 428.229170] data: 0c 00 00 00 03 00 01 20 24 00 00 00
....... $...
[ 428.229180] usb 1-4: urb complete
[ 428.229183] usb 1-4: userurb 00007f1c388e62d8, ep1 bulk-in,
actual_length 0 status -104
[ 428.229199] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 428.229205] usb 1-4: usbdev_do_ioctl: DISCARDURB
[ 428.229216] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 428.229235] ehci_hcd 0000:00:1a.7: IRQ: status 8028 cmd 10021
[ 428.229290] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 428.229295] usb 1-4: userurb 00007f1c397379f0, ep3 int-in, length 32
[ 428.229302] usb 1-4: link qh64-0001/ffff880522e86c00 start 1 [1/0 us]
[ 428.246634] ehci_hcd 0000:00:1a.7: IRQ: status c028 cmd 10031
[ 430.267963] ehci_hcd 0000:00:1a.7: IRQ: status 6009 cmd 10011
[ 430.267976] usb 1-4: urb complete
[ 430.267980] usb 1-4: userurb 00007f1c397379f0, ep3 int-in,
actual_length 16 status -121
[ 430.267984] data: 10 00 00 00 04 00 01 c1 ff ff ff ff 00 00 00 00
................
[ 430.268008] usb 1-4: usbdev_do_ioctl: REAPURBNDELAY
[ 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
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
