On Fri, Jan 01, 2021 at 06:56:21PM +0100, Marcus Glocker wrote:
> It looks like with xhci(4) for some reason the bulk endpoints are
> stalling after some operations, which isn't happening with ehci(4). I
> currently can't see why this happens only with xhci(4). That's why
> on your second attempt you see the timeouts happening, because the bulk
> endpoints still are in a stalled state.
>
> Using usbd_clear_endpoint_stall() at the pipe closing routine simply
> resets all the endpoints, which is why on the next attempt the
> transfers are working fine again. That's probably why this was called
> a workaround, because we should understand why the endpoints are
> getting stalled in a first line with xhci(4).
>
> I can't tell why the issue disappears on your end when you use
> debugging printfs in xhci_device_generic_start(). Looks like a
> timing thing. If you like you can share your xhci(4) debugging diff,
> and I'll check if I can see the same effect here.
In function xhci_device_generic_start() there are three printfs marked
with `XXX slow XXX` comment and in blow diff only last one is commented
out and that one is enough to make the problem go away. I think any of
those tree `slow` printf() instances makes the problem go away.
Please bare in mind `if (MMM_endpt == 0x88)` which narrow some printfs
only to this specific endpoint.
Hope that helps. If you need any more info, please let me know.
diff refs/heads/openbsd refs/heads/xhci-stall
blob - 6a27d3f64101e7f37fc4578e20c0b1f654bce0b8
blob + 74105be6385f36966d91bd01d9d241d22a9d0eb1
--- dev/usb/ugen.c
+++ dev/usb/ugen.c
@@ -270,6 +270,7 @@ ugenopen(dev_t dev, int flag, int mode, struct proc *p
DPRINTFN(5, ("ugenopen: flag=%d, mode=%d, unit=%d endpt=%d\n",
flag, mode, unit, endpt));
+ printf("MMM ===== dv_xname=%s unit=%d endpt=%d [%s()|%s|%d]\n",
sc->sc_dev.dv_xname, unit, endpt, __func__, __FILE_NAME__, __LINE__);
if (sc == NULL || usbd_is_dying(sc->sc_udev))
return (ENXIO);
@@ -481,6 +482,7 @@ ugen_do_read(struct ugen_softc *sc, int endpt, struct
u_char buffer[UGEN_CHUNK];
DPRINTFN(5, ("%s: ugenread: %d\n", sc->sc_dev.dv_xname, endpt));
+ printf("MMM dv_xname=%s endpt=%d [%s()|%s|%d]\n", sc->sc_dev.dv_xname,
endpt, __func__, __FILE_NAME__, __LINE__);
if (usbd_is_dying(sc->sc_udev))
return (EIO);
@@ -499,8 +501,10 @@ ugen_do_read(struct ugen_softc *sc, int endpt, struct
}
#endif
+ printf("MMM dv_xname=%s endpt=%d xfertype=%d [%s()|%s|%d]\n",
sc->sc_dev.dv_xname, endpt, UE_GET_XFERTYPE(sce->edesc->bmAttributes),
__func__, __FILE_NAME__, __LINE__);
switch (UE_GET_XFERTYPE(sce->edesc->bmAttributes)) {
case UE_INTERRUPT:
+ printf("MMM start UE_INTERRUPT [%s()|%s|%d]\n", __func__,
__FILE_NAME__, __LINE__);
/* Block until activity occurred. */
s = splusb();
while (sce->q.c_cc == 0) {
@@ -540,8 +544,10 @@ ugen_do_read(struct ugen_softc *sc, int endpt, struct
if (error)
break;
}
+ printf("MMM end UE_INTERRUPT [%s()|%s|%d]\n", __func__,
__FILE_NAME__, __LINE__);
break;
case UE_BULK:
+ printf("MMM start UE_BULK [%s()|%s|%d]\n", __func__,
__FILE_NAME__, __LINE__);
xfer = usbd_alloc_xfer(sc->sc_udev);
if (xfer == 0)
return (ENOMEM);
@@ -552,10 +558,12 @@ ugen_do_read(struct ugen_softc *sc, int endpt, struct
flags |= USBD_CATCH;
while ((n = ulmin(UGEN_BBSIZE, uio->uio_resid)) != 0) {
DPRINTFN(1, ("ugenread: start transfer %zu bytes\n",n));
+ /* printf("MMM dv_xname=%s endpt=%d n=%zu
[%s()|%s|%d]\n", sc->sc_dev.dv_xname, endpt, n, __func__, __FILE_NAME__,
__LINE__); */
usbd_setup_xfer(xfer, sce->pipeh, 0, buf, n,
flags, sce->timeout, NULL);
err = usbd_transfer(xfer);
if (err) {
+ printf("MMM dv_xname=%s endpt=%d err=%d n=%zu
timeout=%d flags=%d [%s()|%s|%d]\n", sc->sc_dev.dv_xname, endpt, err, n,
sce->timeout, flags, __func__, __FILE_NAME__, __LINE__);
usbd_clear_endpoint_stall(sce->pipeh);
if (err == USBD_INTERRUPTED)
error = EINTR;
@@ -572,8 +580,10 @@ ugen_do_read(struct ugen_softc *sc, int endpt, struct
break;
}
usbd_free_xfer(xfer);
+ printf("MMM end UE_BULK [%s()|%s|%d]\n", __func__,
__FILE_NAME__, __LINE__);
break;
case UE_ISOCHRONOUS:
+ printf("MMM start UE_ISOCHRONOUS [%s()|%s|%d]\n", __func__,
__FILE_NAME__, __LINE__);
s = splusb();
while (sce->cur == sce->fill) {
if (flag & IO_NDELAY) {
@@ -613,6 +623,7 @@ ugen_do_read(struct ugen_softc *sc, int endpt, struct
sce->cur = sce->ibuf;
}
splx(s);
+ printf("MMM end UE_ISOCHRONOUS [%s()|%s|%d]\n", __func__,
__FILE_NAME__, __LINE__);
break;
@@ -631,8 +642,10 @@ ugenread(dev_t dev, struct uio *uio, int flag)
sc = ugen_cd.cd_devs[UGENUNIT(dev)];
+ printf("MMM>> dv_xname=%s endpt=%d flag=%d [%s()|%s|%d]\n",
sc->sc_dev.dv_xname, endpt, flag, __func__, __FILE_NAME__, __LINE__);
sc->sc_refcnt++;
error = ugen_do_read(sc, endpt, uio, flag);
+ printf("MMM<< dv_xname=%s endpt=%d error=%d [%s()|%s|%d]\n",
sc->sc_dev.dv_xname, endpt, error, __func__, __FILE_NAME__, __LINE__);
if (--sc->sc_refcnt < 0)
usb_detach_wakeup(&sc->sc_dev);
return (error);
blob - ecb17c3bf4ff58b0c1ccd3869d2f8b30195b7536
blob + 73161eff85ce058466822b609992e08306642c5e
--- dev/usb/usbdi.c
+++ dev/usb/usbdi.c
@@ -306,8 +306,10 @@ usbd_transfer(struct usbd_xfer *xfer)
printf("usbd_transfer: has old buffer!\n");
#endif
err = usb_allocmem(bus, xfer->length, 0, 0, &xfer->dmabuf);
- if (err)
+ if (err) {
+ printf("MMM polling=%d flags=%d running=%d
usb_allocmem/err=%d [%s()|%s|%d]\n", polling, xfer->flags, pipe->running, err,
__func__, __FILE_NAME__, __LINE__);
return (err);
+ }
xfer->rqflags |= URQ_AUTO_DMABUF;
}
@@ -327,12 +329,20 @@ usbd_transfer(struct usbd_xfer *xfer)
}
}
- if (!(xfer->flags & USBD_SYNCHRONOUS))
+ if (!(xfer->flags & USBD_SYNCHRONOUS)) {
+ /* printf("MMM polling=%d err=%d xfer->flags=%d
non-USBD_SYNCHRONOUS [%s()|%s|%d]\n", polling, err, xfer->flags, __func__,
__FILE_NAME__, __LINE__); */
return (err);
+ }
+ if (xfer->status != USBD_NOT_STARTED && xfer->status !=
USBD_IN_PROGRESS) {
+ /* printf("MMM polling=%d xfer->flags=%d xfer->status=%d err=%d
[%s()|%s|%d]\n", polling, xfer->flags, xfer->status, err, __func__,
__FILE_NAME__, __LINE__); */
+ }
+
/* Sync transfer, wait for completion. */
- if (err != USBD_IN_PROGRESS)
+ if (err != USBD_IN_PROGRESS) {
+ /* printf("MMM polling=%d err=%d err!=USBD_IN_PROGRESS
[%s()|%s|%d]\n", polling, err, __func__, __FILE_NAME__, __LINE__); */
return (err);
+ }
s = splusb();
if (polling) {
@@ -352,6 +362,7 @@ usbd_transfer(struct usbd_xfer *xfer)
}
if (timo < 0) {
+ printf("MMM polling=%d timeout [%s()|%s|%d]\n",
polling, __func__, __FILE_NAME__, __LINE__);
xfer->status = USBD_TIMEOUT;
usb_transfer_complete(xfer);
}
@@ -360,15 +371,23 @@ usbd_transfer(struct usbd_xfer *xfer)
flags = PRIBIO|(xfer->flags & USBD_CATCH ? PCATCH : 0);
err = tsleep_nsec(xfer, flags, "usbsyn", INFSLP);
+ if (xfer->status != USBD_NOT_STARTED && xfer->status !=
USBD_NORMAL_COMPLETION) {
+ printf("MMM ! polling=%d flags=%d err=%d xfer->flags=%d
xfer->status=%d xfer->done=%d [%s()|%s|%d]\n", polling, flags, err,
xfer->flags, xfer->status, xfer->done, __func__, __FILE_NAME__, __LINE__);
+ }
if (err && !xfer->done) {
usbd_abort_pipe(pipe);
- if (err == EINTR)
+ if (err == EINTR) {
xfer->status = USBD_INTERRUPTED;
- else
+ } else {
+ printf("MMM polling=%d timeout
[%s()|%s|%d]\n", polling, __func__, __FILE_NAME__, __LINE__);
xfer->status = USBD_TIMEOUT;
+ }
}
}
}
+ if (xfer->status != USBD_NORMAL_COMPLETION) {
+ printf("MMM final polling=%d xfer->flags=%d xfer->status=%d
[%s()|%s|%d]\n", polling, xfer->flags, xfer->status, __func__, __FILE_NAME__,
__LINE__);
+ }
splx(s);
return (xfer->status);
}
@@ -716,7 +735,13 @@ usb_transfer_complete(struct usbd_xfer *xfer)
struct usbd_bus *bus = pipe->device->bus;
int polling = bus->use_polling;
int status, flags;
+/*
+ int MMM_endpt = xfer->pipe->endpoint->edesc->bEndpointAddress;
+ if (MMM_endpt == 0x88) {
+ printf("MMM xHCI endpt=0x%x polling=%d [%s()|%s|%d]\n",
MMM_endpt, polling, __func__, __FILE_NAME__, __LINE__);
+ }
+*/
#if 0
/* XXX ohci_intr1() calls usb_transfer_complete() for RHSC. */
splsoftassert(IPL_SOFTUSB);
@@ -735,13 +760,12 @@ usb_transfer_complete(struct usbd_xfer *xfer)
if (polling)
pipe->running = 0;
-#ifdef DIAGNOSTIC
if (xfer->actlen > xfer->length) {
printf("%s: actlen > len %u > %u\n", __func__, xfer->actlen,
xfer->length);
+ KASSERT(xfer->actlen <= xfer->length);
xfer->actlen = xfer->length;
}
-#endif
if (usbd_xfer_isread(xfer) && xfer->actlen != 0 &&
(xfer->flags & USBD_NO_COPY) == 0)
blob - a016dd0e68da3fff63476e576fe48db816c810bc
blob + 0c1bd1709db4d44cbeb38c41198d2ebfcbed458e
--- dev/usb/xhci.c
+++ dev/usb/xhci.c
@@ -2328,12 +2328,17 @@ xhci_timeout(void *addr)
{
struct usbd_xfer *xfer = addr;
struct xhci_softc *sc = (struct xhci_softc *)xfer->device->bus;
+ int MMM_endpt = xfer->pipe->endpoint->edesc->bEndpointAddress;
if (sc->sc_bus.dying) {
xhci_timeout_task(addr);
return;
}
+ if (MMM_endpt == 0x88) {
+ printf("MMM xHCI endpt=0x%x [%s()|%s|%d]\n", MMM_endpt,
__func__, __FILE_NAME__, __LINE__);
+ }
+
usb_init_task(&xfer->abort_task, xhci_timeout_task, addr,
USB_TASK_TYPE_ABORT);
usb_add_task(xfer->device, &xfer->abort_task);
@@ -2343,9 +2348,18 @@ void
xhci_timeout_task(void *addr)
{
struct usbd_xfer *xfer = addr;
+ struct usbd_xfer *xfer_loop;
int s;
+ int MMM_endpt = xfer->pipe->endpoint->edesc->bEndpointAddress;
s = splusb();
+ if (MMM_endpt == 0x88) {
+ printf("MMM xHCI endpt=0x%x [%s()|%s|%d]\n", MMM_endpt,
__func__, __FILE_NAME__, __LINE__);
+ printf("%s: pipe=%p xfer=%p\n", __func__, xfer->pipe, xfer);
+ SIMPLEQ_FOREACH(xfer_loop, &xfer->pipe->queue, next) {
+ printf(" xfer=%p\n", xfer_loop);
+ }
+ }
xhci_abort_xfer(xfer, USBD_TIMEOUT);
splx(s);
}
@@ -2945,10 +2959,13 @@ usbd_status
xhci_device_generic_transfer(struct usbd_xfer *xfer)
{
usbd_status err;
+ int MMM_endpt = xfer->pipe->endpoint->edesc->bEndpointAddress;
err = usb_insert_transfer(xfer);
- if (err)
+ if (err) {
+ printf("MMM xHCI endpt=0x%x err=%d [%s()|%s|%d]\n", MMM_endpt,
err, __func__, __FILE_NAME__, __LINE__);
return (err);
+ }
return (xhci_device_generic_start(SIMPLEQ_FIRST(&xfer->pipe->queue)));
}
@@ -2964,6 +2981,7 @@ xhci_device_generic_start(struct usbd_xfer *xfer)
uint64_t paddr = DMAADDR(&xfer->dmabuf, 0);
uint8_t toggle;
int s, i, ntrb, zerotd = 0;
+ int MMM_endpt = xfer->pipe->endpoint->edesc->bEndpointAddress;
KASSERT(!(xfer->rqflags & URQ_REQUEST));
@@ -2972,6 +2990,12 @@ xhci_device_generic_start(struct usbd_xfer *xfer)
/* How many TRBs do we need for this transfer? */
ntrb = howmany(xfer->length, XHCI_TRB_MAXSIZE);
+ /* XXX slow XXX */
+/*
+ if (MMM_endpt == 0x88) {
+ printf("MMM xHCI endpt=0x%x xfer->status=%d ntrb=%d
[%s()|%s|%d]\n", MMM_endpt, xfer->status, ntrb, __func__, __FILE_NAME__,
__LINE__);
+ }
+*/
/* If the buffer crosses a 64k boundary, we need one more. */
len = XHCI_TRB_MAXSIZE - (paddr & (XHCI_TRB_MAXSIZE - 1));
@@ -2979,11 +3003,18 @@ xhci_device_generic_start(struct usbd_xfer *xfer)
ntrb = howmany(xfer->length - len, XHCI_TRB_MAXSIZE) + 1;
else
len = xfer->length;
-
+ /* XXX slow XXX */
+/*
+ if (MMM_endpt == 0x88) {
+ printf("MMM xHCI endpt=0x%x xfer->status=%d ntrb=%d len=%d
xfer->length=%d [%s()|%s|%d]\n", MMM_endpt, xfer->status, ntrb, len,
xfer->length, __func__, __FILE_NAME__, __LINE__);
+ }
+*/
/* If we need to append a zero length packet, we need one more. */
if ((xfer->flags & USBD_FORCE_SHORT_XFER || xfer->length == 0) &&
- (xfer->length % UE_GET_SIZE(mps) == 0))
+ (xfer->length % UE_GET_SIZE(mps) == 0)) {
zerotd = 1;
+ printf("MMM xHCI endpt=0x%x xfer->status=%d ntrb=%d len=%d
xfer->length=%d zerotd=%d [%s()|%s|%d]\n", MMM_endpt, xfer->status, ntrb, len,
xfer->length, zerotd, __func__, __FILE_NAME__, __LINE__);
+ }
if (xp->free_trbs < (ntrb + zerotd))
return (USBD_NOMEM);
@@ -3066,6 +3097,11 @@ xhci_device_generic_start(struct usbd_xfer *xfer)
}
splx(s);
+ /* XXX slow XXX */
+ if (MMM_endpt == 0x88) {
+ printf("MMM xHCI endpt=0x%x xfer->status=%d [%s()|%s|%d]\n",
MMM_endpt, xfer->status, __func__, __FILE_NAME__, __LINE__);
+ }
+
return (USBD_IN_PROGRESS);
}
--
Regards,
Mikolaj
