Source-Changes-HG archive
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index][Old Index]
[src/trunk]: src/sys/dev/usb usbdi(9): Sprinkle usbhist into usb xfer timeout...
details: https://anonhg.NetBSD.org/src/rev/301abdc9b493
branches: trunk
changeset: 370053:301abdc9b493
user: riastradh <riastradh%NetBSD.org@localhost>
date: Tue Sep 13 10:32:58 2022 +0000
description:
usbdi(9): Sprinkle usbhist into usb xfer timeout logic.
diffstat:
sys/dev/usb/usbdi.c | 85 +++++++++++++++++++++++++++++++++++++++++++++++++---
1 files changed, 79 insertions(+), 6 deletions(-)
diffs (237 lines):
diff -r 3319a4c78481 -r 301abdc9b493 sys/dev/usb/usbdi.c
--- a/sys/dev/usb/usbdi.c Tue Sep 13 10:32:41 2022 +0000
+++ b/sys/dev/usb/usbdi.c Tue Sep 13 10:32:58 2022 +0000
@@ -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 @@
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 @@
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 @@
/* 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 @@
/* 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 @@
* 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 @@
* 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 @@
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 @@
/* 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 @@
*/
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 @@
* 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 @@
* 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 @@
{
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 @@
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 @@
* 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 @@
* 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 @@
* 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);
}
/*
Home |
Main Index |
Thread Index |
Old Index