On Thu, Jun 21, 2012 at 8:47 AM, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote:
> On Wed, 20 Jun 2012, Austin Schuh wrote:
>> Here's the output with your latest patch.
>
>> [ 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
>
> And qh_completions wasn't even called...
>
> It's interesting that in both the last two test cases, the problem
> occurred immediately following the completion of an interrupt-IN URB.
> Maybe there's some connection.
>
>> $ cat 0000\:00\:1a.7/async
>> qh/ffff88055a83b180 dev4 hs ep2 42002204 40000000 (00008c00 data0 nak4)
>> ffff880037801240 out len=0 00008c00 urb ffff8805709bef00
>
> The next question is: Why wasn't qh_completions called? Either
> ehci_irq isn't calling ehci_work, or ehci_work isn't calling
> scan_async, or scan_async isn't calling qh_completions.
>
> Can you add appropriate debugging statements to figure that out, or
> would you like me to write another patch?
>
> Alan Stern
>
Sorry, I got side tracked on other stuff.
diff --git a/ehci-hcd.c b/ehci-hcd.c
index 53ab0fb..71bbf2e 100644
--- a/ehci-hcd.c
+++ b/ehci-hcd.c
@@ -483,6 +483,7 @@ static void ehci_port_power (struct ehci_hcd
*ehci, int is_on)
static void ehci_work (struct ehci_hcd *ehci)
{
timer_action_done (ehci, TIMER_IO_WATCHDOG);
+ ehci_dbg(ehci, "ehci_work\n");
/* another CPU may drop ehci->lock during a schedule scan while
* it reports urb completions. this flag guards against bogus
@@ -781,7 +782,7 @@ static irqreturn_t ehci_irq (struct usb_hcd *hcd)
spin_lock (&ehci->lock);
status = ehci_readl(ehci, &ehci->regs->status);
- ehci_info(ehci, "IRQ: status %x cmd %x\n", status,
+ ehci_info(ehci, "ehci_irq: IRQ: status %x cmd %x\n", status,
ehci_readl(ehci, &ehci->regs->command));
diff --git a/ehci-q.c b/ehci-q.c
index 11e7e04..c6d5de5 100644
--- a/ehci-q.c
+++ b/ehci-q.c
@@ -1249,6 +1249,7 @@ static void scan_async (struct ehci_hcd *ehci)
bool stopped;
struct ehci_qh *qh;
enum ehci_timer_action action = TIMER_IO_WATCHDOG;
+ ehci_dbg(ehci, "scan_async\n");
ehci->stamp = ehci_readl(ehci, &ehci->regs->frame_index);
timer_action_done (ehci, TIMER_ASYNC_SHRINK);
@@ -1256,8 +1257,12 @@ rescan:
stopped = !HC_IS_RUNNING(ehci_to_hcd(ehci)->state);
qh = ehci->async->qh_next.qh;
if (likely (qh != NULL)) {
+ ehci_dbg(ehci, "scan_async: qh!=NULL\n");
do {
/* clean any finished work for this qh */
+ ehci_dbg(ehci, "scan_async: !empty=%d
stopped=%d stamp=%d\n",
+ !list_empty(&qh->qtd_list),
stopped, qh->stamp != ehci->stamp);
+
if (!list_empty(&qh->qtd_list) && (stopped ||
qh->stamp != ehci->stamp)) {
int temp;
[ 501.743705] usb 1-4: usbdev_do_ioctl: SUBMITURB
[ 501.743712] usb 1-4: userurb 00007f001a2133d0, ep2 bulk-out, length 12
[ 501.743715] data: 0c 00 00 00 01 00 16 91 25 00 00 00
........%...
[ 501.743763] ehci_hcd 0000:00:1a.7: ehci_irq: IRQ: status c009 cmd 10021
[ 501.743767] ehci_hcd 0000:00:1a.7: ehci_work
[ 501.743769] ehci_hcd 0000:00:1a.7: scan_async
[ 501.743772] ehci_hcd 0000:00:1a.7: scan_async: qh!=NULL
[ 501.743775] ehci_hcd 0000:00:1a.7: scan_async: !empty=1 stopped=0 stamp=0
>From looking at the rest of the traces, it looks like stamp should be 1.
Austin Schu
--
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
