On Tue, Sep 09, 2014 at 01:15:04PM -0600, Dave Frodin wrote:
> I'm seeing a problem booting from USB thumbdrives with commit ab9d771ce
>     ehci: Update usb command timeouts to use usb_xfer_time()
>
> I'm not quite sure what the problem is other than it not liking the new
> timeouts.
> I couldn't see any problems with the ehci_control() calls to ehci_wait_td().
> But the ehci_send_bulk() only allows the system to boot if I change
>     int ret = ehci_wait_td(pipe, td, end);
> to
>     int ret = ehci_wait_td(pipe, td, timer_calc(5000));
>
> One potential problem is that the "end" value is calculated once and reused
> multiple times in the functions. Prior to the commit the timeout value was
> passed
> to the ehci_wait_td() function. Now the final "end" time is passed. So it
> looks like
> once the end timeout is reached in one of the loops that calls
> ehci_wait_td() the
> timer will always be expired for any other calls from that function.
>
> One solution might be to get rid of the "end" variable and change the calls
> from
>     ret = ehci_wait_td(pipe, td, end);
> to
>     ret = ehci_wait_td(pipe, td, timer_calc(usb_xfer_time(p, datasize)));
>
> Making the above change didn't have any impact on my booting problem until
> I forced the ehci_send_bulk() timeouts to 5000.

Hi Dave,

Stefan Burger reported a similar problem with that commit.  However,
I'm puzzled what would be causing such a regression - five seconds
should be more then enough time to complete a single usb transaction.

Do you have serial debugging (or similar) available on the device you
are working with?  If you could provide the output from the debugging
patch below it may help diagnose the issue.

I also got my Acer c720 back, and will run some tests on it.

-Kevin


--- a/src/hw/usb-ehci.c
+++ b/src/hw/usb-ehci.c
@@ -629,6 +629,7 @@ ehci_send_bulk(struct usb_pipe *p, int dir, void *data, int datasize)
             , &pipe->qh, dir, data, datasize);

     // Allocate 4 tds on stack (with required alignment)
+    u32 starttime = timer_calc(0);
     u32 end = timer_calc(usb_xfer_time(p, datasize));
     u8 tdsbuf[sizeof(struct ehci_qtd) * STACKQTDS + EHCI_QTD_ALIGN - 1];
     struct ehci_qtd *tds = (void*)ALIGN((u32)tdsbuf, EHCI_QTD_ALIGN);
@@ -642,7 +643,7 @@ ehci_send_bulk(struct usb_pipe *p, int dir, void *data, int datasize)
         struct ehci_qtd *td = &tds[tdpos++ % STACKQTDS];
         int ret = ehci_wait_td(pipe, td, end);
         if (ret)
-            return -1;
+            goto fail;

         struct ehci_qtd *nexttd_fl = MAKE_FLATPTR(GET_SEG(SS)
                                                  , &tds[tdpos % STACKQTDS]);
@@ -662,10 +663,15 @@ ehci_send_bulk(struct usb_pipe *p, int dir, void *data, int datasize)
         struct ehci_qtd *td = &tds[tdpos++ % STACKQTDS];
         int ret = ehci_wait_td(pipe, td, end);
         if (ret)
-            return -1;
+            goto fail;
     }

     return 0;
+fail:
+    dprintf(1, "timeout: start=%x end=%x cur=%x time=%d devaddr=%x datasize=%d\n"
+            , starttime, end, timer_calc(0)
+            , usb_xfer_time(p, datasize), p->devaddr, datasize);
+    return -1;
 }

 int