Re: [Qemu-devel] 2 issues with qemu-master / 1.2 ehci code

[Hans de Goede <hdegoede@redhat.com>]

[-- Attachment #1: Type: text/plain, Size: 1881 bytes --]

Hi,

On 08/16/2012 09:26 PM, Gerd Hoffmann wrote:

<snip>

>> I can get things working by turning ehci_fill_queue() into a nop...
>> Investigating this further. But if you've any insights they would be
>> appreciated. I'm thinking this may be caused by packets completing
>> out of order, which could be caused by the special handling of some
>> ctrl commands ...
>
> usbredir wouldn't see multiple parallel inflight requests per endpoint
> unless you explicitly enable this using usb_ep_set_pipeline().  Doing
> that on bulk endpoints should give you a nice performance boost for usb
> sticks.  Doing it on the control endpoint is asking for trouble ;)
>
> Can you turn on all ehci tracepoints & send me a log?

No need for that, I've been debugging this almost the entire day yesterday
and I've significantly narrowed it down further, the problem is that
the assert triggers when:
1) There are more packets then 1 in the queue (iow fill_queue did something)
2) A packet completion is not followed by an advqueue call

2) happens when a packet fails, and the queue should be halted, in this case
ehci_state_writeback() correctly does not call advqueue, bot does a horizqh
instead. The problem is that once this happens p->qtdaddr == q->qtdaddr is no
longer true ...

I've already come up with multiple approaches to try and fix this, but none
work sofar :|


Another problem with failing packets is that hw/usb/core.c will happily execute
the next packet in the ep queue, even though the spec says the ep-queue should
be halted, giving the guest a chance to cancel transfers after the failed one
without them ever executing. I've a poc patch fixing this too.

I've attached a wip patch with my work on this so-far. Note that currently
the halted bit at the ehci level never gets cleared (since we've queues at 2
levels, we need to track halting at 2 levels too)

Regards,

Hans



