On Mon, 3 Dec 2012, Piergiorgio Sartor wrote:
> Hi Alan,
>
> I updated the bug report with dmesg dump.
>
> I hope this time it is correct...
Yes, it is. It shows a couple of strange things; I need more
information.
Below is a new test patch; try running the test with this patch in
place of the previous one. I don't need to see the usbmon trace, just
the dmesg log. And not even all of that; just the part from "alan
start" to "alan end" -- this will be near the end of the log.
Also, what output do you get from "lspci -v -s b.1"?
Alan Stern
Index: usb-3.7/drivers/usb/host/ehci-hcd.c
===================================================================
--- usb-3.7.orig/drivers/usb/host/ehci-hcd.c
+++ usb-3.7/drivers/usb/host/ehci-hcd.c
@@ -825,8 +825,10 @@ dead:
bh = 0;
}
- if (bh)
+ if (bh) {
+ ehci->last_scan_time = jiffies;
ehci_work (ehci);
+ }
spin_unlock (&ehci->lock);
if (pcd_status)
usb_hcd_poll_rh_status(hcd);
@@ -884,6 +886,53 @@ static int ehci_urb_enqueue (
}
}
+static void alan_debug(struct ehci_hcd *ehci, struct urb *urb, struct ehci_qh *qh)
+{
+ static int done;
+ struct ehci_qh *qh2;
+ struct ehci_qtd *td;
+ char label[24];
+
+ if (done)
+ return;
+ if (urb->transfer_buffer_length != 31) {
+ ehci_dbg(ehci, "unlink urb len %d\n", urb->transfer_buffer_length);
+ return;
+ }
+
+ ehci->alan_urb = urb;
+ done = 1;
+ ehci_dbg(ehci, "alan start cur time %lu last scan %lu\n",
+ jiffies, ehci->last_scan_time);
+ ehci_dbg(ehci, "command %x cmd reg %x io watchdog %d async count %d\n",
+ ehci->command, ehci_readl(ehci, &ehci->regs->command),
+ ehci->need_io_watchdog, ehci->async_count);
+
+ ehci_dbg(ehci, "async list:\n");
+ qh2 = ehci->async;
+ while (qh2) {
+ ehci_dbg(ehci, " qh %p hw %p dma %x next %p hw_next %x\n",
+ qh2, qh2->hw, (u32) qh2->qh_dma, qh2->qh_next.qh,
+ hc32_to_cpu(ehci, qh2->hw->hw_next));
+ qh2 = qh2->qh_next.qh;
+ }
+
+ ehci_dbg(ehci, "This qh link time %lu enqueue time %lu td token %x ov token %x\n",
+ qh->link_time, qh->enqueue_time,
+ hc32_to_cpu(ehci, qh->tdtoken),
+ hc32_to_cpu(ehci, qh->ovtoken));
+ dbg_qh(" ", ehci, qh);
+
+ list_for_each_entry(td, &qh->qtd_list, qtd_list) {
+ sprintf(label, " dma %x", (u32) td->qtd_dma);
+ dbg_qtd(label, ehci, td);
+ }
+
+ sprintf(label, " dummy %x", (u32) qh->dummy->qtd_dma);
+ dbg_qtd(label, ehci, qh->dummy);
+}
+
+
/* remove from hardware lists
* completions normally happen asynchronously
*/
@@ -907,6 +956,10 @@ static int ehci_urb_dequeue(struct usb_h
qh = (struct ehci_qh *) urb->hcpriv;
if (!qh)
break;
+
+ if (usb_pipetype(urb->pipe) == PIPE_BULK)
+ alan_debug(ehci, urb, qh);
+
switch (qh->qh_state) {
case QH_STATE_LINKED:
case QH_STATE_COMPLETING:
Index: usb-3.7/drivers/usb/host/ehci.h
===================================================================
--- usb-3.7.orig/drivers/usb/host/ehci.h
+++ usb-3.7/drivers/usb/host/ehci.h
@@ -221,6 +221,10 @@ struct ehci_hcd { /* one per controlle
#ifdef DEBUG
struct dentry *debug_dir;
#endif
+
+ struct urb *alan_urb;
+ unsigned long last_scan_time;
+
};
/* convert between an HCD pointer and the corresponding EHCI_HCD */
@@ -400,6 +404,9 @@ struct ehci_qh {
struct usb_device *dev; /* access to TT */
unsigned is_out:1; /* bulk or intr OUT */
unsigned clearing_tt:1; /* Clear-TT-Buf in progress */
+
+ unsigned long link_time, enqueue_time;
+ __hc32 tdtoken, ovtoken;
};
/*-------------------------------------------------------------------------*/
Index: usb-3.7/drivers/usb/host/ehci-q.c
===================================================================
--- usb-3.7.orig/drivers/usb/host/ehci-q.c
+++ usb-3.7/drivers/usb/host/ehci-q.c
@@ -291,6 +291,11 @@ __acquires(ehci->lock)
/* complete() can reenter this HCD */
usb_hcd_unlink_urb_from_ep(ehci_to_hcd(ehci), urb);
spin_unlock (&ehci->lock);
+ if (urb == ehci->alan_urb) {
+ ehci->alan_urb = NULL;
+ ehci_dbg(ehci, "giveback urb %p actual %d\n", urb, urb->actual_length);
+ ehci_dbg(ehci, "alan end\n");
+ }
usb_hcd_giveback_urb(ehci_to_hcd(ehci), urb, status);
spin_lock (&ehci->lock);
}
@@ -1002,6 +1007,7 @@ static void qh_link_async (struct ehci_h
/* clear halt and/or toggle; and maybe recover from silicon quirk */
qh_refresh(ehci, qh);
+ qh->link_time = jiffies;
/* splice right after start */
head = ehci->async;
@@ -1101,6 +1107,7 @@ static struct ehci_qh *qh_append_tds (
dummy->hw_token = token;
urb->hcpriv = qh;
+ qh->tdtoken = token;
}
}
return qh;
@@ -1154,8 +1161,11 @@ submit_async (
/* Control/bulk operations through TTs don't need scheduling,
* the HC and TT handle it when the TT has a buffer ready.
*/
+ qh->enqueue_time = jiffies;
if (likely (qh->qh_state == QH_STATE_IDLE))
qh_link_async(ehci, qh);
+ qh->ovtoken = qh->hw->hw_token;
+
done:
spin_unlock_irqrestore (&ehci->lock, flags);
if (unlikely (qh == NULL))
--
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
