diff options
| author | riastradh <riastradh@NetBSD.org> | 2022-09-13 10:32:58 +0000 |
|---|---|---|
| committer | riastradh <riastradh@NetBSD.org> | 2022-09-13 10:32:58 +0000 |
| commit | 339e16bea902e2fc07bfb77563198ddc61045398 (patch) | |
| tree | 2c51cfe689eb36fad75f1a1fe316cfc420e36252 /sys/dev | |
| parent | a50cb576d1c573cb8e6376bc07bd00fb9fe2ad66 (diff) | |
usbdi(9): Sprinkle usbhist into usb xfer timeout logic.
Diffstat (limited to 'sys/dev')
| -rw-r--r-- | sys/dev/usb/usbdi.c | 85 |
1 files changed, 79 insertions, 6 deletions
diff --git a/sys/dev/usb/usbdi.c b/sys/dev/usb/usbdi.c index 28dd31f81c1..fac06b94df4 100644 --- a/sys/dev/usb/usbdi.c +++ b/sys/dev/usb/usbdi.c @@ -1,4 +1,4 @@ -/* $NetBSD: usbdi.c,v 1.246 2022/09/13 10:32:41 riastradh Exp $ */ +/* $NetBSD: usbdi.c,v 1.247 2022/09/13 10:32:58 riastradh Exp $ */ /* * Copyright (c) 1998, 2012, 2015 The NetBSD Foundation, Inc. @@ -32,7 +32,7 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: usbdi.c,v 1.246 2022/09/13 10:32:41 riastradh Exp $"); +__KERNEL_RCSID(0, "$NetBSD: usbdi.c,v 1.247 2022/09/13 10:32:58 riastradh Exp $"); #ifdef _KERNEL_OPT #include "opt_usb.h" @@ -1510,6 +1510,10 @@ usbd_xfer_trycomplete(struct usbd_xfer *xfer) KASSERT(bus->ub_usepolling || mutex_owned(bus->ub_lock)); + USBHIST_FUNC(); + USBHIST_CALLARGS(usbdebug, "xfer %#jx status %jd", + (uintptr_t)xfer, xfer->ux_status, 0, 0); + /* * If software has completed it, either by synchronous abort or * by timeout, too late. @@ -1547,6 +1551,10 @@ usbd_xfer_abort(struct usbd_xfer *xfer) KASSERT(mutex_owned(bus->ub_lock)); + USBHIST_FUNC(); + USBHIST_CALLARGS(usbdebug, "xfer %#jx status %jd", + (uintptr_t)xfer, xfer->ux_status, 0, 0); + /* * If host controller interrupt or timer interrupt has * completed it, too late. But the xfer cannot be @@ -1594,13 +1602,23 @@ usbd_xfer_timeout(void *cookie) /* Acquire the lock so we can transition the timeout state. */ mutex_enter(bus->ub_lock); + USBHIST_FUNC(); + USBHIST_CALLARGS(usbdebug, "xfer %#jx status %jd", + (uintptr_t)xfer, xfer->ux_status, 0, 0); + /* * Use usbd_xfer_probe_timeout to check whether the timeout is * still valid, or to reschedule the callout if necessary. If * it is still valid, schedule the task. */ - if (usbd_xfer_probe_timeout(xfer)) + if (usbd_xfer_probe_timeout(xfer)) { + USBHIST_LOG(usbdebug, "xfer %#jx schedule timeout task", + (uintptr_t)xfer, 0, 0, 0); usb_add_task(dev, &xfer->ux_aborttask, USB_TASKQ_HC); + } else { + USBHIST_LOG(usbdebug, "xfer %#jx timeout cancelled", + (uintptr_t)xfer, 0, 0, 0); + } /* * Notify usbd_xfer_cancel_timeout_async that we may have @@ -1631,6 +1649,10 @@ usbd_xfer_timeout_task(void *cookie) /* Acquire the lock so we can transition the timeout state. */ mutex_enter(bus->ub_lock); + USBHIST_FUNC(); + USBHIST_CALLARGS(usbdebug, "xfer %#jx status %jd", + (uintptr_t)xfer, xfer->ux_status, 0, 0); + /* * Use usbd_xfer_probe_timeout to check whether the timeout is * still valid, or to reschedule the callout if necessary. If @@ -1638,8 +1660,11 @@ usbd_xfer_timeout_task(void *cookie) * cancelled, or the xfer has already been resubmitted -- then * we're done here. */ - if (!usbd_xfer_probe_timeout(xfer)) + if (!usbd_xfer_probe_timeout(xfer)) { + USBHIST_LOG(usbdebug, "xfer %#jx timeout cancelled", + (uintptr_t)xfer, 0, 0, 0); goto out; + } /* * After this point, no further timeout probing will happen for @@ -1656,14 +1681,19 @@ usbd_xfer_timeout_task(void *cookie) * no need to timeout. */ KASSERT(xfer->ux_status != USBD_TIMEOUT); - if (xfer->ux_status != USBD_IN_PROGRESS) + if (xfer->ux_status != USBD_IN_PROGRESS) { + USBHIST_LOG(usbdebug, "xfer %#jx timeout raced", + (uintptr_t)xfer, 0, 0, 0); goto out; + } /* * We beat everyone else. Claim the status as timed out, do * the bus-specific dance to abort the hardware, and complete * the xfer. */ + USBHIST_LOG(usbdebug, "xfer %#jx timed out", + (uintptr_t)xfer, 0, 0, 0); xfer->ux_status = USBD_TIMEOUT; bus->ub_methods->ubm_abortx(xfer); usb_transfer_complete(xfer); @@ -1686,6 +1716,12 @@ usbd_xfer_probe_timeout(struct usbd_xfer *xfer) struct usbd_bus *bus = xfer->ux_bus; bool valid; + USBHIST_FUNC(); + USBHIST_CALLARGS(usbdebug, "xfer %#jx timeout %jdms" + " set %jd reset %jd", + (uintptr_t)xfer, xfer->ux_timeout, + xfer->ux_timeout_set, xfer->ux_timeout_reset); + KASSERT(bus->ub_usepolling || mutex_owned(bus->ub_lock)); /* The timeout must be set. */ @@ -1701,6 +1737,8 @@ usbd_xfer_probe_timeout(struct usbd_xfer *xfer) /* There are a few cases... */ if (bus->ub_methods->ubm_dying(bus)) { /* Host controller dying. Drop it all on the floor. */ + USBHIST_LOG(usbdebug, "xfer %#jx bus dying, not rescheduling", + (uintptr_t)xfer, 0, 0, 0); xfer->ux_timeout_set = false; xfer->ux_timeout_reset = false; valid = false; @@ -1713,11 +1751,17 @@ usbd_xfer_probe_timeout(struct usbd_xfer *xfer) */ xfer->ux_timeout_reset = false; if (xfer->ux_timeout && !bus->ub_usepolling) { + USBHIST_LOG(usbdebug, "xfer %#jx resubmitted," + " rescheduling timer for %jdms", + (uintptr_t)xfer, xfer->ux_timeout, 0, 0); KASSERT(xfer->ux_timeout_set); callout_schedule(&xfer->ux_callout, mstohz(xfer->ux_timeout)); } else { /* No more callout or task scheduled. */ + USBHIST_LOG(usbdebug, "xfer %#jx resubmitted" + " and completed, not rescheduling", + (uintptr_t)xfer, 0, 0, 0); xfer->ux_timeout_set = false; } valid = false; @@ -1728,6 +1772,9 @@ usbd_xfer_probe_timeout(struct usbd_xfer *xfer) * timeout must be unset, and is no longer valid for * the caller. */ + USBHIST_LOG(usbdebug, "xfer %#jx timeout lost race," + " status=%jd, not rescheduling", + (uintptr_t)xfer, xfer->ux_status, 0, 0); xfer->ux_timeout_set = false; valid = false; } else { @@ -1735,6 +1782,8 @@ usbd_xfer_probe_timeout(struct usbd_xfer *xfer) * The xfer has not yet completed, so the timeout is * valid. */ + USBHIST_LOG(usbdebug, "xfer %#jx timing out", + (uintptr_t)xfer, 0, 0, 0); valid = true; } @@ -1783,6 +1832,12 @@ usbd_xfer_schedule_timeout(struct usbd_xfer *xfer) { struct usbd_bus *bus = xfer->ux_bus; + USBHIST_FUNC(); + USBHIST_CALLARGS(usbdebug, "xfer %#jx timeout %jdms" + " set %jd reset %jd", + (uintptr_t)xfer, xfer->ux_timeout, + xfer->ux_timeout_set, xfer->ux_timeout_reset); + KASSERT(bus->ub_usepolling || mutex_owned(bus->ub_lock)); if (xfer->ux_timeout_set) { @@ -1825,13 +1880,22 @@ usbd_xfer_cancel_timeout_async(struct usbd_xfer *xfer) KASSERT(bus->ub_usepolling || mutex_owned(bus->ub_lock)); + USBHIST_FUNC(); + USBHIST_CALLARGS(usbdebug, "xfer %#jx timeout %jdms" + " set %jd reset %jd", + (uintptr_t)xfer, xfer->ux_timeout, + xfer->ux_timeout_set, xfer->ux_timeout_reset); + /* * If the timer wasn't running anyway, forget about it. This * can happen if we are completing an isochronous transfer * which doesn't use the same timeout logic. */ - if (!xfer->ux_timeout_set) + if (!xfer->ux_timeout_set) { + USBHIST_LOG(usbdebug, "xfer %#jx timer not running", + (uintptr_t)xfer, 0, 0, 0); return; + } xfer->ux_timeout_reset = false; if (!callout_stop(&xfer->ux_callout)) { @@ -1839,6 +1903,8 @@ usbd_xfer_cancel_timeout_async(struct usbd_xfer *xfer) * We stopped the callout before it ran. The timeout * is no longer set. */ + USBHIST_LOG(usbdebug, "xfer %#jx timer stopped", + (uintptr_t)xfer, 0, 0, 0); xfer->ux_timeout_set = false; } else if (callout_invoking(&xfer->ux_callout)) { /* @@ -1854,6 +1920,8 @@ usbd_xfer_cancel_timeout_async(struct usbd_xfer *xfer) * cases, the callout will DTRT, so no further action * is needed here. */ + USBHIST_LOG(usbdebug, "xfer %#jx timer fired", + (uintptr_t)xfer, 0, 0, 0); } else if (usb_rem_task(xfer->ux_pipe->up_dev, &xfer->ux_aborttask)) { /* * The callout had fired and scheduled the task, but we @@ -1866,7 +1934,12 @@ usbd_xfer_cancel_timeout_async(struct usbd_xfer *xfer) * xfer->ux_timeout_set is false, or by the callout or * task itself when xfer->ux_timeout_reset is true. */ + USBHIST_LOG(usbdebug, "xfer %#jx task fired", + (uintptr_t)xfer, 0, 0, 0); xfer->ux_timeout_set = false; + } else { + USBHIST_LOG(usbdebug, "xfer %#jx task stopped", + (uintptr_t)xfer, 0, 0, 0); } /* |
