summaryrefslogtreecommitdiff
path: root/sys/dev
diff options
context:
space:
mode:
authorriastradh <riastradh@NetBSD.org>2022-09-13 10:32:58 +0000
committerriastradh <riastradh@NetBSD.org>2022-09-13 10:32:58 +0000
commit339e16bea902e2fc07bfb77563198ddc61045398 (patch)
tree2c51cfe689eb36fad75f1a1fe316cfc420e36252 /sys/dev
parenta50cb576d1c573cb8e6376bc07bd00fb9fe2ad66 (diff)
usbdi(9): Sprinkle usbhist into usb xfer timeout logic.
Diffstat (limited to 'sys/dev')
-rw-r--r--sys/dev/usb/usbdi.c85
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);
}
/*