Module Name: src
Committed By: riastradh
Date: Tue Sep 13 10:32:58 UTC 2022
Modified Files:
src/sys/dev/usb: usbdi.c
Log Message:
usbdi(9): Sprinkle usbhist into usb xfer timeout logic.
To generate a diff of this commit:
cvs rdiff -u -r1.246 -r1.247 src/sys/dev/usb/usbdi.c
Please note that diffs are not public domain; they are subject to the
copyright notices on the relevant files.
Modified files:
Index: src/sys/dev/usb/usbdi.c
diff -u src/sys/dev/usb/usbdi.c:1.246 src/sys/dev/usb/usbdi.c:1.247
--- src/sys/dev/usb/usbdi.c:1.246 Tue Sep 13 10:32:41 2022
+++ src/sys/dev/usb/usbdi.c Tue Sep 13 10:32:58 2022
@@ -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 *
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
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
/* 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->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
* 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
* 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_x
{
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 us
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 us
* 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 us
* 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 us
* 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);
}
/*