[-- Attachment #2: wip --]
[-- Type: text/plain, Size: 9887 bytes --]

diff --git a/hw/usb.h b/hw/usb.h
index 432ccae..6fa3088 100644
--- a/hw/usb.h
+++ b/hw/usb.h
@@ -179,6 +179,7 @@ struct USBEndpoint {
     uint8_t ifnum;
     int max_packet_size;
     bool pipeline;
+    bool halted;
     USBDevice *dev;
     QTAILQ_HEAD(, USBPacket) queue;
 };
@@ -375,6 +376,8 @@ void usb_ep_set_max_packet_size(USBDevice *dev, int pid, int ep,
                                 uint16_t raw);
 int usb_ep_get_max_packet_size(USBDevice *dev, int pid, int ep);
 void usb_ep_set_pipeline(USBDevice *dev, int pid, int ep, bool enabled);
+void usb_ep_process_queue(USBEndpoint *ep);
+void usb_ep_clear_halt(USBEndpoint *ep);
 
 void usb_attach(USBPort *port);
 void usb_detach(USBPort *port);
diff --git a/hw/usb/core.c b/hw/usb/core.c
index c7e5bc0..c9ad57e 100644
--- a/hw/usb/core.c
+++ b/hw/usb/core.c
@@ -382,12 +382,20 @@ int usb_handle_packet(USBDevice *dev, USBPacket *p)
     usb_packet_check_state(p, USB_PACKET_SETUP);
     assert(p->ep != NULL);
 
+    /* Submitting a new packet clears halt */
+    p->ep->halted = false;
+
     if (QTAILQ_EMPTY(&p->ep->queue) || p->ep->pipeline) {
         ret = usb_process_one(p);
         if (ret == USB_RET_ASYNC) {
             usb_packet_set_state(p, USB_PACKET_ASYNC);
             QTAILQ_INSERT_TAIL(&p->ep->queue, p, queue);
         } else {
+            /*
+             * When pipelining is enabled usb-devices must always return async,
+             * otherwise packets can complete out of order!
+             */
+            assert(!p->ep->pipeline);
             p->result = ret;
             usb_packet_set_state(p, USB_PACKET_COMPLETE);
         }
@@ -402,33 +410,26 @@ int usb_handle_packet(USBDevice *dev, USBPacket *p)
 /* Notify the controller that an async packet is complete.  This should only
    be called for packets previously deferred by returning USB_RET_ASYNC from
    handle_packet. */
-void usb_packet_complete(USBDevice *dev, USBPacket *p)
+static void __usb_packet_complete(USBDevice *dev, USBPacket *p)
 {
     USBEndpoint *ep = p->ep;
-    int ret;
 
-    usb_packet_check_state(p, USB_PACKET_ASYNC);
-    assert(QTAILQ_FIRST(&ep->queue) == p);
+    if (p->result < 0) {
+//        ep->halted = true;
+    }
     usb_packet_set_state(p, USB_PACKET_COMPLETE);
     QTAILQ_REMOVE(&ep->queue, p, queue);
     dev->port->ops->complete(dev->port, p);
+}
 
-    while (!QTAILQ_EMPTY(&ep->queue)) {
-        p = QTAILQ_FIRST(&ep->queue);
-        if (p->state == USB_PACKET_ASYNC) {
-            break;
-        }
-        usb_packet_check_state(p, USB_PACKET_QUEUED);
-        ret = usb_process_one(p);
-        if (ret == USB_RET_ASYNC) {
-            usb_packet_set_state(p, USB_PACKET_ASYNC);
-            break;
-        }
-        p->result = ret;
-        usb_packet_set_state(p, USB_PACKET_COMPLETE);
-        QTAILQ_REMOVE(&ep->queue, p, queue);
-        dev->port->ops->complete(dev->port, p);
-    }
+void usb_packet_complete(USBDevice *dev, USBPacket *p)
+{
+    USBEndpoint *ep = p->ep;
+
+    usb_packet_check_state(p, USB_PACKET_ASYNC);
+    assert(QTAILQ_FIRST(&ep->queue) == p);
+    __usb_packet_complete(dev, p);
+    usb_ep_process_queue(ep);
 }
 
 /* Cancel an active packet.  The packed must have been deferred by
@@ -702,3 +703,30 @@ void usb_ep_set_pipeline(USBDevice *dev, int pid, int ep, bool enabled)
     struct USBEndpoint *uep = usb_ep_get(dev, pid, ep);
     uep->pipeline = enabled;
 }
+
+void usb_ep_process_queue(USBEndpoint *ep)
+{
+    USBPacket *p;
+    int ret;
+
+    while (!ep->halted && !QTAILQ_EMPTY(&ep->queue)) {
+        p = QTAILQ_FIRST(&ep->queue);
+        if (p->state == USB_PACKET_ASYNC) {
+            break;
+        }
+        usb_packet_check_state(p, USB_PACKET_QUEUED);
+        ret = usb_process_one(p);
+        if (ret == USB_RET_ASYNC) {
+            usb_packet_set_state(p, USB_PACKET_ASYNC);
+            break;
+        }
+        p->result = ret;
+        __usb_packet_complete(ep->dev, p);
+    }
+}
+
+void usb_ep_clear_halt(USBEndpoint *ep)
+{
+    ep->halted = false;
+    usb_ep_process_queue(ep);
+}
diff --git a/hw/usb/hcd-ehci.c b/hw/usb/hcd-ehci.c
index 41d663d..c8d2d96 100644
--- a/hw/usb/hcd-ehci.c
+++ b/hw/usb/hcd-ehci.c
@@ -366,6 +366,7 @@ struct EHCIQueue {
     uint64_t ts;
     int async;
     int revalidate;
+    bool halted;
 
     /* cached data from guest - needs to be flushed
      * when guest removes an entry (doorbell, handshake sequence)
@@ -740,6 +741,7 @@ static EHCIPacket *ehci_alloc_packet(EHCIQueue *q)
 
 static void ehci_free_packet(EHCIPacket *p)
 {
+    printf("queue %p packet %p free\n", p->queue, p);
     trace_usb_ehci_packet_action(p->queue, p, "free");
     if (p->async == EHCI_ASYNC_INFLIGHT) {
         usb_cancel_packet(&p->packet);
@@ -1773,6 +1775,7 @@ static EHCIQueue *ehci_state_fetchqh(EHCIState *ehci, int async)
     if (q->revalidate && (q->qh.epchar      != qh.epchar ||
                           q->qh.epcap       != qh.epcap  ||
                           q->qh.current_qtd != qh.current_qtd)) {
+        printf("queue %p packet %p qtdaddr %08x freeing because of cancel\n", q, NULL, q->qtdaddr);
         ehci_free_queue(q);
         q = ehci_alloc_queue(ehci, entry, async);
         q->seen++;
@@ -1786,6 +1789,7 @@ static EHCIQueue *ehci_state_fetchqh(EHCIState *ehci, int async)
     if (q->dev != NULL && q->dev->addr != devaddr) {
         if (!QTAILQ_EMPTY(&q->packets)) {
             /* should not happen (guest bug) */
+            printf("guest bug 2!!!\n");
             while ((p = QTAILQ_FIRST(&q->packets)) != NULL) {
                 ehci_free_packet(p);
             }
@@ -1796,18 +1800,22 @@ static EHCIQueue *ehci_state_fetchqh(EHCIState *ehci, int async)
         q->dev = ehci_find_device(q->ehci, devaddr);
     }
 
-    if (p && p->async == EHCI_ASYNC_INFLIGHT) {
+    if (!q->halted && p && p->async == EHCI_ASYNC_INFLIGHT) {
+//        if (p->packet.ep->halted && !(q->qh.token & QTD_TOKEN_HALT)) {
+//            usb_ep_clear_halt(p->packet.ep);
+//        }
         /* I/O still in progress -- skip queue */
         ehci_set_state(ehci, async, EST_HORIZONTALQH);
         goto out;
     }
-    if (p && p->async == EHCI_ASYNC_FINISHED) {
+    if (!q->halted && p && p->async == EHCI_ASYNC_FINISHED) {
         /* I/O finished -- continue processing queue */
         trace_usb_ehci_packet_action(p->queue, p, "complete");
+        if ((q->qh.epchar & QH_EPCHAR_EP_MASK) == 0)
+             printf("queue %p packet %p qtdaddr %08x completing from fetchqh\n", q, p, p->qtdaddr);
         ehci_set_state(ehci, async, EST_EXECUTING);
         goto out;
     }
-
     if (async && (q->qh.epchar & QH_EPCHAR_H)) {
 
         /*  EHCI spec version 1.0 Section 4.8.3 & 4.10.1 */
@@ -1842,6 +1850,8 @@ static EHCIQueue *ehci_state_fetchqh(EHCIState *ehci, int async)
         ehci_set_state(ehci, async, EST_FETCHQTD);
 
     } else {
+        if ((q->qh.epchar & QH_EPCHAR_EP_MASK) == 0)
+            printf("queue %p packet %p qtdaddr %08x advqueue fetchqh\n", q, NULL, q->qtdaddr);
         /*  EHCI spec version 1.0 Section 4.10.2 */
         ehci_set_state(ehci, async, EST_ADVANCEQUEUE);
     }
@@ -1951,19 +1961,31 @@ static int ehci_state_fetchqtd(EHCIQueue *q)
     p = QTAILQ_FIRST(&q->packets);
     while (p != NULL && p->qtdaddr != q->qtdaddr) {
         /* should not happen (guest bug) */
+        printf("guest bug!!!\n");
         ehci_free_packet(p);
         p = QTAILQ_FIRST(&q->packets);
     }
     if (p != NULL) {
         ehci_qh_do_overlay(q);
-        if (p->async == EHCI_ASYNC_INFLIGHT) {
+        switch (p->async) {
+        case EHCI_ASYNC_NONE:
+            ehci_set_state(q->ehci, q->async, EST_EXECUTING);
+            break;
+        case EHCI_ASYNC_INFLIGHT:
             ehci_set_state(q->ehci, q->async, EST_HORIZONTALQH);
-        } else {
+            break;
+        case EHCI_ASYNC_FINISHED:
+            trace_usb_ehci_packet_action(q, p, "complete");
+            if ((q->qh.epchar & QH_EPCHAR_EP_MASK) == 0)
+                printf("queue %p packet %p qtdaddr %08x completing from fetchqtd\n", q, p, p->qtdaddr);
             ehci_set_state(q->ehci, q->async, EST_EXECUTING);
+            break;
         }
         again = 1;
     } else if (qtd.token & QTD_TOKEN_ACTIVE) {
         p = ehci_alloc_packet(q);
+        if ((q->qh.epchar & QH_EPCHAR_EP_MASK) == 0)
+            printf("queue %p packet %p qtdaddr %08x ep %d added (fetchqtd)\n", q, p, q->qtdaddr, (q->qh.epchar & QH_EPCHAR_EP_MASK) >> QH_EPCHAR_EP_SH);
         p->qtdaddr = q->qtdaddr;
         p->qtd = qtd;
         ehci_set_state(q->ehci, q->async, EST_EXECUTE);
@@ -2012,6 +2034,8 @@ static void ehci_fill_queue(EHCIPacket *p)
             break;
         }
         p = ehci_alloc_packet(q);
+        if ((q->qh.epchar & QH_EPCHAR_EP_MASK) == 0)
+            printf("queue %p packet %p qtdaddr %08x added (fill_queue)\n", q, p, qtdaddr);
         p->qtdaddr = qtdaddr;
         p->qtd = qtd;
         p->usb_status = ehci_execute(p, "queue");
@@ -2076,10 +2100,15 @@ static int ehci_state_executing(EHCIQueue *q)
     EHCIPacket *p = QTAILQ_FIRST(&q->packets);
     int again = 0;
 
+    if ((q->qh.epchar & QH_EPCHAR_EP_MASK) == 0)
+        printf("queue %p packet %p qtdaddr %08x completing, async %d\n", q, p, p->qtdaddr, p->async);
+
     assert(p != NULL);
     assert(p->qtdaddr == q->qtdaddr);
 
     ehci_execute_complete(q);
+    if ((q->qh.epchar & QH_EPCHAR_EP_MASK) == 0)
+        printf("queue %p packet %p qtdaddr %08x completed, status %d\n", q, p, p->qtdaddr, p->usb_status);
     if (p->usb_status == USB_RET_ASYNC) {
         goto out;
     }
@@ -2137,6 +2166,7 @@ static int ehci_state_writeback(EHCIQueue *q)
      * bit is clear.
      */
     if (q->qh.token & QTD_TOKEN_HALT) {
+        q->halted = true;
         ehci_set_state(q->ehci, q->async, EST_HORIZONTALQH);
         again = 1;
     } else {