Module Name: src Committed By: skrll Date: Fri Sep 12 16:40:38 UTC 2014
Modified Files: src/sys/dev/usb: ehci.c files.usb if_smsc.c umass.c umass_isdata.c umass_quirks.c umass_scsipi.c usb.c usb.h usb_mem.c usb_quirks.c usb_subr.c usbdi.c usbdi_util.c uvideo.c src/sys/external/bsd/dwc2/conf: files.dwc2 Added Files: src/sys/dev/usb: usbhist.h Log Message: Improve USB debugging with USBHIST based on KERNHIST. Convert some DPRINTFs to USBHIST_LOG and allow usbdebug, ehcidebug and umassdebug to be changed via sysctl. Remove the #define mess in usb.h. This was started by mrg@ and updated by reinoud@ To generate a diff of this commit: cvs rdiff -u -r1.228 -r1.229 src/sys/dev/usb/ehci.c cvs rdiff -u -r1.133 -r1.134 src/sys/dev/usb/files.usb cvs rdiff -u -r1.19 -r1.20 src/sys/dev/usb/if_smsc.c cvs rdiff -u -r1.148 -r1.149 src/sys/dev/usb/umass.c cvs rdiff -u -r1.29 -r1.30 src/sys/dev/usb/umass_isdata.c cvs rdiff -u -r1.95 -r1.96 src/sys/dev/usb/umass_quirks.c cvs rdiff -u -r1.48 -r1.49 src/sys/dev/usb/umass_scsipi.c cvs rdiff -u -r1.155 -r1.156 src/sys/dev/usb/usb.c cvs rdiff -u -r1.109 -r1.110 src/sys/dev/usb/usb.h cvs rdiff -u -r1.64 -r1.65 src/sys/dev/usb/usb_mem.c cvs rdiff -u -r1.80 -r1.81 src/sys/dev/usb/usb_quirks.c cvs rdiff -u -r1.196 -r1.197 src/sys/dev/usb/usb_subr.c cvs rdiff -u -r1.161 -r1.162 src/sys/dev/usb/usbdi.c cvs rdiff -u -r1.62 -r1.63 src/sys/dev/usb/usbdi_util.c cvs rdiff -u -r0 -r1.1 src/sys/dev/usb/usbhist.h cvs rdiff -u -r1.40 -r1.41 src/sys/dev/usb/uvideo.c cvs rdiff -u -r1.1 -r1.2 src/sys/external/bsd/dwc2/conf/files.dwc2 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/ehci.c diff -u src/sys/dev/usb/ehci.c:1.228 src/sys/dev/usb/ehci.c:1.229 --- src/sys/dev/usb/ehci.c:1.228 Tue Aug 5 10:33:46 2014 +++ src/sys/dev/usb/ehci.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: ehci.c,v 1.228 2014/08/05 10:33:46 skrll Exp $ */ +/* $NetBSD: ehci.c,v 1.229 2014/09/12 16:40:38 skrll Exp $ */ /* * Copyright (c) 2004-2012 The NetBSD Foundation, Inc. @@ -53,53 +53,70 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: ehci.c,v 1.228 2014/08/05 10:33:46 skrll Exp $"); +__KERNEL_RCSID(0, "$NetBSD: ehci.c,v 1.229 2014/09/12 16:40:38 skrll Exp $"); #include "ohci.h" #include "uhci.h" +#include "opt_usb.h" #include <sys/param.h> -#include <sys/systm.h> + +#include <sys/bus.h> +#include <sys/cpu.h> +#include <sys/device.h> #include <sys/kernel.h> #include <sys/kmem.h> -#include <sys/device.h> -#include <sys/select.h> +#include <sys/mutex.h> #include <sys/proc.h> #include <sys/queue.h> -#include <sys/mutex.h> -#include <sys/bus.h> -#include <sys/cpu.h> +#include <sys/select.h> +#include <sys/sysctl.h> +#include <sys/systm.h> #include <machine/endian.h> #include <dev/usb/usb.h> #include <dev/usb/usbdi.h> #include <dev/usb/usbdivar.h> +#include <dev/usb/usbhist.h> #include <dev/usb/usb_mem.h> #include <dev/usb/usb_quirks.h> +#include <dev/usb/usbroothub_subr.h> #include <dev/usb/ehcireg.h> #include <dev/usb/ehcivar.h> -#include <dev/usb/usbroothub_subr.h> #ifdef EHCI_DEBUG -static void __printflike(1, 2) -ehciprintf(const char *fmt, ...) +static int ehcidebug = 0; + +SYSCTL_SETUP(sysctl_hw_ehci_setup, "sysctl hw.ehci setup") { - va_list ap; + int err; + const struct sysctlnode *rnode; + const struct sysctlnode *cnode; + + err = sysctl_createv(clog, 0, NULL, &rnode, + CTLFLAG_PERMANENT, CTLTYPE_NODE, "ehci", + SYSCTL_DESCR("ehci global controls"), + NULL, 0, NULL, 0, CTL_HW, CTL_CREATE, CTL_EOL); + + if (err) + goto fail; - va_start(ap, fmt); - vprintf(fmt, ap); - va_end(ap); + /* control debugging printfs */ + err = sysctl_createv(clog, 0, &rnode, &cnode, + CTLFLAG_PERMANENT|CTLFLAG_READWRITE, CTLTYPE_INT, + "debug", SYSCTL_DESCR("Enable debugging output"), + NULL, 0, &ehcidebug, sizeof(ehcidebug), CTL_CREATE, CTL_EOL); + if (err) + goto fail; + + return; +fail: + aprint_error("%s: sysctl_createv failed (err = %d)\n", __func__, err); } -#define DPRINTF(x) do { if (ehcidebug) ehciprintf x; } while(0) -#define DPRINTFN(n,x) do { if (ehcidebug>(n)) ehciprintf x; } while (0) -int ehcidebug = 0; -#else -#define DPRINTF(x) -#define DPRINTFN(n,x) -#endif +#endif /* EHCI_DEBUG */ struct ehci_pipe { struct usbd_pipe pipe; @@ -228,22 +245,20 @@ Static void ehci_close_pipe(usbd_pipe_h Static void ehci_abort_xfer(usbd_xfer_handle, usbd_status); #ifdef EHCI_DEBUG -Static void ehci_dump_regs(ehci_softc_t *); -void ehci_dump(void); Static ehci_softc_t *theehci; -Static void ehci_dump_link(ehci_link_t, int); +void ehci_dump(void); +#endif + +#ifdef EHCI_DEBUG +Static void ehci_dump_regs(ehci_softc_t *); Static void ehci_dump_sqtds(ehci_soft_qtd_t *); Static void ehci_dump_sqtd(ehci_soft_qtd_t *); Static void ehci_dump_qtd(ehci_qtd_t *); Static void ehci_dump_sqh(ehci_soft_qh_t *); -#if notyet Static void ehci_dump_sitd(struct ehci_soft_itd *itd); Static void ehci_dump_itd(struct ehci_soft_itd *); -#endif -#ifdef DIAGNOSTIC Static void ehci_dump_exfer(struct ehci_xfer *); #endif -#endif #define EHCI_NULL htole32(EHCI_LINK_TERMINATE) @@ -344,7 +359,7 @@ ehci_init(ehci_softc_t *sc) ehci_soft_qh_t *sqh; u_int ncomp; - DPRINTF(("ehci_init: start\n")); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); #ifdef EHCI_DEBUG theehci = sc; #endif @@ -371,7 +386,7 @@ ehci_init(ehci_softc_t *sc) vers >> 8, vers & 0xff); sparams = EREAD4(sc, EHCI_HCSPARAMS); - DPRINTF(("ehci_init: sparams=0x%x\n", sparams)); + USBHIST_LOG(ehcidebug, "sparams=%#x", sparams, 0, 0, 0); sc->sc_npcomp = EHCI_HCS_N_PCC(sparams); ncomp = EHCI_HCS_N_CC(sparams); if (ncomp != sc->sc_ncomp) { @@ -396,7 +411,7 @@ ehci_init(ehci_softc_t *sc) } sc->sc_noport = EHCI_HCS_N_PORTS(sparams); cparams = EREAD4(sc, EHCI_HCCPARAMS); - DPRINTF(("ehci_init: cparams=0x%x\n", cparams)); + USBHIST_LOG(ehcidebug, "cparams=%#x", cparams, 0, 0, 0); sc->sc_hasppc = EHCI_HCS_PPC(sparams); if (EHCI_HCC_64BIT(cparams)) { @@ -410,7 +425,7 @@ ehci_init(ehci_softc_t *sc) USB_MEM_RESERVE); /* Reset the controller */ - DPRINTF(("%s: resetting\n", device_xname(sc->sc_dev))); + USBHIST_LOG(ehcidebug, "resetting", 0, 0, 0, 0); EOWRITE4(sc, EHCI_USBCMD, 0); /* Halt controller */ usb_delay_ms(&sc->sc_bus, 1); EOWRITE4(sc, EHCI_USBCMD, EHCI_CMD_HCRESET); @@ -452,7 +467,7 @@ ehci_init(ehci_softc_t *sc) EHCI_FLALIGN_ALIGN, &sc->sc_fldma); if (err) return (err); - DPRINTF(("%s: flsize=%d\n", device_xname(sc->sc_dev),sc->sc_flsize)); + USBHIST_LOG(ehcidebug, "flsize=%d", sc->sc_flsize, 0, 0, 0); sc->sc_flist = KERNADDR(&sc->sc_fldma, 0); for (i = 0; i < sc->sc_flsize; i++) { @@ -542,9 +557,7 @@ ehci_init(ehci_softc_t *sc) usb_syncmem(&sqh->dma, sqh->offs, sizeof(sqh->qh), BUS_DMASYNC_PREWRITE | BUS_DMASYNC_PREREAD); #ifdef EHCI_DEBUG - if (ehcidebug) { - ehci_dump_sqh(sqh); - } + ehci_dump_sqh(sqh); #endif /* Point to async list */ @@ -576,7 +589,7 @@ ehci_init(ehci_softc_t *sc) } /* Enable interrupts */ - DPRINTFN(1,("ehci_init: enabling\n")); + USBHIST_LOG(ehcidebug, "enabling interupts", 0, 0, 0, 0); EOWRITE4(sc, EHCI_USBINTR, sc->sc_eintrs); return (USBD_NORMAL_COMPLETION); @@ -596,6 +609,8 @@ ehci_intr(void *v) ehci_softc_t *sc = v; int ret = 0; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + if (sc == NULL) return 0; @@ -611,7 +626,8 @@ ehci_intr(void *v) if (intrs) EOWRITE4(sc, EHCI_USBSTS, intrs); /* Acknowledge */ #ifdef DIAGNOSTIC - DPRINTFN(16, ("ehci_intr: ignored interrupt while polling\n")); + USBHIST_LOGN(ehcidebug, 16, + "ignored interrupt while polling", 0, 0, 0, 0); #endif goto done; } @@ -628,7 +644,7 @@ ehci_intr1(ehci_softc_t *sc) { u_int32_t intrs, eintrs; - DPRINTFN(20,("ehci_intr1: enter\n")); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); /* In case the interrupt occurs before initialization has completed. */ if (sc == NULL) { @@ -645,16 +661,15 @@ ehci_intr1(ehci_softc_t *sc) return (0); eintrs = intrs & sc->sc_eintrs; - DPRINTFN(7, ("ehci_intr1: sc=%p intrs=0x%x(0x%x) eintrs=0x%x\n", - sc, (u_int)intrs, EOREAD4(sc, EHCI_USBSTS), - (u_int)eintrs)); + USBHIST_LOG(ehcidebug, "sc=%p intrs=%#x(%#x) eintrs=%#x", + sc, intrs, EOREAD4(sc, EHCI_USBSTS), eintrs); if (!eintrs) return (0); EOWRITE4(sc, EHCI_USBSTS, intrs); /* Acknowledge */ sc->sc_bus.no_intrs++; if (eintrs & EHCI_STS_IAA) { - DPRINTF(("ehci_intr1: door bell\n")); + USBHIST_LOG(ehcidebug, "door bell", 0, 0, 0, 0); kpreempt_disable(); KASSERT(sc->sc_doorbell_si != NULL); softint_schedule(sc->sc_doorbell_si); @@ -662,9 +677,9 @@ ehci_intr1(ehci_softc_t *sc) eintrs &= ~EHCI_STS_IAA; } if (eintrs & (EHCI_STS_INT | EHCI_STS_ERRINT)) { - DPRINTFN(5,("ehci_intr1: %s %s\n", - eintrs & EHCI_STS_INT ? "INT" : "", - eintrs & EHCI_STS_ERRINT ? "ERRINT" : "")); + USBHIST_LOG(ehcidebug, "INT=%d ERRINT=%d", + eintrs & EHCI_STS_INT ? 1 : 0, + eintrs & EHCI_STS_ERRINT ? 1 : 0, 0, 0); usb_schedsoftintr(&sc->sc_bus); eintrs &= ~(EHCI_STS_INT | EHCI_STS_ERRINT); } @@ -710,6 +725,8 @@ ehci_pcd(void *addr) u_char *p; int i, m; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + mutex_enter(&sc->sc_lock); xfer = sc->sc_intrxfer; @@ -725,8 +742,10 @@ ehci_pcd(void *addr) /* Pick out CHANGE bits from the status reg. */ if (EOREAD4(sc, EHCI_PORTSC(i)) & EHCI_PS_CLEAR) p[i/8] |= 1 << (i%8); + if (i % 8 == 7) + USBHIST_LOG(ehcidebug, "change(%d)=0x%02x", i / 8, + p[i/8], 0, 0); } - DPRINTF(("ehci_pcd: change=0x%02x\n", *p)); xfer->actlen = xfer->length; xfer->status = USBD_NORMAL_COMPLETION; @@ -745,7 +764,7 @@ ehci_softintr(void *v) KASSERT(sc->sc_bus.use_polling || mutex_owned(&sc->sc_lock)); - DPRINTFN(10,("%s: ehci_softintr\n", device_xname(sc->sc_dev))); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); /* * The only explanation I can think of for why EHCI is as brain dead @@ -776,7 +795,8 @@ ehci_check_intr(ehci_softc_t *sc, struct { int attr; - DPRINTFN(/*15*/2, ("ehci_check_intr: ex=%p\n", ex)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + USBHIST_LOG(ehcidebug, "ex = %p", ex, 0, 0, 0); KASSERT(sc->sc_bus.use_polling || mutex_owned(&sc->sc_lock)); @@ -795,6 +815,8 @@ ehci_check_qh_intr(ehci_softc_t *sc, str ehci_soft_qtd_t *sqtd, *lsqtd; __uint32_t status; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + KASSERT(sc->sc_bus.use_polling || mutex_owned(&sc->sc_lock)); if (ex->sqtdstart == NULL) { @@ -823,7 +845,7 @@ ehci_check_qh_intr(ehci_softc_t *sc, str lsqtd->offs + offsetof(ehci_qtd_t, qtd_status), sizeof(lsqtd->qtd.qtd_status), BUS_DMASYNC_PREREAD); if (status & EHCI_QTD_ACTIVE) { - DPRINTFN(12, ("ehci_check_intr: active ex=%p\n", ex)); + USBHIST_LOGN(ehcidebug, 10, "active ex=%p", ex, 0, 0, 0); for (sqtd = ex->sqtdstart; sqtd != lsqtd; sqtd=sqtd->nextqtd) { usb_syncmem(&sqtd->dma, sqtd->offs + offsetof(ehci_qtd_t, qtd_status), @@ -860,12 +882,12 @@ ehci_check_qh_intr(ehci_softc_t *sc, str goto done; } } - DPRINTFN(12, ("ehci_check_intr: ex=%p std=%p still active\n", - ex, ex->sqtdstart)); + USBHIST_LOGN(ehcidebug, 10, "ex=%p std=%p still active", + ex, ex->sqtdstart, 0, 0); return; } done: - DPRINTFN(12, ("ehci_check_intr: ex=%p done\n", ex)); + USBHIST_LOGN(ehcidebug, 10, "ex=%p done", ex, 0, 0, 0); callout_stop(&ex->xfer.timeout_handle); ehci_idone(ex); } @@ -876,6 +898,8 @@ ehci_check_itd_intr(ehci_softc_t *sc, st ehci_soft_itd_t *itd; int i; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + KASSERT(mutex_owned(&sc->sc_lock)); if (&ex->xfer != SIMPLEQ_FIRST(&ex->xfer.pipe->queue)) @@ -911,11 +935,11 @@ ehci_check_itd_intr(ehci_softc_t *sc, st goto done; /* All 8 descriptors inactive, it's done */ } - DPRINTFN(12, ("ehci_check_itd_intr: ex %p itd %p still active\n", ex, - ex->itdstart)); + USBHIST_LOGN(ehcidebug, 10, "ex %p itd %p still active", ex, + ex->itdstart, 0, 0); return; done: - DPRINTFN(12, ("ehci_check_itd_intr: ex=%p done\n", ex)); + USBHIST_LOG(ehcidebug, "ex %p done", ex, 0, 0, 0); callout_stop(&ex->xfer.timeout_handle); ehci_idone(ex); } @@ -930,9 +954,11 @@ ehci_idone(struct ehci_xfer *ex) u_int32_t status = 0, nstatus = 0; int actlen; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + KASSERT(sc->sc_bus.use_polling || mutex_owned(&sc->sc_lock)); - DPRINTFN(/*12*/2, ("ehci_idone: ex=%p\n", ex)); + USBHIST_LOG(ehcidebug, "ex=%p", ex, 0, 0, 0); #ifdef DIAGNOSTIC if (ex->isdone) { @@ -947,14 +973,13 @@ ehci_idone(struct ehci_xfer *ex) if (xfer->status == USBD_CANCELLED || xfer->status == USBD_TIMEOUT) { - DPRINTF(("ehci_idone: aborted xfer=%p\n", xfer)); + USBHIST_LOG(ehcidebug, "aborted xfer=%p", xfer, 0, 0, 0); return; } + USBHIST_LOG(ehcidebug, "xfer=%p, pipe=%p ready", xfer, epipe, 0, 0); #ifdef EHCI_DEBUG - DPRINTFN(/*10*/2, ("ehci_idone: xfer=%p, pipe=%p ready\n", xfer, epipe)); - if (ehcidebug > 10) - ehci_dump_sqtds(ex->sqtdstart); + ehci_dump_sqtds(ex->sqtdstart); #endif /* The transfer is done, compute actual length and status. */ @@ -1030,8 +1055,9 @@ ehci_idone(struct ehci_xfer *ex) */ if ((sqtd != lsqtd->nextqtd || EHCI_QTD_GET_BYTES(status)) && xfer->pipe->device->default_pipe != xfer->pipe) { - DPRINTFN(2, ("ehci_idone: need toggle update " - "status=%08x nstatus=%08x\n", status, nstatus)); + USBHIST_LOG(ehcidebug, + "toggle update status=0x%08x nstatus=0x%08x", + status, nstatus, 0, 0); #if 0 ehci_dump_sqh(epipe->sqh); ehci_dump_sqtds(ex->sqtdstart); @@ -1039,28 +1065,33 @@ ehci_idone(struct ehci_xfer *ex) epipe->nexttoggle = EHCI_QTD_GET_TOGGLE(nstatus); } - DPRINTFN(/*10*/2, ("ehci_idone: len=%d, actlen=%d, status=0x%x\n", - xfer->length, actlen, status)); + USBHIST_LOG(ehcidebug, "len=%d actlen=%d status=0x%08x", xfer->length, + actlen, status, 0); xfer->actlen = actlen; if (status & EHCI_QTD_HALTED) { #ifdef EHCI_DEBUG - char sbuf[128]; - - snprintb(sbuf, sizeof(sbuf), - "\20\10ACTIVE\7HALTED\6BUFERR\5BABBLE" - "\4XACTERR\3MISSED\2SPLIT\1PING", - (u_int32_t)status); - - DPRINTFN(2, ("%s: error, addr=%d, endpt=0x%02x, " - "cerr=%d pid=%d stat=%s\n", __func__, + USBHIST_LOG(ehcidebug, "halted addr=%d endpt=0x%02x", xfer->pipe->device->address, - xfer->pipe->endpoint->edesc->bEndpointAddress, - EHCI_QTD_GET_CERR(status), EHCI_QTD_GET_PID(status), sbuf)); + xfer->pipe->endpoint->edesc->bEndpointAddress, 0, 0); + USBHIST_LOG(ehcidebug, "cerr=%d pid=%d stat=%#x", + EHCI_QTD_GET_CERR(status), EHCI_QTD_GET_PID(status), + status, 0); + USBHIST_LOG(ehcidebug, + "ACTIVE =%d HALTED=%d BUFERR=%d BABBLE=%d", + status & EHCI_QTD_ACTIVE ? 1 : 0, + status & EHCI_QTD_HALTED ? 1 : 0, + status & EHCI_QTD_BUFERR ? 1 : 0, + status & EHCI_QTD_BABBLE ? 1 : 0); + + USBHIST_LOG(ehcidebug, + "XACTERR=%d MISSED=%d SPLIT =%d PING =%d", + status & EHCI_QTD_XACTERR ? 1 : 0, + status & EHCI_QTD_MISSEDMICRO ? 1 : 0, + status & EHCI_QTD_SPLITXSTATE ? 1 : 0, + status & EHCI_QTD_PINGSTATE ? 1 : 0); - if (ehcidebug > 2) { - ehci_dump_sqh(epipe->sqh); - ehci_dump_sqtds(ex->sqtdstart); - } + ehci_dump_sqh(epipe->sqh); + ehci_dump_sqtds(ex->sqtdstart); #endif /* low&full speed has an extra error flag */ if (EHCI_QH_GET_EPS(epipe->sqh->qh.qh_endp) != @@ -1088,7 +1119,7 @@ ehci_idone(struct ehci_xfer *ex) * during this call, before methods->done is called: dma sync required * beforehand? */ usb_transfer_complete(xfer); - DPRINTFN(/*12*/2, ("ehci_idone: ex=%p done\n", ex)); + USBHIST_LOG(ehcidebug, "ex=%p done", ex, 0, 0, 0); } /* @@ -1102,6 +1133,8 @@ ehci_waitintr(ehci_softc_t *sc, usbd_xfe int timo; u_int32_t intrs; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + xfer->status = USBD_IN_PROGRESS; for (timo = xfer->timeout; timo >= 0; timo--) { usb_delay_ms(&sc->sc_bus, 1); @@ -1109,7 +1142,7 @@ ehci_waitintr(ehci_softc_t *sc, usbd_xfe break; intrs = EHCI_STS_INTRS(EOREAD4(sc, EHCI_USBSTS)) & sc->sc_eintrs; - DPRINTFN(15,("ehci_waitintr: 0x%04x\n", intrs)); + USBHIST_LOG(ehcidebug, "0x%04x", intrs, 0, 0, 0); #ifdef EHCI_DEBUG if (ehcidebug > 15) ehci_dump_regs(sc); @@ -1124,7 +1157,7 @@ ehci_waitintr(ehci_softc_t *sc, usbd_xfe } /* Timeout */ - DPRINTF(("ehci_waitintr: timeout\n")); + USBHIST_LOG(ehcidebug, "timeout", 0, 0, 0, 0); xfer->status = USBD_TIMEOUT; mutex_enter(&sc->sc_lock); usb_transfer_complete(xfer); @@ -1136,12 +1169,15 @@ Static void ehci_poll(struct usbd_bus *bus) { ehci_softc_t *sc = bus->hci_private; + + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + #ifdef EHCI_DEBUG static int last; int new; new = EHCI_STS_INTRS(EOREAD4(sc, EHCI_USBSTS)); if (new != last) { - DPRINTFN(10,("ehci_poll: intrs=0x%04x\n", new)); + USBHIST_LOG(ehcidebug, "intrs=0x%04x", new, 0, 0, 0); last = new; } #endif @@ -1167,6 +1203,8 @@ ehci_detach(struct ehci_softc *sc, int f { int rv = 0; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + if (sc->sc_child != NULL) rv = config_detach(sc->sc_child, flags); @@ -1232,6 +1270,8 @@ ehci_suspend(device_t dv, const pmf_qual int i; uint32_t cmd, hcr; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + mutex_spin_enter(&sc->sc_intr_lock); sc->sc_bus.use_polling++; mutex_spin_exit(&sc->sc_intr_lock); @@ -1284,6 +1324,8 @@ ehci_resume(device_t dv, const pmf_qual_ int i; uint32_t cmd, hcr; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + /* restore things in case the bios sucks */ EOWRITE4(sc, EHCI_CTRLDSSEGMENT, 0); EOWRITE4(sc, EHCI_PERIODICLISTBASE, DMAADDR(&sc->sc_fldma, 0)); @@ -1340,7 +1382,8 @@ ehci_shutdown(device_t self, int flags) { ehci_softc_t *sc = device_private(self); - DPRINTF(("ehci_shutdown: stopping the HC\n")); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + EOWRITE4(sc, EHCI_USBCMD, 0); /* Halt controller */ EOWRITE4(sc, EHCI_USBCMD, EHCI_CMD_HCRESET); return true; @@ -1429,8 +1472,10 @@ ehci_device_clear_toggle(usbd_pipe_handl { struct ehci_pipe *epipe = (struct ehci_pipe *)pipe; - DPRINTF(("ehci_device_clear_toggle: epipe=%p status=0x%x\n", - epipe, epipe->sqh->qh.qh_qtd.qtd_status)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "epipe=%p status=0x%08x", + epipe, epipe->sqh->qh.qh_qtd.qtd_status, 0, 0); #ifdef EHCI_DEBUG if (ehcidebug) usbd_dump_pipe(pipe); @@ -1444,24 +1489,6 @@ ehci_noop(usbd_pipe_handle pipe) } #ifdef EHCI_DEBUG -Static void -ehci_dump_regs(ehci_softc_t *sc) -{ - int i; - printf("cmd=0x%08x, sts=0x%08x, ien=0x%08x\n", - EOREAD4(sc, EHCI_USBCMD), - EOREAD4(sc, EHCI_USBSTS), - EOREAD4(sc, EHCI_USBINTR)); - printf("frindex=0x%08x ctrdsegm=0x%08x periodic=0x%08x async=0x%08x\n", - EOREAD4(sc, EHCI_FRINDEX), - EOREAD4(sc, EHCI_CTRLDSSEGMENT), - EOREAD4(sc, EHCI_PERIODICLISTBASE), - EOREAD4(sc, EHCI_ASYNCLISTADDR)); - for (i = 1; i <= sc->sc_noport; i++) - printf("port %d status=0x%08x\n", i, - EOREAD4(sc, EHCI_PORTSC(i))); -} - /* * Unused function - this is meant to be called from a kernel * debugger. @@ -1469,37 +1496,78 @@ ehci_dump_regs(ehci_softc_t *sc) void ehci_dump(void) { - ehci_dump_regs(theehci); + ehci_softc_t *sc = theehci; + int i; + printf("cmd=0x%08x, sts=0x%08x, ien=0x%08x\n", + EOREAD4(sc, EHCI_USBCMD), + EOREAD4(sc, EHCI_USBSTS), + EOREAD4(sc, EHCI_USBINTR)); + printf("frindex=0x%08x ctrdsegm=0x%08x periodic=0x%08x async=0x%08x\n", + EOREAD4(sc, EHCI_FRINDEX), + EOREAD4(sc, EHCI_CTRLDSSEGMENT), + EOREAD4(sc, EHCI_PERIODICLISTBASE), + EOREAD4(sc, EHCI_ASYNCLISTADDR)); + for (i = 1; i <= sc->sc_noport; i++) + printf("port %d status=0x%08x\n", i, + EOREAD4(sc, EHCI_PORTSC(i))); } Static void -ehci_dump_link(ehci_link_t link, int type) +ehci_dump_regs(ehci_softc_t *sc) { - link = le32toh(link); - printf("0x%08x", link); - if (link & EHCI_LINK_TERMINATE) - printf("<T>"); - else { - printf("<"); - if (type) { - switch (EHCI_LINK_TYPE(link)) { - case EHCI_LINK_ITD: printf("ITD"); break; - case EHCI_LINK_QH: printf("QH"); break; - case EHCI_LINK_SITD: printf("SITD"); break; - case EHCI_LINK_FSTN: printf("FSTN"); break; - } + int i; + + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, + "cmd = 0x%08x sts = 0x%08x ien = 0x%08x", + EOREAD4(sc, EHCI_USBCMD), EOREAD4(sc, EHCI_USBSTS), + EOREAD4(sc, EHCI_USBINTR), 0); + USBHIST_LOG(ehcidebug, + "frindex = 0x%08x ctrdsegm = 0x%08x periodic = 0x%08x " + "async = 0x%08x", + EOREAD4(sc, EHCI_FRINDEX), EOREAD4(sc, EHCI_CTRLDSSEGMENT), + EOREAD4(sc, EHCI_PERIODICLISTBASE), + EOREAD4(sc, EHCI_ASYNCLISTADDR)); + for (i = 1; i <= sc->sc_noport; i += 2) { + if (i == sc->sc_noport) { + USBHIST_LOG(ehcidebug, + "port %d status = 0x%08x", i, + EOREAD4(sc, EHCI_PORTSC(i)), 0, 0); + } else { + USBHIST_LOG(ehcidebug, + "port %d status = 0x%08x port %d status = 0x%08x", + i, EOREAD4(sc, EHCI_PORTSC(i)), + i+1, EOREAD4(sc, EHCI_PORTSC(i+1))); } - printf(">"); } } +#ifdef EHCI_DEBUG +#define ehci_dump_link(link, type) do { \ + USBHIST_LOG(ehcidebug, " link 0x%08x (T = %d):", \ + link, \ + link & EHCI_LINK_TERMINATE ? 1 : 0, 0, 0); \ + if (type) { \ + USBHIST_LOG(ehcidebug, \ + " ITD = %d QH = %d SITD = %d FSTN = %d",\ + EHCI_LINK_TYPE(link) == EHCI_LINK_ITD ? 1 : 0, \ + EHCI_LINK_TYPE(link) == EHCI_LINK_QH ? 1 : 0, \ + EHCI_LINK_TYPE(link) == EHCI_LINK_SITD ? 1 : 0, \ + EHCI_LINK_TYPE(link) == EHCI_LINK_FSTN ? 1 : 0); \ + } \ +} while(0) +#else +#define ehci_dump_link(link, type) +#endif + Static void ehci_dump_sqtds(ehci_soft_qtd_t *sqtd) { + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); int i; - u_int32_t stop; + uint32_t stop = 0; - stop = 0; for (i = 0; sqtd && i < 20 && !stop; sqtd = sqtd->nextqtd, i++) { ehci_dump_sqtd(sqtd); usb_syncmem(&sqtd->dma, @@ -1512,16 +1580,22 @@ ehci_dump_sqtds(ehci_soft_qtd_t *sqtd) sizeof(sqtd->qtd), BUS_DMASYNC_PREREAD); } if (sqtd) - printf("dump aborted, too many TDs\n"); + USBHIST_LOG(ehcidebug, + "dump aborted, too many TDs", 0, 0, 0, 0); } Static void ehci_dump_sqtd(ehci_soft_qtd_t *sqtd) { + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + usb_syncmem(&sqtd->dma, sqtd->offs, sizeof(sqtd->qtd), BUS_DMASYNC_POSTWRITE | BUS_DMASYNC_POSTREAD); - printf("QTD(%p) at 0x%08x:\n", sqtd, sqtd->physaddr); + + USBHIST_LOGN(ehcidebug, 10, + "QTD(%p) at 0x%08x:", sqtd, sqtd->physaddr, 0, 0); ehci_dump_qtd(&sqtd->qtd); + usb_syncmem(&sqtd->dma, sqtd->offs, sizeof(sqtd->qtd), BUS_DMASYNC_PREREAD); } @@ -1529,58 +1603,97 @@ ehci_dump_sqtd(ehci_soft_qtd_t *sqtd) Static void ehci_dump_qtd(ehci_qtd_t *qtd) { - u_int32_t s; - char sbuf[128]; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); - printf(" next="); ehci_dump_link(qtd->qtd_next, 0); - printf(" altnext="); ehci_dump_link(qtd->qtd_altnext, 0); - printf("\n"); - s = le32toh(qtd->qtd_status); - snprintb(sbuf, sizeof(sbuf), - "\20\10ACTIVE\7HALTED\6BUFERR\5BABBLE\4XACTERR" - "\3MISSED\2SPLIT\1PING", EHCI_QTD_GET_STATUS(s)); - printf(" status=0x%08x: toggle=%d bytes=0x%x ioc=%d c_page=0x%x\n", - s, EHCI_QTD_GET_TOGGLE(s), EHCI_QTD_GET_BYTES(s), - EHCI_QTD_GET_IOC(s), EHCI_QTD_GET_C_PAGE(s)); - printf(" cerr=%d pid=%d stat=%s\n", EHCI_QTD_GET_CERR(s), - EHCI_QTD_GET_PID(s), sbuf); - for (s = 0; s < 5; s++) - printf(" buffer[%d]=0x%08x\n", s, le32toh(qtd->qtd_buffer[s])); +#ifdef USBHIST + uint32_t s = le32toh(qtd->qtd_status); +#endif + + USBHIST_LOGN(ehcidebug, 10, + " next = 0x%08x altnext = 0x%08x status = 0x%08x", + qtd->qtd_altnext, qtd->qtd_next, s, 0); + USBHIST_LOGN(ehcidebug, 10, + " toggle = %d ioc = %d bytes = %#x " + "c_page = %#x", EHCI_QTD_GET_TOGGLE(s), EHCI_QTD_GET_IOC(s), + EHCI_QTD_GET_BYTES(s), EHCI_QTD_GET_C_PAGE(s)); + USBHIST_LOGN(ehcidebug, 10, + " cerr = %d pid = %d stat = %x", + EHCI_QTD_GET_CERR(s), EHCI_QTD_GET_PID(s), EHCI_QTD_GET_STATUS(s), + 0); + USBHIST_LOGN(ehcidebug, 10, + "active =%d halted=%d buferr=%d babble=%d", + s & EHCI_QTD_ACTIVE ? 1 : 0, + s & EHCI_QTD_HALTED ? 1 : 0, + s & EHCI_QTD_BUFERR ? 1 : 0, + s & EHCI_QTD_BABBLE ? 1 : 0); + USBHIST_LOGN(ehcidebug, 10, + "xacterr=%d missed=%d split =%d ping =%d", + s & EHCI_QTD_XACTERR ? 1 : 0, + s & EHCI_QTD_MISSEDMICRO ? 1 : 0, + s & EHCI_QTD_SPLITXSTATE ? 1 : 0, + s & EHCI_QTD_PINGSTATE ? 1 : 0); + USBHIST_LOGN(ehcidebug, 10, + "buffer[0] = %#x buffer[1] = %#x " + "buffer[2] = %#x buffer[3] = %#x", + le32toh(qtd->qtd_buffer[0]), le32toh(qtd->qtd_buffer[1]), + le32toh(qtd->qtd_buffer[2]), le32toh(qtd->qtd_buffer[3])); + USBHIST_LOGN(ehcidebug, 10, + "buffer[4] = %#x", le32toh(qtd->qtd_buffer[4]), 0, 0, 0); } Static void ehci_dump_sqh(ehci_soft_qh_t *sqh) { +#ifdef USBHIST ehci_qh_t *qh = &sqh->qh; + ehci_link_t link; +#endif u_int32_t endp, endphub; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); usb_syncmem(&sqh->dma, sqh->offs, sizeof(sqh->qh), BUS_DMASYNC_POSTWRITE | BUS_DMASYNC_POSTREAD); - printf("QH(%p) at 0x%08x:\n", sqh, sqh->physaddr); - printf(" link="); ehci_dump_link(qh->qh_link, 1); printf("\n"); + + USBHIST_LOGN(ehcidebug, 10, + "QH(%p) at %#x:", sqh, sqh->physaddr, 0, 0); + link = le32toh(qh->qh_link); + ehci_dump_link(link, true); + endp = le32toh(qh->qh_endp); - printf(" endp=0x%08x\n", endp); - printf(" addr=0x%02x inact=%d endpt=%d eps=%d dtc=%d hrecl=%d\n", - EHCI_QH_GET_ADDR(endp), EHCI_QH_GET_INACT(endp), - EHCI_QH_GET_ENDPT(endp), EHCI_QH_GET_EPS(endp), - EHCI_QH_GET_DTC(endp), EHCI_QH_GET_HRECL(endp)); - printf(" mpl=0x%x ctl=%d nrl=%d\n", - EHCI_QH_GET_MPL(endp), EHCI_QH_GET_CTL(endp), - EHCI_QH_GET_NRL(endp)); + USBHIST_LOGN(ehcidebug, 10, + " endp = %#x", endp, 0, 0, 0); + USBHIST_LOGN(ehcidebug, 10, + " addr = 0x%02x inact = %d endpt = %d eps = %d", + EHCI_QH_GET_ADDR(endp), EHCI_QH_GET_INACT(endp), + EHCI_QH_GET_ENDPT(endp), EHCI_QH_GET_EPS(endp)); + USBHIST_LOGN(ehcidebug, 10, + " dtc = %d hrecl = %d", + EHCI_QH_GET_DTC(endp), EHCI_QH_GET_HRECL(endp), 0, 0); + USBHIST_LOGN(ehcidebug, 10, + " ctl = %d nrl = %d mpl = %#x(%d)", + EHCI_QH_GET_CTL(endp),EHCI_QH_GET_NRL(endp), + EHCI_QH_GET_MPL(endp), EHCI_QH_GET_MPL(endp)); + endphub = le32toh(qh->qh_endphub); - printf(" endphub=0x%08x\n", endphub); - printf(" smask=0x%02x cmask=0x%02x huba=0x%02x port=%d mult=%d\n", - EHCI_QH_GET_SMASK(endphub), EHCI_QH_GET_CMASK(endphub), - EHCI_QH_GET_HUBA(endphub), EHCI_QH_GET_PORT(endphub), - EHCI_QH_GET_MULT(endphub)); - printf(" curqtd="); ehci_dump_link(qh->qh_curqtd, 0); printf("\n"); - printf("Overlay qTD:\n"); + USBHIST_LOGN(ehcidebug, 10, + " endphub = %#x", endphub, 0, 0, 0); + USBHIST_LOGN(ehcidebug, 10, + " smask = 0x%02x cmask = 0x%02x", + EHCI_QH_GET_SMASK(endphub), EHCI_QH_GET_CMASK(endphub), 1, 0); + USBHIST_LOGN(ehcidebug, 10, + " huba = 0x%02x port = %d mult = %d", + EHCI_QH_GET_HUBA(endphub), EHCI_QH_GET_PORT(endphub), + EHCI_QH_GET_MULT(endphub), 0); + + link = le32toh(qh->qh_curqtd); + ehci_dump_link(link, false); + USBHIST_LOGN(ehcidebug, 10, "Overlay qTD:", 0, 0, 0, 0); ehci_dump_qtd(&qh->qh_qtd); + usb_syncmem(&sqh->dma, sqh->offs, sizeof(sqh->qh), BUS_DMASYNC_PREREAD); } -#if notyet Static void ehci_dump_itd(struct ehci_soft_itd *itd) { @@ -1588,44 +1701,55 @@ ehci_dump_itd(struct ehci_soft_itd *itd) ehci_isoc_bufr_ptr_t b, b2, b3; int i; - printf("ITD: next phys=%X\n", itd->itd.itd_next); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "ITD: next phys = %#x", itd->itd.itd_next, 0, + 0, 0); for (i = 0; i < EHCI_ITD_NUFRAMES; i++) { t = le32toh(itd->itd.itd_ctl[i]); - printf("ITDctl %d: stat=%X len=%X ioc=%X pg=%X offs=%X\n", i, - EHCI_ITD_GET_STATUS(t), EHCI_ITD_GET_LEN(t), + USBHIST_LOG(ehcidebug, "ITDctl %d: stat = %x len = %x", + i, EHCI_ITD_GET_STATUS(t), EHCI_ITD_GET_LEN(t), 0); + USBHIST_LOG(ehcidebug, " ioc = %x pg = %x offs = %x", EHCI_ITD_GET_IOC(t), EHCI_ITD_GET_PG(t), - EHCI_ITD_GET_OFFS(t)); + EHCI_ITD_GET_OFFS(t), 0); } - printf("ITDbufr: "); + USBHIST_LOG(ehcidebug, "ITDbufr: ", 0, 0, 0, 0); for (i = 0; i < EHCI_ITD_NBUFFERS; i++) - printf("%X,", EHCI_ITD_GET_BPTR(le32toh(itd->itd.itd_bufr[i]))); + USBHIST_LOG(ehcidebug, " %x", + EHCI_ITD_GET_BPTR(le32toh(itd->itd.itd_bufr[i])), 0, 0, 0); b = le32toh(itd->itd.itd_bufr[0]); b2 = le32toh(itd->itd.itd_bufr[1]); b3 = le32toh(itd->itd.itd_bufr[2]); - printf("\nep=%X daddr=%X dir=%d maxpkt=%X multi=%X\n", - EHCI_ITD_GET_EP(b), EHCI_ITD_GET_DADDR(b), EHCI_ITD_GET_DIR(b2), - EHCI_ITD_GET_MAXPKT(b2), EHCI_ITD_GET_MULTI(b3)); + USBHIST_LOG(ehcidebug, " ep = %x daddr = %x dir = %d", + EHCI_ITD_GET_EP(b), EHCI_ITD_GET_DADDR(b), EHCI_ITD_GET_DIR(b2), 0); + USBHIST_LOG(ehcidebug, " maxpkt = %x multi = %x", + EHCI_ITD_GET_MAXPKT(b2), EHCI_ITD_GET_MULTI(b3), 0, 0); } Static void ehci_dump_sitd(struct ehci_soft_itd *itd) { - printf("SITD %p next=%p prev=%p xfernext=%p physaddr=%X slot=%d\n", - itd, itd->u.frame_list.next, itd->u.frame_list.prev, - itd->xfer_next, itd->physaddr, itd->slot); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "SITD %p next = %p prev = %p", + itd, itd->u.frame_list.next, itd->u.frame_list.prev, 0); + USBHIST_LOG(ehcidebug, " xfernext=%p physaddr=%X slot=%d", + itd->xfer_next, itd->physaddr, itd->slot, 0); } -#endif -#ifdef DIAGNOSTIC Static void ehci_dump_exfer(struct ehci_xfer *ex) { - printf("ehci_dump_exfer: ex=%p sqtdstart=%p end=%p itdstart=%p end=%p isdone=%d\n", ex, ex->sqtdstart, ex->sqtdend, ex->itdstart, ex->itdend, ex->isdone); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "ex = %p sqtdstart = %p end = %p", + ex, ex->sqtdstart, ex->sqtdend, 0); + USBHIST_LOG(ehcidebug, " itdstart = %p end = %p isdone = %d", + ex->itdstart, ex->itdend, ex->isdone, 0); } #endif -#endif Static usbd_status ehci_open(usbd_pipe_handle pipe) @@ -1641,8 +1765,10 @@ ehci_open(usbd_pipe_handle pipe) int ival, speed, naks; int hshubaddr, hshubport; - DPRINTFN(1, ("ehci_open: pipe=%p, addr=%d, endpt=%d (%d)\n", - pipe, addr, ed->bEndpointAddress, sc->sc_addr)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "pipe=%p, addr=%d, endpt=%d (%d)", + pipe, addr, ed->bEndpointAddress, sc->sc_addr); if (dev->myhsport) { /* @@ -1677,8 +1803,9 @@ ehci_open(usbd_pipe_handle pipe) pipe->methods = &ehci_root_intr_methods; break; default: - DPRINTF(("ehci_open: bad bEndpointAddress 0x%02x\n", - ed->bEndpointAddress)); + USBHIST_LOG(ehcidebug, + "bad bEndpointAddress 0x%02x", + ed->bEndpointAddress, 0, 0, 0); return (USBD_INVAL); } return (USBD_NORMAL_COMPLETION); @@ -1699,8 +1826,8 @@ ehci_open(usbd_pipe_handle pipe) "not yet supported.\n"); aprint_normal_dev(sc->sc_dev, "reattach the device to the " "root hub instead.\n"); - DPRINTFN(1,("ehci_open: hshubaddr=%d hshubport=%d\n", - hshubaddr, hshubport)); + USBHIST_LOG(ehcidebug, "hshubaddr=%d hshubport=%d", + hshubaddr, hshubport, 0, 0); return USBD_INVAL; } @@ -1809,7 +1936,7 @@ ehci_open(usbd_pipe_handle pipe) epipe->u.isoc.cur_xfers = 0; break; default: - DPRINTF(("ehci: bad xfer type %d\n", xfertype)); + USBHIST_LOG(ehcidebug, "bad xfer type %d", xfertype, 0, 0, 0); err = USBD_INVAL; goto bad; } @@ -1830,22 +1957,25 @@ ehci_add_qh(ehci_softc_t *sc, ehci_soft_ KASSERT(mutex_owned(&sc->sc_lock)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + usb_syncmem(&head->dma, head->offs + offsetof(ehci_qh_t, qh_link), sizeof(head->qh.qh_link), BUS_DMASYNC_POSTWRITE); + sqh->next = head->next; sqh->qh.qh_link = head->qh.qh_link; + usb_syncmem(&sqh->dma, sqh->offs + offsetof(ehci_qh_t, qh_link), sizeof(sqh->qh.qh_link), BUS_DMASYNC_PREWRITE); + head->next = sqh; head->qh.qh_link = htole32(sqh->physaddr | EHCI_LINK_QH); + usb_syncmem(&head->dma, head->offs + offsetof(ehci_qh_t, qh_link), sizeof(head->qh.qh_link), BUS_DMASYNC_PREWRITE); #ifdef EHCI_DEBUG - if (ehcidebug > 5) { - printf("ehci_add_qh:\n"); - ehci_dump_sqh(sqh); - } + ehci_dump_sqh(sqh); #endif } @@ -1922,23 +2052,25 @@ ehci_sync_hc(ehci_softc_t *sc) KASSERT(mutex_owned(&sc->sc_lock)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + if (sc->sc_dying) { - DPRINTFN(2,("ehci_sync_hc: dying\n")); + USBHIST_LOG(ehcidebug, "dying", 0, 0, 0, 0); return; } - DPRINTFN(2,("ehci_sync_hc: enter\n")); /* ask for doorbell */ EOWRITE4(sc, EHCI_USBCMD, EOREAD4(sc, EHCI_USBCMD) | EHCI_CMD_IAAD); - DPRINTFN(1,("ehci_sync_hc: cmd=0x%08x sts=0x%08x\n", - EOREAD4(sc, EHCI_USBCMD), EOREAD4(sc, EHCI_USBSTS))); + USBHIST_LOG(ehcidebug, "cmd = 0x%08x sts = 0x%08x", + EOREAD4(sc, EHCI_USBCMD), EOREAD4(sc, EHCI_USBSTS), 0, 0); + error = cv_timedwait(&sc->sc_doorbell, &sc->sc_lock, hz); /* bell wait */ - DPRINTFN(1,("ehci_sync_hc: cmd=0x%08x sts=0x%08x\n", - EOREAD4(sc, EHCI_USBCMD), EOREAD4(sc, EHCI_USBSTS))); + + USBHIST_LOG(ehcidebug, "cmd = 0x%08x sts = 0x%08x", + EOREAD4(sc, EHCI_USBCMD), EOREAD4(sc, EHCI_USBSTS), 0, 0); #ifdef DIAGNOSTIC if (error) printf("ehci_sync_hc: cv_timedwait() = %d\n", error); #endif - DPRINTFN(2,("ehci_sync_hc: exit\n")); } Static void @@ -2097,6 +2229,8 @@ ehci_root_ctrl_start(usbd_xfer_handle xf usbd_status err; u_int32_t v; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + if (sc->sc_dying) return (USBD_IOERROR); @@ -2107,8 +2241,8 @@ ehci_root_ctrl_start(usbd_xfer_handle xf #endif req = &xfer->request; - DPRINTFN(4,("ehci_root_ctrl_start: type=0x%02x request=%02x\n", - req->bmRequestType, req->bRequest)); + USBHIST_LOG(ehcidebug, "type=0x%02x request=%02x", + req->bmRequestType, req->bRequest, 0, 0); len = UGETW(req->wLength); value = UGETW(req->wValue); @@ -2134,7 +2268,7 @@ ehci_root_ctrl_start(usbd_xfer_handle xf } break; case C(UR_GET_DESCRIPTOR, UT_READ_DEVICE): - DPRINTFN(8,("ehci_root_ctrl_start: wValue=0x%04x\n", value)); + USBHIST_LOG(ehcidebug, "wValue=0x%04x", value, 0, 0, 0); if (len == 0) break; switch(value >> 8) { @@ -2254,16 +2388,16 @@ ehci_root_ctrl_start(usbd_xfer_handle xf case C(UR_CLEAR_FEATURE, UT_WRITE_CLASS_DEVICE): break; case C(UR_CLEAR_FEATURE, UT_WRITE_CLASS_OTHER): - DPRINTFN(4, ("ehci_root_ctrl_start: UR_CLEAR_PORT_FEATURE " - "port=%d feature=%d\n", - index, value)); + USBHIST_LOG(ehcidebug, + "UR_CLEAR_PORT_FEATURE port=%d feature=%d", index, value, + 0, 0); if (index < 1 || index > sc->sc_noport) { err = USBD_IOERROR; goto ret; } port = EHCI_PORTSC(index); v = EOREAD4(sc, port); - DPRINTFN(4, ("ehci_root_ctrl_start: portsc=0x%08x\n", v)); + USBHIST_LOG(ehcidebug, "portsc=0x%08x", v, 0, 0, 0); v &= ~EHCI_PS_CLEAR; switch(value) { case UHF_PORT_ENABLE: @@ -2289,12 +2423,12 @@ ehci_root_ctrl_start(usbd_xfer_handle xf EOWRITE4(sc, port, v &~ EHCI_PS_PP); break; case UHF_PORT_TEST: - DPRINTFN(2,("ehci_root_ctrl_start: clear port test " - "%d\n", index)); + USBHIST_LOG(ehcidebug, "clear port test " + "%d", index, 0, 0, 0); break; case UHF_PORT_INDICATOR: - DPRINTFN(2,("ehci_root_ctrl_start: clear port ind " - "%d\n", index)); + USBHIST_LOG(ehcidebug, "clear port ind " + "%d", index, 0, 0, 0); EOWRITE4(sc, port, v &~ EHCI_PS_PIC); break; case UHF_C_PORT_CONNECTION: @@ -2359,8 +2493,7 @@ ehci_root_ctrl_start(usbd_xfer_handle xf totlen = len; break; case C(UR_GET_STATUS, UT_READ_CLASS_OTHER): - DPRINTFN(8,("ehci_root_ctrl_start: get port status i=%d\n", - index)); + USBHIST_LOG(ehcidebug, "get port status i=%d", index, 0, 0, 0); if (index < 1 || index > sc->sc_noport) { err = USBD_IOERROR; goto ret; @@ -2370,7 +2503,7 @@ ehci_root_ctrl_start(usbd_xfer_handle xf goto ret; } v = EOREAD4(sc, EHCI_PORTSC(index)); - DPRINTFN(8,("ehci_root_ctrl_start: port status=0x%04x\n", v)); + USBHIST_LOG(ehcidebug, "port status=0x%04x", v, 0, 0, 0); i = UPS_HIGH_SPEED; if (sc->sc_flags & EHCIF_ETTF) { @@ -2413,7 +2546,7 @@ ehci_root_ctrl_start(usbd_xfer_handle xf } port = EHCI_PORTSC(index); v = EOREAD4(sc, port); - DPRINTFN(4, ("ehci_root_ctrl_start: portsc=0x%08x\n", v)); + USBHIST_LOG(ehcidebug, "portsc=0x%08x", v, 0, 0, 0); v &= ~EHCI_PS_CLEAR; switch(value) { case UHF_PORT_ENABLE: @@ -2423,8 +2556,7 @@ ehci_root_ctrl_start(usbd_xfer_handle xf EOWRITE4(sc, port, v | EHCI_PS_SUSP); break; case UHF_PORT_RESET: - DPRINTFN(5,("ehci_root_ctrl_start: reset port %d\n", - index)); + USBHIST_LOG(ehcidebug, "reset port %d", index, 0, 0, 0); if (EHCI_PS_IS_LOWSPEED(v) && sc->sc_ncomp > 0 && !(sc->sc_flags & EHCIF_ETTF)) { @@ -2463,7 +2595,8 @@ ehci_root_ctrl_start(usbd_xfer_handle xf } v = EOREAD4(sc, port); - DPRINTF(("ehci after reset, status=0x%08x\n", v)); + USBHIST_LOG(ehcidebug, + "ehci after reset, status=0x%08x", v, 0, 0, 0); if (v & EHCI_PS_PR) { printf("%s: port reset timeout\n", device_xname(sc->sc_dev)); @@ -2475,23 +2608,24 @@ ehci_root_ctrl_start(usbd_xfer_handle xf break; } sc->sc_isreset[index] = 1; - DPRINTF(("ehci port %d reset, status = 0x%08x\n", - index, v)); + USBHIST_LOG(ehcidebug, + "ehci port %d reset, status = 0x%08x", index, v, 0, + 0); break; case UHF_PORT_POWER: - DPRINTFN(2,("ehci_root_ctrl_start: set port power " - "%d (has PPC = %d)\n", index, - sc->sc_hasppc)); + USBHIST_LOG(ehcidebug, + "set port power %d (has PPC = %d)", index, + sc->sc_hasppc, 0, 0); if (sc->sc_hasppc) EOWRITE4(sc, port, v | EHCI_PS_PP); break; case UHF_PORT_TEST: - DPRINTFN(2,("ehci_root_ctrl_start: set port test " - "%d\n", index)); + USBHIST_LOG(ehcidebug, "set port test %d", + index, 0, 0, 0); break; case UHF_PORT_INDICATOR: - DPRINTFN(2,("ehci_root_ctrl_start: set port ind " - "%d\n", index)); + USBHIST_LOG(ehcidebug, "set port ind %d", + index, 0, 0, 0); EOWRITE4(sc, port, v | EHCI_PS_PIC); break; default: @@ -2524,7 +2658,9 @@ ehci_disown(ehci_softc_t *sc, int index, int port; u_int32_t v; - DPRINTF(("ehci_disown: index=%d lowspeed=%d\n", index, lowspeed)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "index=%d lowspeed=%d", index, lowspeed, 0, 0); #ifdef DIAGNOSTIC if (sc->sc_npcomp != 0) { int i = (index-1) / sc->sc_npcomp; @@ -2557,7 +2693,7 @@ ehci_root_ctrl_abort(usbd_xfer_handle xf Static void ehci_root_ctrl_close(usbd_pipe_handle pipe) { - DPRINTF(("ehci_root_ctrl_close\n")); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); /* Nothing to do. */ } @@ -2621,9 +2757,9 @@ ehci_root_intr_close(usbd_pipe_handle pi { ehci_softc_t *sc = pipe->device->bus->hci_private; - KASSERT(mutex_owned(&sc->sc_lock)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); - DPRINTF(("ehci_root_intr_close\n")); + KASSERT(mutex_owned(&sc->sc_lock)); sc->sc_intrxfer = NULL; } @@ -2644,8 +2780,10 @@ ehci_alloc_sqh(ehci_softc_t *sc) int i, offs; usb_dma_t dma; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + if (sc->sc_freeqhs == NULL) { - DPRINTFN(2, ("ehci_alloc_sqh: allocating chunk\n")); + USBHIST_LOG(ehcidebug, "allocating chunk", 0, 0, 0, 0); err = usb_allocmem(&sc->sc_bus, EHCI_SQH_SIZE * EHCI_SQH_CHUNK, EHCI_PAGE_SIZE, &dma); #ifdef EHCI_DEBUG @@ -2686,8 +2824,10 @@ ehci_alloc_sqtd(ehci_softc_t *sc) int i, offs; usb_dma_t dma; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + if (sc->sc_freeqtds == NULL) { - DPRINTFN(2, ("ehci_alloc_sqtd: allocating chunk\n")); + USBHIST_LOG(ehcidebug, "allocating chunk", 0, 0, 0, 0); err = usb_allocmem(&sc->sc_bus, EHCI_SQTD_SIZE*EHCI_SQTD_CHUNK, EHCI_PAGE_SIZE, &dma); @@ -2747,7 +2887,9 @@ ehci_alloc_sqtd_chain(struct ehci_pipe * u_int16_t flags = xfer->flags; paddr_t a; - DPRINTFN(alen<4*4096,("ehci_alloc_sqtd_chain: start len=%d\n", alen)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "start len=%d", alen, 0, 0, 0); len = alen; qtdstatus = EHCI_QTD_ACTIVE | @@ -2781,15 +2923,15 @@ ehci_alloc_sqtd_chain(struct ehci_pipe * /* the length must be a multiple of the max size */ curlen -= curlen % mps; - DPRINTFN(1,("ehci_alloc_sqtd_chain: multiple QTDs, " - "curlen=%d\n", curlen)); + USBHIST_LOG(ehcidebug, "multiple QTDs, " + "curlen=%d", curlen, 0, 0, 0); #ifdef DIAGNOSTIC if (curlen == 0) panic("ehci_alloc_sqtd_chain: curlen == 0"); #endif } - DPRINTFN(4,("ehci_alloc_sqtd_chain: len=%d curlen=%d " - "curoffs=%zu\n", len, curlen, (size_t)curoffs)); + USBHIST_LOG(ehcidebug, "len=%d curlen=%d curoffs=%zu", + len, curlen, (size_t)curoffs, 0); /* * Allocate another transfer if there's more data left, @@ -2831,8 +2973,8 @@ ehci_alloc_sqtd_chain(struct ehci_pipe * cur->xfer = xfer; cur->len = curlen; - DPRINTFN(10,("ehci_alloc_sqtd_chain: cbp=0x%08zx end=0x%08zx\n", - (size_t)curoffs, (size_t)(curoffs + curlen))); + USBHIST_LOG(ehcidebug, "cbp=0x%08zx end=0x%08zx", + (size_t)curoffs, (size_t)(curoffs + curlen), 0, 0); /* adjust the toggle based on the number of packets in this qtd */ @@ -2844,7 +2986,7 @@ ehci_alloc_sqtd_chain(struct ehci_pipe * break; usb_syncmem(&cur->dma, cur->offs, sizeof(cur->qtd), BUS_DMASYNC_PREWRITE | BUS_DMASYNC_PREREAD); - DPRINTFN(10,("ehci_alloc_sqtd_chain: extend chain\n")); + USBHIST_LOG(ehcidebug, "extend chain", 0, 0, 0, 0); if (len) curoffs += curlen; cur = next; @@ -2855,14 +2997,14 @@ ehci_alloc_sqtd_chain(struct ehci_pipe * *ep = cur; epipe->nexttoggle = tog; - DPRINTFN(10,("ehci_alloc_sqtd_chain: return sqtd=%p sqtdend=%p\n", - *sp, *ep)); + USBHIST_LOG(ehcidebug, "return sqtd=%p sqtdend=%p", + *sp, *ep, 0, 0); return (USBD_NORMAL_COMPLETION); nomem: /* XXX free chain */ - DPRINTFN(-1,("ehci_alloc_sqtd_chain: no memory\n")); + USBHIST_LOG(ehcidebug, "no memory", 0, 0, 0, 0); return (USBD_NOMEM); } @@ -2873,8 +3015,10 @@ ehci_free_sqtd_chain(ehci_softc_t *sc, e ehci_soft_qtd_t *p; int i; - DPRINTFN(10,("ehci_free_sqtd_chain: sqtd=%p sqtdend=%p\n", - sqtd, sqtdend)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "sqtd=%p sqtdend=%p", + sqtd, sqtdend, 0, 0); for (i = 0; sqtd != sqtdend; sqtd = p, i++) { p = sqtd->nextqtd; @@ -2890,6 +3034,8 @@ ehci_alloc_itd(ehci_softc_t *sc) int i, offs, frindex, previndex; usb_dma_t dma; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + mutex_enter(&sc->sc_lock); /* Find an itd that wasn't freed this frame or last frame. This can @@ -2910,12 +3056,13 @@ ehci_alloc_itd(ehci_softc_t *sc) } if (freeitd == NULL) { - DPRINTFN(2, ("ehci_alloc_itd allocating chunk\n")); + USBHIST_LOG(ehcidebug, "allocating chunk", 0, 0, 0, 0); err = usb_allocmem(&sc->sc_bus, EHCI_ITD_SIZE * EHCI_ITD_CHUNK, EHCI_PAGE_SIZE, &dma); if (err) { - DPRINTF(("ehci_alloc_itd, alloc returned %d\n", err)); + USBHIST_LOG(ehcidebug, + "alloc returned %d", err, 0, 0, 0); mutex_exit(&sc->sc_lock); return NULL; } @@ -3001,7 +3148,9 @@ ehci_abort_xfer(usbd_xfer_handle xfer, u int hit; int wake; - DPRINTF(("ehci_abort_xfer: xfer=%p pipe=%p\n", xfer, epipe)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "xfer=%p pipe=%p", xfer, epipe, 0, 0); KASSERT(mutex_owned(&sc->sc_lock)); @@ -3021,14 +3170,15 @@ ehci_abort_xfer(usbd_xfer_handle xfer, u * complete and return. */ if (xfer->hcflags & UXFER_ABORTING) { - DPRINTFN(2, ("ehci_abort_xfer: already aborting\n")); + USBHIST_LOG(ehcidebug, "already aborting", 0, 0, 0, 0); #ifdef DIAGNOSTIC if (status == USBD_TIMEOUT) printf("ehci_abort_xfer: TIMEOUT while aborting\n"); #endif /* Override the status which might be USBD_TIMEOUT. */ xfer->status = status; - DPRINTFN(2, ("ehci_abort_xfer: waiting for abort to finish\n")); + USBHIST_LOG(ehcidebug, "waiting for abort to finish", + 0, 0, 0, 0); xfer->hcflags |= UXFER_ABORTWAIT; while (xfer->hcflags & UXFER_ABORTING) cv_wait(&xfer->hccv, &sc->sc_lock); @@ -3098,7 +3248,7 @@ ehci_abort_xfer(usbd_xfer_handle xfer, u sqtd = sqtd->nextqtd; /* Zap curqtd register if hardware pointed inside the xfer. */ if (hit && sqtd != NULL) { - DPRINTFN(1,("ehci_abort_xfer: cur=0x%08x\n", sqtd->physaddr)); + USBHIST_LOG(ehcidebug, "cur=0x%08x", sqtd->physaddr, 0, 0, 0); sqh->qh.qh_curqtd = htole32(sqtd->physaddr); /* unlink qTDs */ usb_syncmem(&sqh->dma, sqh->offs + offsetof(ehci_qh_t, qh_curqtd), @@ -3110,7 +3260,7 @@ ehci_abort_xfer(usbd_xfer_handle xfer, u sizeof(sqh->qh.qh_qtd.qtd_status), BUS_DMASYNC_PREWRITE | BUS_DMASYNC_PREREAD); } else { - DPRINTFN(1,("ehci_abort_xfer: no hit\n")); + USBHIST_LOG(ehcidebug, "no hit", 0, 0, 0, 0); } /* @@ -3140,11 +3290,13 @@ ehci_abort_isoc_xfer(usbd_xfer_handle xf struct ehci_soft_itd *itd; int i, wake; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + epipe = (struct ehci_pipe *) xfer->pipe; exfer = EXFER(xfer); sc = epipe->pipe.device->bus->hci_private; - DPRINTF(("ehci_abort_isoc_xfer: xfer %p pipe %p\n", xfer, epipe)); + USBHIST_LOG(ehcidebug, "xfer %p pipe %p", xfer, epipe, 0, 0); KASSERT(mutex_owned(&sc->sc_lock)); @@ -3156,7 +3308,7 @@ ehci_abort_isoc_xfer(usbd_xfer_handle xf } if (xfer->hcflags & UXFER_ABORTING) { - DPRINTFN(2, ("ehci_abort_isoc_xfer: already aborting\n")); + USBHIST_LOG(ehcidebug, "already aborting", 0, 0, 0, 0); #ifdef DIAGNOSTIC if (status == USBD_TIMEOUT) @@ -3164,7 +3316,8 @@ ehci_abort_isoc_xfer(usbd_xfer_handle xf #endif xfer->status = status; - DPRINTFN(2, ("ehci_abort_isoc_xfer: waiting for abort to finish\n")); + USBHIST_LOG(ehcidebug, + "waiting for abort to finish", 0, 0, 0, 0); xfer->hcflags |= UXFER_ABORTWAIT; while (xfer->hcflags & UXFER_ABORTING) cv_wait(&xfer->hccv, &sc->sc_lock); @@ -3219,7 +3372,9 @@ ehci_timeout(void *addr) struct ehci_pipe *epipe = (struct ehci_pipe *)exfer->xfer.pipe; ehci_softc_t *sc = epipe->pipe.device->bus->hci_private; - DPRINTF(("ehci_timeout: exfer=%p\n", exfer)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "exfer %p", exfer, 0, 0, 0); #ifdef EHCI_DEBUG if (ehcidebug > 1) usbd_dump_pipe(exfer->xfer.pipe); @@ -3245,7 +3400,9 @@ ehci_timeout_task(void *addr) usbd_xfer_handle xfer = addr; ehci_softc_t *sc = xfer->pipe->device->bus->hci_private; - DPRINTF(("ehci_timeout_task: xfer=%p\n", xfer)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "xfer=%p", xfer, 0, 0, 0); mutex_enter(&sc->sc_lock); ehci_abort_xfer(xfer, USBD_TIMEOUT); @@ -3309,7 +3466,9 @@ ehci_device_ctrl_done(usbd_xfer_handle x int len = UGETW(req->wLength); int rd = req->bmRequestType & UT_READ; - DPRINTFN(10,("ehci_ctrl_done: xfer=%p\n", xfer)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "xfer=%p", xfer, 0, 0, 0); KASSERT(sc->sc_bus.use_polling || mutex_owned(&sc->sc_lock)); @@ -3329,14 +3488,16 @@ ehci_device_ctrl_done(usbd_xfer_handle x rd ? BUS_DMASYNC_POSTREAD : BUS_DMASYNC_POSTWRITE); } - DPRINTFN(5, ("ehci_ctrl_done: length=%d\n", xfer->actlen)); + USBHIST_LOG(ehcidebug, "length=%d", xfer->actlen, 0, 0, 0); } /* Abort a device control request. */ Static void ehci_device_ctrl_abort(usbd_xfer_handle xfer) { - DPRINTF(("ehci_device_ctrl_abort: xfer=%p\n", xfer)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "xfer=%p", xfer, 0, 0, 0); ehci_abort_xfer(xfer, USBD_CANCELLED); } @@ -3347,9 +3508,11 @@ ehci_device_ctrl_close(usbd_pipe_handle ehci_softc_t *sc = pipe->device->bus->hci_private; /*struct ehci_pipe *epipe = (struct ehci_pipe *)pipe;*/ + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + KASSERT(mutex_owned(&sc->sc_lock)); - DPRINTF(("ehci_device_ctrl_close: pipe=%p\n", pipe)); + USBHIST_LOG(ehcidebug, "pipe=%p", pipe, 0, 0, 0); ehci_close_pipe(pipe, sc->sc_async_head); } @@ -3368,14 +3531,18 @@ ehci_device_request(usbd_xfer_handle xfe int len; usbd_status err; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + isread = req->bmRequestType & UT_READ; len = UGETW(req->wLength); - DPRINTFN(3,("ehci_device_request: type=0x%02x, request=0x%02x, " - "wValue=0x%04x, wIndex=0x%04x len=%d, addr=%d, endpt=%d\n", - req->bmRequestType, req->bRequest, UGETW(req->wValue), - UGETW(req->wIndex), len, dev->address, - epipe->pipe.endpoint->edesc->bEndpointAddress)); + USBHIST_LOG(ehcidebug, "type=0x%02x, request=0x%02x, " + "wValue=0x%04x, wIndex=0x%04x", + req->bmRequestType, req->bRequest, UGETW(req->wValue), + UGETW(req->wIndex)); + USBHIST_LOG(ehcidebug, "len=%d, addr=%d, endpt=%d", + len, dev->address, + epipe->pipe.endpoint->edesc->bEndpointAddress, 0); setup = ehci_alloc_sqtd(sc); if (setup == NULL) { @@ -3458,11 +3625,9 @@ ehci_device_request(usbd_xfer_handle xfe BUS_DMASYNC_PREWRITE | BUS_DMASYNC_PREREAD); #ifdef EHCI_DEBUG - if (ehcidebug > 5) { - DPRINTF(("ehci_device_request:\n")); - ehci_dump_sqh(sqh); - ehci_dump_sqtds(setup); - } + USBHIST_LOGN(ehcidebug, 5, "dump:", 0, 0, 0, 0); + ehci_dump_sqh(sqh); + ehci_dump_sqtds(setup); #endif exfer->sqtdstart = setup; @@ -3485,15 +3650,13 @@ ehci_device_request(usbd_xfer_handle xfe mutex_exit(&sc->sc_lock); #ifdef EHCI_DEBUG - if (ehcidebug > 10) { - DPRINTF(("ehci_device_request: status=%x\n", - EOREAD4(sc, EHCI_USBSTS))); - delay(10000); - ehci_dump_regs(sc); - ehci_dump_sqh(sc->sc_async_head); - ehci_dump_sqh(sqh); - ehci_dump_sqtds(setup); - } + USBHIST_LOGN(ehcidebug, 10, "status=%x, dump:", + EOREAD4(sc, EHCI_USBSTS), 0, 0, 0); +// delay(10000); + ehci_dump_regs(sc); + ehci_dump_sqh(sc->sc_async_head); + ehci_dump_sqh(sqh); + ehci_dump_sqtds(setup); #endif return (USBD_NORMAL_COMPLETION); @@ -3504,7 +3667,7 @@ ehci_device_request(usbd_xfer_handle xfe bad2: ehci_free_sqtd(sc, setup); bad1: - DPRINTFN(-1,("ehci_device_request: no memory\n")); + USBHIST_LOG(ehcidebug, "no memory", 0, 0, 0, 0); mutex_enter(&sc->sc_lock); xfer->status = err; usb_transfer_complete(xfer); @@ -3529,7 +3692,8 @@ ehci_intrlist_timeout(void *arg) { ehci_softc_t *sc = arg; - DPRINTF(("ehci_intrlist_timeout\n")); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + usb_schedsoftintr(&sc->sc_bus); } @@ -3564,8 +3728,10 @@ ehci_device_bulk_start(usbd_xfer_handle usbd_status err; int len, isread, endpt; - DPRINTFN(2, ("ehci_device_bulk_start: xfer=%p len=%d flags=%d\n", - xfer, xfer->length, xfer->flags)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "xfer=%p len=%d flags=%d", + xfer, xfer->length, xfer->flags, 0); if (sc->sc_dying) return (USBD_IOERROR); @@ -3587,7 +3753,7 @@ ehci_device_bulk_start(usbd_xfer_handle err = ehci_alloc_sqtd_chain(epipe, sc, len, isread, xfer, &data, &dataend); if (err) { - DPRINTFN(-1,("ehci_device_bulk_transfer: no memory\n")); + USBHIST_LOG(ehcidebug, "no memory", 0, 0, 0, 0); xfer->status = err; usb_transfer_complete(xfer); mutex_exit(&sc->sc_lock); @@ -3595,11 +3761,9 @@ ehci_device_bulk_start(usbd_xfer_handle } #ifdef EHCI_DEBUG - if (ehcidebug > 5) { - DPRINTF(("ehci_device_bulk_start: data(1)\n")); - ehci_dump_sqh(sqh); - ehci_dump_sqtds(data); - } + USBHIST_LOGN(ehcidebug, 5, "data(1):", 0, 0, 0, 0); + ehci_dump_sqh(sqh); + ehci_dump_sqtds(data); #endif /* Set up interrupt info. */ @@ -3622,19 +3786,17 @@ ehci_device_bulk_start(usbd_xfer_handle mutex_exit(&sc->sc_lock); #ifdef EHCI_DEBUG - if (ehcidebug > 10) { - DPRINTF(("ehci_device_bulk_start: data(2)\n")); - delay(10000); - DPRINTF(("ehci_device_bulk_start: data(3)\n")); - ehci_dump_regs(sc); + USBHIST_LOGN(ehcidebug, 5, "data(2)", 0, 0, 0, 0); +// delay(10000); + USBHIST_LOGN(ehcidebug, 5, "data(3)", 0, 0, 0, 0); + ehci_dump_regs(sc); #if 0 - printf("async_head:\n"); - ehci_dump_sqh(sc->sc_async_head); + printf("async_head:\n"); + ehci_dump_sqh(sc->sc_async_head); #endif - printf("sqh:\n"); - ehci_dump_sqh(sqh); - ehci_dump_sqtds(data); - } + USBHIST_LOG(ehcidebug, "sqh:", 0, 0, 0, 0); + ehci_dump_sqh(sqh); + ehci_dump_sqtds(data); #endif if (sc->sc_bus.use_polling) @@ -3647,7 +3809,9 @@ ehci_device_bulk_start(usbd_xfer_handle Static void ehci_device_bulk_abort(usbd_xfer_handle xfer) { - DPRINTF(("ehci_device_bulk_abort: xfer=%p\n", xfer)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "xfer %p", xfer, 0, 0, 0); ehci_abort_xfer(xfer, USBD_CANCELLED); } @@ -3660,9 +3824,11 @@ ehci_device_bulk_close(usbd_pipe_handle ehci_softc_t *sc = pipe->device->bus->hci_private; struct ehci_pipe *epipe = (struct ehci_pipe *)pipe; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + KASSERT(mutex_owned(&sc->sc_lock)); - DPRINTF(("ehci_device_bulk_close: pipe=%p\n", pipe)); + USBHIST_LOG(ehcidebug, "pipe=%p", pipe, 0, 0, 0); pipe->endpoint->datatoggle = epipe->nexttoggle; ehci_close_pipe(pipe, sc->sc_async_head); } @@ -3676,8 +3842,10 @@ ehci_device_bulk_done(usbd_xfer_handle x int endpt = epipe->pipe.endpoint->edesc->bEndpointAddress; int rd = UE_GET_DIR(endpt) == UE_DIR_IN; - DPRINTFN(10,("ehci_bulk_done: xfer=%p, actlen=%d\n", - xfer, xfer->actlen)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "xfer=%p, actlen=%d", + xfer, xfer->actlen, 0, 0); KASSERT(mutex_owned(&sc->sc_lock)); @@ -3688,7 +3856,7 @@ ehci_device_bulk_done(usbd_xfer_handle x rd ? BUS_DMASYNC_POSTREAD : BUS_DMASYNC_POSTWRITE); } - DPRINTFN(5, ("ehci_bulk_done: length=%d\n", xfer->actlen)); + USBHIST_LOG(ehcidebug, "length=%d", xfer->actlen, 0, 0, 0); } /************************/ @@ -3750,8 +3918,10 @@ ehci_device_intr_start(usbd_xfer_handle usbd_status err; int len, isread, endpt; - DPRINTFN(2, ("ehci_device_intr_start: xfer=%p len=%d flags=%d\n", - xfer, xfer->length, xfer->flags)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "xfer=%p len=%d flags=%d", + xfer, xfer->length, xfer->flags, 0); if (sc->sc_dying) return (USBD_IOERROR); @@ -3773,7 +3943,7 @@ ehci_device_intr_start(usbd_xfer_handle err = ehci_alloc_sqtd_chain(epipe, sc, len, isread, xfer, &data, &dataend); if (err) { - DPRINTFN(-1, ("ehci_device_intr_start: no memory\n")); + USBHIST_LOG(ehcidebug, "no memory", 0, 0, 0, 0); xfer->status = err; usb_transfer_complete(xfer); mutex_exit(&sc->sc_lock); @@ -3781,11 +3951,9 @@ ehci_device_intr_start(usbd_xfer_handle } #ifdef EHCI_DEBUG - if (ehcidebug > 5) { - DPRINTF(("ehci_device_intr_start: data(1)\n")); - ehci_dump_sqh(sqh); - ehci_dump_sqtds(data); - } + USBHIST_LOGN(ehcidebug, 5, "data(1)", 0, 0, 0, 0); + ehci_dump_sqh(sqh); + ehci_dump_sqtds(data); #endif /* Set up interrupt info. */ @@ -3808,15 +3976,13 @@ ehci_device_intr_start(usbd_xfer_handle mutex_exit(&sc->sc_lock); #ifdef EHCI_DEBUG - if (ehcidebug > 10) { - DPRINTF(("ehci_device_intr_start: data(2)\n")); - delay(10000); - DPRINTF(("ehci_device_intr_start: data(3)\n")); - ehci_dump_regs(sc); - printf("sqh:\n"); - ehci_dump_sqh(sqh); - ehci_dump_sqtds(data); - } + USBHIST_LOGN(ehcidebug, 5, "data(2)", 0, 0, 0, 0); +// delay(10000); + USBHIST_LOGN(ehcidebug, 5, "data(3)", 0, 0, 0, 0); + ehci_dump_regs(sc); + USBHIST_LOGN(ehcidebug, 5, "sqh:", 0, 0, 0, 0); + ehci_dump_sqh(sqh); + ehci_dump_sqtds(data); #endif if (sc->sc_bus.use_polling) @@ -3829,7 +3995,9 @@ ehci_device_intr_start(usbd_xfer_handle Static void ehci_device_intr_abort(usbd_xfer_handle xfer) { - DPRINTFN(1, ("ehci_device_intr_abort: xfer=%p\n", xfer)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "xfer=%p", xfer, 0, 0, 0); KASSERT(xfer->pipe->intrxfer == xfer); /* @@ -3865,8 +4033,10 @@ ehci_device_intr_done(usbd_xfer_handle x usbd_status err; int len, isread, endpt; - DPRINTFN(10, ("ehci_device_intr_done: xfer=%p, actlen=%d\n", - xfer, xfer->actlen)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "xfer=%p, actlen=%d", + xfer, xfer->actlen, 0, 0); KASSERT(sc->sc_bus.use_polling || mutex_owned(&sc->sc_lock)); @@ -3884,7 +4054,7 @@ ehci_device_intr_done(usbd_xfer_handle x err = ehci_alloc_sqtd_chain(epipe, sc, len, isread, xfer, &data, &dataend); if (err) { - DPRINTFN(-1, ("ehci_device_intr_done: no memory\n")); + USBHIST_LOG(ehcidebug, "no memory", 0, 0, 0, 0); xfer->status = err; return; } @@ -3894,6 +4064,8 @@ ehci_device_intr_done(usbd_xfer_handle x exfer->sqtdend = dataend; #ifdef DIAGNOSTIC if (!exfer->isdone) { + USBHIST_LOG(ehcidebug, "marked not done, ex = %p", + exfer, 0, 0, 0); printf("ehci_device_intr_done: not done, ex=%p\n", exfer); } @@ -3947,6 +4119,8 @@ ehci_device_isoc_start(usbd_xfer_handle int trans_count, offs, total_length; int frindex; + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + start = NULL; prev = NULL; itd = NULL; @@ -3966,8 +4140,8 @@ ehci_device_isoc_start(usbd_xfer_handle if (exfer->itdstart != NULL) return USBD_IN_PROGRESS; - DPRINTFN(2, ("ehci_device_isoc_start: xfer %p len %d flags %d\n", - xfer, xfer->length, xfer->flags)); + USBHIST_LOG(ehcidebug, "xfer %p len %d flags %d", + xfer, xfer->length, xfer->flags, 0); if (sc->sc_dying) return USBD_IOERROR; @@ -3979,6 +4153,8 @@ ehci_device_isoc_start(usbd_xfer_handle */ if ((1 << (epipe->pipe.endpoint->edesc->bInterval)) * xfer->nframes >= (sc->sc_flsize - 4) * 8) { + USBHIST_LOG(ehcidebug, + "isoc descriptor spans entire frametable", 0, 0, 0, 0); printf("ehci: isoc descriptor requested that spans the entire frametable, too many frames\n"); return USBD_INVAL; } @@ -3987,8 +4163,11 @@ ehci_device_isoc_start(usbd_xfer_handle if (xfer->rqflags & URQ_REQUEST) panic("ehci_device_isoc_start: request\n"); - if (!exfer->isdone) + if (!exfer->isdone) { + USBHIST_LOG(ehcidebug, "marked not done, ex = %p", exfer, + 0, 0, 0); printf("ehci_device_isoc_start: not done, ex = %p\n", exfer); + } exfer->isdone = 0; #endif @@ -4001,7 +4180,7 @@ ehci_device_isoc_start(usbd_xfer_handle i = epipe->pipe.endpoint->edesc->bInterval; if (i > 16 || i == 0) { /* Spec page 271 says intervals > 16 are invalid */ - DPRINTF(("ehci_device_isoc_start: bInvertal %d invalid\n", i)); + USBHIST_LOG(ehcidebug, "bInvertal %d invalid", i, 0, 0, 0); return USBD_INVAL; } @@ -4010,7 +4189,7 @@ ehci_device_isoc_start(usbd_xfer_handle uframes = USB_UFRAMES_PER_FRAME / ufrperframe; if (frames == 0) { - DPRINTF(("ehci_device_isoc_start: frames == 0\n")); + USBHIST_LOG(ehcidebug, "frames == 0", 0, 0, 0, 0); return USBD_INVAL; } @@ -4209,14 +4388,18 @@ ehci_device_isoc_start(usbd_xfer_handle Static void ehci_device_isoc_abort(usbd_xfer_handle xfer) { - DPRINTFN(1, ("ehci_device_isoc_abort: xfer = %p\n", xfer)); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "xfer = %p", xfer, 0, 0, 0); ehci_abort_isoc_xfer(xfer, USBD_CANCELLED); } Static void ehci_device_isoc_close(usbd_pipe_handle pipe) { - DPRINTFN(1, ("ehci_device_isoc_close: nothing in the pipe to free?\n")); + USBHIST_FUNC(); USBHIST_CALLED(ehcidebug); + + USBHIST_LOG(ehcidebug, "nothing in the pipe to free?", 0, 0, 0, 0); } Static void Index: src/sys/dev/usb/files.usb diff -u src/sys/dev/usb/files.usb:1.133 src/sys/dev/usb/files.usb:1.134 --- src/sys/dev/usb/files.usb:1.133 Tue Aug 12 13:28:44 2014 +++ src/sys/dev/usb/files.usb Fri Sep 12 16:40:38 2014 @@ -1,18 +1,95 @@ -# $NetBSD: files.usb,v 1.133 2014/08/12 13:28:44 skrll Exp $ +# $NetBSD: files.usb,v 1.134 2014/09/12 16:40:38 skrll Exp $ # # Config file and device description for machine-independent USB code. # Included by ports that need it. Ports that use it must provide # their own "major" declarations for the appropriate devices. defflag USBVERBOSE +defparam opt_usb.h USBHIST_SIZE defflag opt_usb.h USB_FRAG_DMA_WORKAROUND -defflag opt_usb.h UHUB_DEBUG USB_DEBUG -defflag opt_usb.h EHCI_DEBUG OHCI_DEBUG UHCI_DEBUG XHCI_DEBUG -defflag opt_umodem.h UMODEM_DEBUG -defflag opt_uvideo.h UVIDEO_DEBUG -defflag opt_umass.h UMASS_DEBUG -defflag opt_uatp.h UATP_DEBUG +# top level usb debug defines +defflag opt_usb.h USBHIST: KERNHIST +defflag opt_usb.h USB_DEBUG: USBHIST + +# HC controllers +defflag opt_usb.h EHCI_DEBUG: USB_DEBUG +defflag opt_usb.h OHCI_DEBUG: USB_DEBUG +defflag opt_usb.h UHCI_DEBUG: USB_DEBUG +defflag opt_usb.h DWC2_DEBUG: USB_DEBUG +defflag opt_usb.h XHCI_DEBUG: USB_DEBUG +defflag opt_usb.h MOTG_DEBUG: USB_DEBUG + +# HUB driver +defflag opt_usb.h UHUB_DEBUG: USB_DEBUG + +# Device drivers + +defflag opt_usb.h ATU_DEBUG: USB_DEBUG +defflag opt_usb.h AUE_DEBUG: USB_DEBUG +defflag opt_usb.h AUVITEK_I2C_DEBUG: USB_DEBUG +defflag opt_usb.h AXE_DEBUG: USB_DEBUG +defflag opt_usb.h AXEN_DEBUG: USB_DEBUG +defflag opt_usb.h CUE_DEBUG: USB_DEBUG +defflag opt_usb.h EZLOAD_DEBUG: USB_DEBUG +defflag opt_usb.h KUE_DEBUG: USB_DEBUG +defflag opt_usb.h OTUS_DEBUG: USB_DEBUG +defflag opt_usb.h RUM_DEBUG: USB_DEBUG +defflag opt_usb.h RUN_DEBUG: USB_DEBUG +defflag opt_usb.h UARK_DEBUG: USB_DEBUG +defflag opt_usb.h UATP_DEBUG: USB_DEBUG +defflag opt_usb.h UAUDIO_DEBUG: USB_DEBUG +defflag opt_usb.h UBERRY_DEBUG: USB_DEBUG +defflag opt_usb.h UBSA_DEBUG: USB_DEBUG +defflag opt_usb.h UBT_DEBUG: USB_DEBUG +defflag opt_usb.h UCHCOM_DEBUG: USB_DEBUG +defflag opt_usb.h UCOM_DEBUG: USB_DEBUG +defflag opt_usb.h UCYCOM_DEBUG: USB_DEBUG +defflag opt_usb.h UDAV_DEBUG: USB_DEBUG +defflag opt_usb.h UDL_DEBUG: USB_DEBUG +defflag opt_usb.h UDSBR_DEBUG: USB_DEBUG +defflag opt_usb.h UFTDI_DEBUG: USB_DEBUG +defflag opt_usb.h UGENSA_DEBUG: USB_DEBUG +defflag opt_usb.h UGEN_DEBUG: USB_DEBUG +defflag opt_usb.h UHIDEV_DEBUG: USB_DEBUG +defflag opt_usb.h UHID_DEBUG: USB_DEBUG +defflag opt_usb.h UHMODEM_DEBUG: USB_DEBUG +defflag opt_usb.h UHSO_DEBUG: USB_DEBUG +defflag opt_usb.h UIPAD_DEBUG: USB_DEBUG +defflag opt_usb.h UIPAQ_DEBUG: USB_DEBUG +defflag opt_usb.h UIRDA_DEBUG: USB_DEBUG +defflag opt_usb.h UISDATA_DEBUG: USB_DEBUG +defflag opt_usb.h UKBD_DEBUG: USB_DEBUG +defflag opt_usb.h UKYOPON_DEBUG: USB_DEBUG +defflag opt_usb.h ULPT_DEBUG: USB_DEBUG +defflag opt_usb.h UMASS_DEBUG: USB_DEBUG +defflag opt_usb.h UMCT_DEBUG: USB_DEBUG +defflag opt_usb.h UMIDIQUIRK_DEBUG: USB_DEBUG +defflag opt_usb.h UMIDI_DEBUG: USB_DEBUG +defflag opt_usb.h UMODEM_DEBUG: USB_DEBUG +defflag opt_usb.h UMS_DEBUG: USB_DEBUG +defflag opt_usb.h UPGT_DEBUG: USB_DEBUG +defflag opt_usb.h UPLCOM_DEBUG: USB_DEBUG +defflag opt_usb.h UPL_DEBUG: USB_DEBUG +defflag opt_usb.h URAL_DEBUG: USB_DEBUG +defflag opt_usb.h URIO_DEBUG: USB_DEBUG +defflag opt_usb.h URL_DEBUG: USB_DEBUG +defflag opt_usb.h URNDIS_DEBUG: USB_DEBUG +defflag opt_usb.h URTWN_DEBUG: USB_DEBUG +defflag opt_usb.h URTW_DEBUG: USB_DEBUG +defflag opt_usb.h USCANNER_DEBUG: USB_DEBUG +defflag opt_usb.h USLSA_DEBUG: USB_DEBUG +defflag opt_usb.h USSCANNER_DEBUG: USB_DEBUG +defflag opt_usb.h USTIR_DEBUG: USB_DEBUG +defflag opt_usb.h UTHUM_DEBUG: USB_DEBUG +defflag opt_usb.h UTOPPY_DEBUG: USB_DEBUG +defflag opt_usb.h UTS_DEBUG: USB_DEBUG +defflag opt_usb.h UVIDEO_DEBUG: USB_DEBUG +defflag opt_usb.h UVISOR_DEBUG: USB_DEBUG +defflag opt_usb.h UVSCOM_DEBUG: USB_DEBUG +defflag opt_usb.h UYUREX_DEBUG: USB_DEBUG +defflag opt_usb.h UZCOM_DEBUG: USB_DEBUG +defflag opt_usb.h ZYD_DEBUG: USB_DEBUG define usbroothubif { } define usbdevif { [port = -1], [configuration = -1], [interface = -1], Index: src/sys/dev/usb/if_smsc.c diff -u src/sys/dev/usb/if_smsc.c:1.19 src/sys/dev/usb/if_smsc.c:1.20 --- src/sys/dev/usb/if_smsc.c:1.19 Sun Aug 10 16:44:36 2014 +++ src/sys/dev/usb/if_smsc.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: if_smsc.c,v 1.19 2014/08/10 16:44:36 tls Exp $ */ +/* $NetBSD: if_smsc.c,v 1.20 2014/09/12 16:40:38 skrll Exp $ */ /* $OpenBSD: if_smsc.c,v 1.4 2012/09/27 12:38:11 jsg Exp $ */ /* $FreeBSD: src/sys/dev/usb/net/if_smsc.c,v 1.1 2012/08/15 04:03:55 gonzo Exp $ */ @@ -61,6 +61,7 @@ */ #ifdef _KERNEL_OPT +#include "opt_usb.h" #include "opt_inet.h" #endif Index: src/sys/dev/usb/umass.c diff -u src/sys/dev/usb/umass.c:1.148 src/sys/dev/usb/umass.c:1.149 --- src/sys/dev/usb/umass.c:1.148 Sun Dec 22 18:30:21 2013 +++ src/sys/dev/usb/umass.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: umass.c,v 1.148 2013/12/22 18:30:21 mlelstv Exp $ */ +/* $NetBSD: umass.c,v 1.149 2014/09/12 16:40:38 skrll Exp $ */ /* * Copyright (c) 2003 The NetBSD Foundation, Inc. @@ -124,10 +124,10 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: umass.c,v 1.148 2013/12/22 18:30:21 mlelstv Exp $"); +__KERNEL_RCSID(0, "$NetBSD: umass.c,v 1.149 2014/09/12 16:40:38 skrll Exp $"); #ifdef _KERNEL_OPT -#include "opt_umass.h" +#include "opt_usb.h" #endif #include "atapibus.h" @@ -141,11 +141,13 @@ __KERNEL_RCSID(0, "$NetBSD: umass.c,v 1. #include <sys/buf.h> #include <sys/device.h> #include <sys/malloc.h> +#include <sys/sysctl.h> #include <dev/usb/usb.h> #include <dev/usb/usbdi.h> #include <dev/usb/usbdi_util.h> #include <dev/usb/usbdevs.h> +#include <dev/usb/usbhist.h> #include <dev/usb/umassvar.h> #include <dev/usb/umass_quirks.h> @@ -155,10 +157,36 @@ __KERNEL_RCSID(0, "$NetBSD: umass.c,v 1. #include <dev/scsipi/scsipi_all.h> #include <dev/scsipi/scsipiconf.h> - -#ifdef UMASS_DEBUG +#ifdef USB_DEBUG int umassdebug = 0; +SYSCTL_SETUP(sysctl_hw_umass_setup, "sysctl hw.umass setup") +{ + int err; + const struct sysctlnode *rnode; + const struct sysctlnode *cnode; + + err = sysctl_createv(clog, 0, NULL, &rnode, + CTLFLAG_PERMANENT, CTLTYPE_NODE, "umass", + SYSCTL_DESCR("umass global controls"), + NULL, 0, NULL, 0, CTL_HW, CTL_CREATE, CTL_EOL); + + if (err) + goto fail; + + /* control debugging printfs */ + err = sysctl_createv(clog, 0, &rnode, &cnode, + CTLFLAG_PERMANENT|CTLFLAG_READWRITE, CTLTYPE_INT, + "debug", SYSCTL_DESCR("Enable debugging output"), + NULL, 0, &umassdebug, sizeof(umassdebug), CTL_CREATE, CTL_EOL); + if (err) + goto fail; + + return; +fail: + aprint_error("%s: sysctl_createv failed (err = %d)\n", __func__, err); +} + const char *states[TSTATE_STATES+1] = { /* should be kept in sync with the list at transfer_state */ "Idle", @@ -786,6 +814,8 @@ umass_setup_transfer(struct umass_softc { usbd_status err; + USBHIST_FUNC(); USBHIST_CALLED(umassdebug); + if (sc->sc_dying) return (USBD_IOERROR); @@ -794,6 +824,8 @@ umass_setup_transfer(struct umass_softc usbd_setup_xfer(xfer, pipe, (void *)sc, buffer, buflen, flags, sc->timeout, sc->sc_methods->wire_state); + USBHIST_LOG(umassdebug, "xfer %p, flags %d", xfer, flags, 0, 0); + err = usbd_transfer(xfer); DPRINTF(UDMASS_XFER,("%s: start xfer buffer=%p buflen=%d flags=0x%x " "timeout=%d\n", device_xname(sc->sc_dev), @@ -1037,6 +1069,8 @@ umass_bbb_state(usbd_xfer_handle xfer, u usbd_xfer_handle next_xfer; int residue; + USBHIST_FUNC(); USBHIST_CALLED(umassdebug); + KASSERTMSG(sc->sc_wire & UMASS_WPROTO_BBB, "sc->sc_wire == 0x%02x wrong for umass_bbb_state\n", sc->sc_wire); @@ -1059,6 +1093,9 @@ umass_bbb_state(usbd_xfer_handle xfer, u device_xname(sc->sc_dev), sc->transfer_state, states[sc->transfer_state], xfer, usbd_errstr(err))); + USBHIST_LOG(umassdebug, "xfer %p, transfer_state %d dir %d", xfer, + sc->transfer_state, sc->transfer_dir, 0); + switch (sc->transfer_state) { /***** Bulk Transfer *****/ Index: src/sys/dev/usb/umass_isdata.c diff -u src/sys/dev/usb/umass_isdata.c:1.29 src/sys/dev/usb/umass_isdata.c:1.30 --- src/sys/dev/usb/umass_isdata.c:1.29 Wed Oct 30 15:37:49 2013 +++ src/sys/dev/usb/umass_isdata.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: umass_isdata.c,v 1.29 2013/10/30 15:37:49 drochner Exp $ */ +/* $NetBSD: umass_isdata.c,v 1.30 2014/09/12 16:40:38 skrll Exp $ */ /* * TODO: @@ -37,11 +37,7 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: umass_isdata.c,v 1.29 2013/10/30 15:37:49 drochner Exp $"); - -#ifdef _KERNEL_OPT -#include "opt_umass.h" -#endif +__KERNEL_RCSID(0, "$NetBSD: umass_isdata.c,v 1.30 2014/09/12 16:40:38 skrll Exp $"); #include <sys/param.h> #include <sys/systm.h> Index: src/sys/dev/usb/umass_quirks.c diff -u src/sys/dev/usb/umass_quirks.c:1.95 src/sys/dev/usb/umass_quirks.c:1.96 --- src/sys/dev/usb/umass_quirks.c:1.95 Tue May 14 14:03:53 2013 +++ src/sys/dev/usb/umass_quirks.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: umass_quirks.c,v 1.95 2013/05/14 14:03:53 kiyohara Exp $ */ +/* $NetBSD: umass_quirks.c,v 1.96 2014/09/12 16:40:38 skrll Exp $ */ /* * Copyright (c) 2001, 2004 The NetBSD Foundation, Inc. @@ -32,11 +32,7 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: umass_quirks.c,v 1.95 2013/05/14 14:03:53 kiyohara Exp $"); - -#ifdef _KERNEL_OPT -#include "opt_umass.h" -#endif +__KERNEL_RCSID(0, "$NetBSD: umass_quirks.c,v 1.96 2014/09/12 16:40:38 skrll Exp $"); #include <sys/param.h> #include <sys/systm.h> Index: src/sys/dev/usb/umass_scsipi.c diff -u src/sys/dev/usb/umass_scsipi.c:1.48 src/sys/dev/usb/umass_scsipi.c:1.49 --- src/sys/dev/usb/umass_scsipi.c:1.48 Sat Jan 5 14:54:06 2013 +++ src/sys/dev/usb/umass_scsipi.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: umass_scsipi.c,v 1.48 2013/01/05 14:54:06 christos Exp $ */ +/* $NetBSD: umass_scsipi.c,v 1.49 2014/09/12 16:40:38 skrll Exp $ */ /* * Copyright (c) 2001, 2003, 2012 The NetBSD Foundation, Inc. @@ -31,10 +31,10 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: umass_scsipi.c,v 1.48 2013/01/05 14:54:06 christos Exp $"); +__KERNEL_RCSID(0, "$NetBSD: umass_scsipi.c,v 1.49 2014/09/12 16:40:38 skrll Exp $"); #ifdef _KERNEL_OPT -#include "opt_umass.h" +#include "opt_usb.h" #endif #include "atapibus.h" Index: src/sys/dev/usb/usb.c diff -u src/sys/dev/usb/usb.c:1.155 src/sys/dev/usb/usb.c:1.156 --- src/sys/dev/usb/usb.c:1.155 Tue Aug 12 13:36:40 2014 +++ src/sys/dev/usb/usb.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: usb.c,v 1.155 2014/08/12 13:36:40 skrll Exp $ */ +/* $NetBSD: usb.c,v 1.156 2014/09/12 16:40:38 skrll Exp $ */ /* * Copyright (c) 1998, 2002, 2008, 2012 The NetBSD Foundation, Inc. @@ -37,9 +37,10 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: usb.c,v 1.155 2014/08/12 13:36:40 skrll Exp $"); +__KERNEL_RCSID(0, "$NetBSD: usb.c,v 1.156 2014/09/12 16:40:38 skrll Exp $"); #ifdef _KERNEL_OPT +#include "opt_usb.h" #include "opt_compat_netbsd.h" #endif @@ -62,6 +63,7 @@ __KERNEL_RCSID(0, "$NetBSD: usb.c,v 1.15 #include <sys/bus.h> #include <sys/once.h> #include <sys/atomic.h> +#include <sys/sysctl.h> #include <dev/usb/usb.h> #include <dev/usb/usbdi.h> @@ -69,6 +71,16 @@ __KERNEL_RCSID(0, "$NetBSD: usb.c,v 1.15 #include <dev/usb/usbdivar.h> #include <dev/usb/usb_verbose.h> #include <dev/usb/usb_quirks.h> +#include <dev/usb/usbhist.h> + +#if defined(USBHIST) + +USBHIST_DEFINE(usbhist); +#ifndef USBHIST_SIZE +#define USBHIST_SIZE 50000 +#endif + +#endif #define USB_DEV_MINOR 255 @@ -82,6 +94,34 @@ int usbdebug = 0; * >1 - do no exploration */ int usb_noexplore = 0; + +SYSCTL_SETUP(sysctl_hw_usb_setup, "sysctl hw.usb setup") +{ + int err; + const struct sysctlnode *rnode; + const struct sysctlnode *cnode; + + err = sysctl_createv(clog, 0, NULL, &rnode, + CTLFLAG_PERMANENT, CTLTYPE_NODE, "usb", + SYSCTL_DESCR("usb global controls"), + NULL, 0, NULL, 0, CTL_HW, CTL_CREATE, CTL_EOL); + + if (err) + goto fail; + + /* control debugging printfs */ + err = sysctl_createv(clog, 0, &rnode, &cnode, + CTLFLAG_PERMANENT|CTLFLAG_READWRITE, CTLTYPE_INT, + "debug", SYSCTL_DESCR("Enable debugging output"), + NULL, 0, &usbdebug, sizeof(usbdebug), CTL_CREATE, CTL_EOL); + if (err) + goto fail; + + return; +fail: + aprint_error("%s: sysctl_createv failed (err = %d)\n", __func__, err); +} + #else #define DPRINTF(x) #define DPRINTFN(n,x) @@ -235,6 +275,8 @@ usb_once_init(void) struct usb_taskq *taskq; int i; + USBHIST_INIT(usbhist, USBHIST_SIZE); + selinit(&usb_selevent); mutex_init(&usb_event_lock, MUTEX_DEFAULT, IPL_NONE); cv_init(&usb_event_cv, "usbrea"); Index: src/sys/dev/usb/usb.h diff -u src/sys/dev/usb/usb.h:1.109 src/sys/dev/usb/usb.h:1.110 --- src/sys/dev/usb/usb.h:1.109 Tue Aug 12 14:22:51 2014 +++ src/sys/dev/usb/usb.h Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: usb.h,v 1.109 2014/08/12 14:22:51 skrll Exp $ */ +/* $NetBSD: usb.h,v 1.110 2014/09/12 16:40:38 skrll Exp $ */ /* $FreeBSD: src/sys/dev/usb/usb.h,v 1.14 1999/11/17 22:33:46 n_hibma Exp $ */ /* @@ -40,10 +40,6 @@ #include <sys/ioctl.h> -#if defined(_KERNEL_OPT) -#include "opt_usb.h" /* for USB_DEBUG */ -#endif - #if defined(_KERNEL) #include <sys/mallocvar.h> @@ -56,78 +52,6 @@ MALLOC_DECLARE(M_USBHC); #endif #ifdef USB_DEBUG -#define ATU_DEBUG 1 -#define AUE_DEBUG 1 -#define AUVITEK_I2C_DEBUG 1 -#define AXE_DEBUG 1 -#define AXEN_DEBUG 1 -#define CUE_DEBUG 1 -#define DWC2_DEBUG 1 -#define EHCI_DEBUG 1 -#define EZLOAD_DEBUG 1 -#define KUE_DEBUG 1 -#define OHCI_DEBUG 1 -#define OTUS_DEBUG 1 -#define RUM_DEBUG 1 -#define RUN_DEBUG 1 -#define UARK_DEBUG 1 -#define UATP_DEBUG 1 -#define UAUDIO_DEBUG 1 -#define UBERRY_DEBUG 1 -#define UBSA_DEBUG 1 -#define UBT_DEBUG 1 -#define UCHCOM_DEBUG 1 -#define UCOM_DEBUG 1 -#define UCYCOM_DEBUG 1 -#define UDAV_DEBUG 1 -#define UDL_DEBUG 1 -#define UDSBR_DEBUG 1 -#define UFTDI_DEBUG 1 -#define UGENSA_DEBUG 1 -#define UGEN_DEBUG 1 -#define UHCI_DEBUG 1 -#define UHIDEV_DEBUG 1 -#define UHID_DEBUG 1 -#define UHMODEM_DEBUG 1 -#define UHSO_DEBUG 1 -#define UHUB_DEBUG 1 -#define UIPAD_DEBUG 1 -#define UIPAQ_DEBUG 1 -#define UIRDA_DEBUG 1 -#define UISDATA_DEBUG 1 -#define UKBD_DEBUG 1 -#define UKYOPON_DEBUG 1 -#define ULPT_DEBUG 1 -#define UMASS_DEBUG 1 -#define UMCT_DEBUG 1 -#define UMIDIQUIRK_DEBUG 1 -#define UMIDI_DEBUG 1 -#define UMODEM_DEBUG 1 -#define UMS_DEBUG 1 -#define UPGT_DEBUG 1 -#define UPLCOM_DEBUG 1 -#define UPL_DEBUG 1 -#define URAL_DEBUG 1 -#define URIO_DEBUG 1 -#define URL_DEBUG 1 -#define URNDIS_DEBUG 1 -#define URTWN_DEBUG 1 -#define URTW_DEBUG 1 -#define USB_DEBUG 1 -#define USCANNER_DEBUG 1 -#define USLSA_DEBUG 1 -#define USSCANNER_DEBUG 1 -#define USTIR_DEBUG 1 -#define UTHUM_DEBUG 1 -#define UTOPPY_DEBUG 1 -#define UTS_DEBUG 1 -#define UVIDEO_DEBUG 1 -#define UVISOR_DEBUG 1 -#define UVSCOM_DEBUG 1 -#define UYUREX_DEBUG 1 -#define UZCOM_DEBUG 1 -#define XHCI_DEBUG 1 -#define ZYD_DEBUG 1 #define Static #else #define Static static Index: src/sys/dev/usb/usb_mem.c diff -u src/sys/dev/usb/usb_mem.c:1.64 src/sys/dev/usb/usb_mem.c:1.65 --- src/sys/dev/usb/usb_mem.c:1.64 Sun Dec 22 18:29:25 2013 +++ src/sys/dev/usb/usb_mem.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: usb_mem.c,v 1.64 2013/12/22 18:29:25 mlelstv Exp $ */ +/* $NetBSD: usb_mem.c,v 1.65 2014/09/12 16:40:38 skrll Exp $ */ /* * Copyright (c) 1998 The NetBSD Foundation, Inc. @@ -38,7 +38,11 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: usb_mem.c,v 1.64 2013/12/22 18:29:25 mlelstv Exp $"); +__KERNEL_RCSID(0, "$NetBSD: usb_mem.c,v 1.65 2014/09/12 16:40:38 skrll Exp $"); + +#ifdef _KERNEL_OPT +#include "opt_usb.h" +#endif #include <sys/param.h> #include <sys/systm.h> Index: src/sys/dev/usb/usb_quirks.c diff -u src/sys/dev/usb/usb_quirks.c:1.80 src/sys/dev/usb/usb_quirks.c:1.81 --- src/sys/dev/usb/usb_quirks.c:1.80 Thu Nov 14 16:33:20 2013 +++ src/sys/dev/usb/usb_quirks.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: usb_quirks.c,v 1.80 2013/11/14 16:33:20 nonaka Exp $ */ +/* $NetBSD: usb_quirks.c,v 1.81 2014/09/12 16:40:38 skrll Exp $ */ /* $FreeBSD: src/sys/dev/usb/usb_quirks.c,v 1.30 2003/01/02 04:15:55 imp Exp $ */ /* @@ -32,7 +32,11 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: usb_quirks.c,v 1.80 2013/11/14 16:33:20 nonaka Exp $"); +__KERNEL_RCSID(0, "$NetBSD: usb_quirks.c,v 1.81 2014/09/12 16:40:38 skrll Exp $"); + +#ifdef _KERNEL_OPT +#include "opt_usb.h" +#endif #include <sys/param.h> #include <sys/systm.h> Index: src/sys/dev/usb/usb_subr.c diff -u src/sys/dev/usb/usb_subr.c:1.196 src/sys/dev/usb/usb_subr.c:1.197 --- src/sys/dev/usb/usb_subr.c:1.196 Mon Feb 17 07:34:21 2014 +++ src/sys/dev/usb/usb_subr.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: usb_subr.c,v 1.196 2014/02/17 07:34:21 skrll Exp $ */ +/* $NetBSD: usb_subr.c,v 1.197 2014/09/12 16:40:38 skrll Exp $ */ /* $FreeBSD: src/sys/dev/usb/usb_subr.c,v 1.18 1999/11/17 22:33:47 n_hibma Exp $ */ /* @@ -32,10 +32,11 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: usb_subr.c,v 1.196 2014/02/17 07:34:21 skrll Exp $"); +__KERNEL_RCSID(0, "$NetBSD: usb_subr.c,v 1.197 2014/09/12 16:40:38 skrll Exp $"); #ifdef _KERNEL_OPT #include "opt_compat_netbsd.h" +#include "opt_usb.h" #include "opt_usbverbose.h" #endif Index: src/sys/dev/usb/usbdi.c diff -u src/sys/dev/usb/usbdi.c:1.161 src/sys/dev/usb/usbdi.c:1.162 --- src/sys/dev/usb/usbdi.c:1.161 Tue Aug 5 06:35:24 2014 +++ src/sys/dev/usb/usbdi.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: usbdi.c,v 1.161 2014/08/05 06:35:24 skrll Exp $ */ +/* $NetBSD: usbdi.c,v 1.162 2014/09/12 16:40:38 skrll Exp $ */ /* * Copyright (c) 1998, 2012 The NetBSD Foundation, Inc. @@ -31,9 +31,10 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: usbdi.c,v 1.161 2014/08/05 06:35:24 skrll Exp $"); +__KERNEL_RCSID(0, "$NetBSD: usbdi.c,v 1.162 2014/09/12 16:40:38 skrll Exp $"); #ifdef _KERNEL_OPT +#include "opt_usb.h" #include "opt_compat_netbsd.h" #endif @@ -52,18 +53,12 @@ __KERNEL_RCSID(0, "$NetBSD: usbdi.c,v 1. #include <dev/usb/usbdivar.h> #include <dev/usb/usb_mem.h> #include <dev/usb/usb_quirks.h> +#include <dev/usb/usbhist.h> /* UTF-8 encoding stuff */ #include <fs/unicode.h> -#ifdef USB_DEBUG -#define DPRINTF(x) if (usbdebug) printf x -#define DPRINTFN(n,x) if (usbdebug>(n)) printf x extern int usbdebug; -#else -#define DPRINTF(x) -#define DPRINTFN(n,x) -#endif Static usbd_status usbd_ar_pipe(usbd_pipe_handle); Static void usbd_start_next(usbd_pipe_handle); @@ -80,41 +75,51 @@ usbd_xfer_isread(usbd_xfer_handle xfer) UE_DIR_IN); } -#if defined(USB_DEBUG) || defined(EHCI_DEBUG) || defined(OHCI_DEBUG) +#if defined(USB_DEBUG) void usbd_dump_iface(struct usbd_interface *iface) { - printf("usbd_dump_iface: iface=%p\n", iface); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + + USBHIST_LOG(usbdebug, "iface %p\n", iface, 0, 0, 0); if (iface == NULL) return; - printf(" device=%p idesc=%p index=%d altindex=%d priv=%p\n", - iface->device, iface->idesc, iface->index, iface->altindex, - iface->priv); + USBHIST_LOG(usbdebug, " device = %p idesc = %p index = %d", + iface->device, iface->idesc, iface->index, 0); + USBHIST_LOG(usbdebug, " altindex=%d priv=%p", + iface->altindex, iface->priv, 0, 0); } void usbd_dump_device(struct usbd_device *dev) { - printf("usbd_dump_device: dev=%p\n", dev); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + + USBHIST_LOG(usbdebug, "dev = %p", dev, 0, 0, 0); if (dev == NULL) return; - printf(" bus=%p default_pipe=%p\n", dev->bus, dev->default_pipe); - printf(" address=%d config=%d depth=%d speed=%d self_powered=%d " - "power=%d langid=%d\n", - dev->address, dev->config, dev->depth, dev->speed, - dev->self_powered, dev->power, dev->langid); + USBHIST_LOG(usbdebug, " bus = %p default_pipe = %p", + dev->bus, dev->default_pipe, 0, 0); + USBHIST_LOG(usbdebug, " address = %d config = %d depth = %d ", + dev->address, dev->config, dev->depth, 0); + USBHIST_LOG(usbdebug, " speed = %d self_powered = %d " + "power = %d langid = %d", + dev->speed, dev->self_powered, dev->power, dev->langid); } void usbd_dump_endpoint(struct usbd_endpoint *endp) { - printf("usbd_dump_endpoint: endp=%p\n", endp); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + + USBHIST_LOG(usbdebug, "endp = %p", endp, 0, 0, 0); if (endp == NULL) return; - printf(" edesc=%p refcnt=%d\n", endp->edesc, endp->refcnt); + USBHIST_LOG(usbdebug, " edesc = %p refcnt = %d", + endp->edesc, endp->refcnt, 0, 0); if (endp->edesc) - printf(" bEndpointAddress=0x%02x\n", - endp->edesc->bEndpointAddress); + USBHIST_LOG(usbdebug, " bEndpointAddress=0x%02x", + endp->edesc->bEndpointAddress, 0, 0, 0); } void @@ -122,25 +127,30 @@ usbd_dump_queue(usbd_pipe_handle pipe) { usbd_xfer_handle xfer; - printf("usbd_dump_queue: pipe=%p\n", pipe); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + + USBHIST_LOG(usbdebug, "pipe = %p", pipe, 0, 0, 0); SIMPLEQ_FOREACH(xfer, &pipe->queue, next) { - printf(" xfer=%p\n", xfer); + USBHIST_LOG(usbdebug, " xfer = %p", xfer, 0, 0, 0); } } void usbd_dump_pipe(usbd_pipe_handle pipe) { - printf("usbd_dump_pipe: pipe=%p\n", pipe); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + + USBHIST_LOG(usbdebug, "pipe = %p", pipe, 0, 0, 0); if (pipe == NULL) return; usbd_dump_iface(pipe->iface); usbd_dump_device(pipe->device); usbd_dump_endpoint(pipe->endpoint); - printf(" (usbd_dump_pipe:)\n refcnt=%d running=%d aborting=%d\n", - pipe->refcnt, pipe->running, pipe->aborting); - printf(" intrxfer=%p, repeat=%d, interval=%d\n", - pipe->intrxfer, pipe->repeat, pipe->interval); + USBHIST_LOG(usbdebug, "(usbd_dump_pipe)", 0, 0, 0, 0); + USBHIST_LOG(usbdebug, " refcnt = %d running = %d aborting = %d", + pipe->refcnt, pipe->running, pipe->aborting, 0); + USBHIST_LOG(usbdebug, " intrxfer = %p, repeat = %d, interval = %d", + pipe->intrxfer, pipe->repeat, pipe->interval, 0); } #endif @@ -161,8 +171,10 @@ usbd_open_pipe_ival(usbd_interface_handl usbd_status err; int i; - DPRINTFN(3,("usbd_open_pipe: iface=%p address=0x%x flags=0x%x\n", - iface, address, flags)); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + + USBHIST_LOG(usbdebug, "iface = %p address = 0x%x flags = 0x%x", + iface, address, flags, 0); for (i = 0; i < iface->idesc->bNumEndpoints; i++) { ep = &iface->endpoints[i]; @@ -193,8 +205,10 @@ usbd_open_pipe_intr(usbd_interface_handl usbd_xfer_handle xfer; usbd_pipe_handle ipipe; - DPRINTFN(3,("usbd_open_pipe_intr: address=0x%x flags=0x%x len=%d\n", - address, flags, len)); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + + USBHIST_LOG(usbdebug, "address = 0x%x flags = 0x%x len = %d", + address, flags, len, 0); err = usbd_open_pipe_ival(iface, address, USBD_EXCLUSIVE_USE | (flags & USBD_MPSAFE), @@ -229,9 +243,11 @@ usbd_status usbd_close_pipe(usbd_pipe_handle pipe) { + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + #ifdef DIAGNOSTIC if (pipe == NULL) { - printf("usbd_close_pipe: pipe==NULL\n"); + USBHIST_LOG(usbdebug, "pipe == NULL", 0, 0, 0, 0); return (USBD_NORMAL_COMPLETION); } #endif @@ -263,8 +279,11 @@ usbd_transfer(usbd_xfer_handle xfer) usbd_status err; unsigned int size, flags; - DPRINTFN(5,("usbd_transfer: xfer=%p, flags=%#x, pipe=%p, running=%d\n", - xfer, xfer->flags, pipe, pipe->running)); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + + USBHIST_LOG(usbdebug, + "xfer = %p, flags = %#x, pipe = %p, running = %d", + xfer, xfer->flags, pipe, pipe->running); #ifdef USB_DEBUG if (usbdebug > 5) @@ -272,8 +291,11 @@ usbd_transfer(usbd_xfer_handle xfer) #endif xfer->done = 0; - if (pipe->aborting) + if (pipe->aborting) { + USBHIST_LOG(usbdebug, "<- done xfer %p, aborting", xfer, 0, 0, + 0); return (USBD_CANCELLED); + } size = xfer->length; /* If there is no buffer, allocate one. */ @@ -285,8 +307,11 @@ usbd_transfer(usbd_xfer_handle xfer) printf("usbd_transfer: has old buffer!\n"); #endif err = bus->methods->allocm(bus, dmap, size); - if (err) + if (err) { + USBHIST_LOG(usbdebug, + "<- done xfer %p, no mem", xfer, 0, 0, 0); return (err); + } xfer->rqflags |= URQ_AUTO_DMABUF; } @@ -298,6 +323,7 @@ usbd_transfer(usbd_xfer_handle xfer) /* xfer is not valid after the transfer method unless synchronous */ err = pipe->methods->transfer(xfer); + USBHIST_LOG(usbdebug, "<- done transfer %p, err = %d", xfer, err, 0, 0); if (err != USBD_IN_PROGRESS && err) { /* The transfer has not been queued, so free buffer. */ @@ -309,16 +335,23 @@ usbd_transfer(usbd_xfer_handle xfer) } } - if (!(flags & USBD_SYNCHRONOUS)) + if (!(flags & USBD_SYNCHRONOUS)) { + USBHIST_LOG(usbdebug, "<- done xfer %p, not sync", xfer, 0, 0, + 0); return (err); + } /* Sync transfer, wait for completion. */ - if (err != USBD_IN_PROGRESS) + if (err != USBD_IN_PROGRESS) { + USBHIST_LOG(usbdebug, "<- done xfer %p, not in progress", xfer, + 0, 0, 0); return (err); + } usbd_lock_pipe(pipe); while (!xfer->done) { if (pipe->device->bus->use_polling) panic("usbd_transfer: not done"); + USBHIST_LOG(usbdebug, "<- sleeping on xfer %p", xfer, 0, 0, 0); err = 0; if ((flags & USBD_SYNCHRONOUS_SIG) != 0) { @@ -395,6 +428,8 @@ usbd_alloc_xfer(usbd_device_handle dev) { usbd_xfer_handle xfer; + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + xfer = dev->bus->methods->allocx(dev->bus); if (xfer == NULL) return (NULL); @@ -402,14 +437,18 @@ usbd_alloc_xfer(usbd_device_handle dev) callout_init(&xfer->timeout_handle, CALLOUT_MPSAFE); cv_init(&xfer->cv, "usbxfer"); cv_init(&xfer->hccv, "usbhcxfer"); - DPRINTFN(5,("usbd_alloc_xfer() = %p\n", xfer)); + + USBHIST_LOG(usbdebug, "returns %p", xfer, 0, 0, 0); + return (xfer); } usbd_status usbd_free_xfer(usbd_xfer_handle xfer) { - DPRINTFN(5,("usbd_free_xfer: %p\n", xfer)); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + + USBHIST_LOG(usbdebug, "%p", xfer, 0, 0, 0); if (xfer->rqflags & (URQ_DEV_DMABUF | URQ_AUTO_DMABUF)) usbd_free_buffer(xfer); #if defined(DIAGNOSTIC) @@ -568,7 +607,7 @@ usbd_clear_endpoint_stall(usbd_pipe_hand usb_device_request_t req; usbd_status err; - DPRINTFN(8, ("usbd_clear_endpoint_stall\n")); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); /* * Clearing en endpoint stall resets the endpoint toggle, so @@ -749,9 +788,11 @@ usbd_ar_pipe(usbd_pipe_handle pipe) { usbd_xfer_handle xfer; + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + KASSERT(mutex_owned(pipe->device->bus->lock)); - DPRINTFN(2,("usbd_ar_pipe: pipe=%p\n", pipe)); + USBHIST_LOG(usbdebug, "pipe = %p", pipe, 0, 0, 0); #ifdef USB_DEBUG if (usbdebug > 5) usbd_dump_queue(pipe); @@ -759,8 +800,8 @@ usbd_ar_pipe(usbd_pipe_handle pipe) pipe->repeat = 0; pipe->aborting = 1; while ((xfer = SIMPLEQ_FIRST(&pipe->queue)) != NULL) { - DPRINTFN(2,("usbd_ar_pipe: pipe=%p xfer=%p (methods=%p)\n", - pipe, xfer, pipe->methods)); + USBHIST_LOG(usbdebug, "pipe = %p xfer = %p (methods = %p)", + pipe, xfer, pipe->methods, 0); /* Make the HC abort it (and invoke the callback). */ pipe->methods->abort(xfer); /* XXX only for non-0 usbd_clear_endpoint_stall(pipe); */ @@ -781,8 +822,10 @@ usb_transfer_complete(usbd_xfer_handle x int polling = pipe->device->bus->use_polling; int repeat; - DPRINTFN(5, ("usb_transfer_complete: pipe=%p xfer=%p status=%d " - "actlen=%d\n", pipe, xfer, xfer->status, xfer->actlen)); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + + USBHIST_LOG(usbdebug, "pipe = %p xfer = %p status = %d actlen = %d", + pipe, xfer, xfer->status, xfer->actlen); KASSERT(polling || mutex_owned(pipe->device->bus->lock)); @@ -839,8 +882,8 @@ usb_transfer_complete(usbd_xfer_handle x #endif SIMPLEQ_REMOVE_HEAD(&pipe->queue, next); } - DPRINTFN(5,("usb_transfer_complete: repeat=%d new head=%p\n", - repeat, SIMPLEQ_FIRST(&pipe->queue))); + USBHIST_LOG(usbdebug, "xfer %p: repeat %d new head = %p", + xfer, repeat, SIMPLEQ_FIRST(&pipe->queue), 0); /* Count completed transfers. */ ++pipe->device->bus->stats.uds_requests @@ -849,12 +892,14 @@ usb_transfer_complete(usbd_xfer_handle x xfer->done = 1; if (!xfer->status && xfer->actlen < xfer->length && !(xfer->flags & USBD_SHORT_XFER_OK)) { - DPRINTFN(-1,("usb_transfer_complete: short transfer %d<%d\n", - xfer->actlen, xfer->length)); + USBHIST_LOG(usbdebug, "short transfer %d < %d", + xfer->actlen, xfer->length, 0, 0); xfer->status = USBD_SHORT_XFER; } if (repeat) { + USBHIST_LOG(usbdebug, "xfer %p doing callback %p status %x", + xfer, xfer->callback, xfer->status, 0); if (xfer->callback) { if (!polling) mutex_exit(pipe->device->bus->lock); @@ -862,6 +907,8 @@ usb_transfer_complete(usbd_xfer_handle x if (!(pipe->flags & USBD_MPSAFE)) KERNEL_LOCK(1, curlwp); xfer->callback(xfer, xfer->priv, xfer->status); + USBHIST_LOG(usbdebug, "xfer %p doing done %p", xfer, + pipe->methods->done, 0, 0); if (!(pipe->flags & USBD_MPSAFE)) KERNEL_UNLOCK_ONE(curlwp); @@ -870,7 +917,11 @@ usb_transfer_complete(usbd_xfer_handle x } pipe->methods->done(xfer); } else { + USBHIST_LOG(usbdebug, "xfer %p doing done %p", xfer, + pipe->methods->done, 0, 0); pipe->methods->done(xfer); + USBHIST_LOG(usbdebug, "xfer %p doing callback %p status %x", + xfer, xfer->callback, xfer->status, 0); if (xfer->callback) { if (!polling) mutex_exit(pipe->device->bus->lock); @@ -887,6 +938,7 @@ usb_transfer_complete(usbd_xfer_handle x } if (sync && !polling) { + USBHIST_LOG(usbdebug, "<- done xfer %p, wakeup", xfer, 0, 0, 0); cv_broadcast(&xfer->cv); } @@ -906,13 +958,17 @@ usb_insert_transfer(usbd_xfer_handle xfe usbd_pipe_handle pipe = xfer->pipe; usbd_status err; - DPRINTFN(5,("usb_insert_transfer: pipe=%p running=%d timeout=%d\n", - pipe, pipe->running, xfer->timeout)); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + + USBHIST_LOG(usbdebug, "pipe = %p running = %d timeout = %d", + pipe, pipe->running, xfer->timeout, 0); KASSERT(mutex_owned(pipe->device->bus->lock)); #ifdef DIAGNOSTIC if (xfer->busy_free != XFER_BUSY) { + USBHIST_LOG(usbdebug, "<- done, xfer %p not busy", xfer, 0, 0, + 0); printf("usb_insert_transfer: xfer=%p not busy 0x%08x\n", xfer, xfer->busy_free); return (USBD_INVAL); @@ -926,6 +982,7 @@ usb_insert_transfer(usbd_xfer_handle xfe pipe->running = 1; err = USBD_NORMAL_COMPLETION; } + USBHIST_LOG(usbdebug, "<- done xfer %p, err %d", xfer, err, 0, 0); return (err); } @@ -936,6 +993,8 @@ usbd_start_next(usbd_pipe_handle pipe) usbd_xfer_handle xfer; usbd_status err; + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + #ifdef DIAGNOSTIC if (pipe == NULL) { printf("usbd_start_next: pipe == NULL\n"); @@ -951,7 +1010,7 @@ usbd_start_next(usbd_pipe_handle pipe) /* Get next request in queue. */ xfer = SIMPLEQ_FIRST(&pipe->queue); - DPRINTFN(5, ("usbd_start_next: pipe=%p, xfer=%p\n", pipe, xfer)); + USBHIST_LOG(usbdebug, "pipe = %p, xfer = %p", pipe, xfer, 0, 0); if (xfer == NULL) { pipe->running = 0; } else { @@ -960,7 +1019,7 @@ usbd_start_next(usbd_pipe_handle pipe) mutex_enter(pipe->device->bus->lock); if (err != USBD_IN_PROGRESS) { - printf("usbd_start_next: error=%d\n", err); + USBHIST_LOG(usbdebug, "error = %d", err, 0, 0, 0); pipe->running = 0; /* XXX do what? */ } @@ -992,9 +1051,11 @@ usbd_do_request_flags_pipe(usbd_device_h usbd_xfer_handle xfer; usbd_status err; + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + #ifdef DIAGNOSTIC if (cpu_intr_p() || cpu_softintr_p()) { - printf("usbd_do_request: not in process context\n"); + USBHIST_LOG(usbdebug, "not in process context", 0, 0, 0, 0); return (USBD_INVAL); } #endif @@ -1008,13 +1069,14 @@ usbd_do_request_flags_pipe(usbd_device_h err = usbd_sync_transfer(xfer); #if defined(USB_DEBUG) || defined(DIAGNOSTIC) if (xfer->actlen > xfer->length) { - DPRINTF(("%s: overrun addr=%d type=0x%02x req=0x" - "%02x val=%d index=%d rlen=%d length=%d actlen=%d\n", - __func__, dev->address, xfer->request.bmRequestType, - xfer->request.bRequest, UGETW(xfer->request.wValue), - UGETW(xfer->request.wIndex), - UGETW(xfer->request.wLength), - xfer->length, xfer->actlen)); + USBHIST_LOG(usbdebug, "overrun addr = %d type = 0x%02x", + dev->address, xfer->request.bmRequestType, 0, 0); + USBHIST_LOG(usbdebug, " req = 0x%02x val = %d index = %d", + xfer->request.bRequest, UGETW(xfer->request.wValue), + UGETW(xfer->request.wIndex), 0); + USBHIST_LOG(usbdebug, " rlen = %d length = %d actlen = %d", + UGETW(xfer->request.wLength), + xfer->length, xfer->actlen, 0); } #endif if (actlen != NULL) @@ -1042,7 +1104,7 @@ usbd_do_request_flags_pipe(usbd_device_h if (nerr) goto bad; s = UGETW(status.wStatus); - DPRINTF(("usbd_do_request: status = 0x%04x\n", s)); + USBHIST_LOG(usbdebug, "status = 0x%04x", s, 0, 0, 0); if (!(s & UES_HALT)) goto bad; treq.bmRequestType = UT_WRITE_ENDPOINT; @@ -1059,7 +1121,8 @@ usbd_do_request_flags_pipe(usbd_device_h bad: if (err) { - DPRINTF(("%s: returning err=%s\n", __func__, usbd_errstr(err))); + USBHIST_LOG(usbdebug, "returning err = %s", + usbd_errstr(err), 0, 0, 0); } usbd_free_xfer(xfer); return (err); @@ -1202,6 +1265,8 @@ usbd_get_string0(usbd_device_handle dev, usbd_status err; int size; + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + buf[0] = '\0'; if (si == 0) return (USBD_INVAL); @@ -1212,7 +1277,8 @@ usbd_get_string0(usbd_device_handle dev, err = usbd_get_string_desc(dev, USB_LANGUAGE_TABLE, 0, &us, &size); if (err || size < 4) { - DPRINTFN(-1,("usbd_get_string: getting lang failed, using 0\n")); + USBHIST_LOG(usbdebug, "getting lang failed, using 0", + 0, 0, 0, 0); dev->langid = 0; /* Well, just pick something then */ } else { /* Pick the first language as the default. */ Index: src/sys/dev/usb/usbdi_util.c diff -u src/sys/dev/usb/usbdi_util.c:1.62 src/sys/dev/usb/usbdi_util.c:1.63 --- src/sys/dev/usb/usbdi_util.c:1.62 Thu Sep 26 07:25:31 2013 +++ src/sys/dev/usb/usbdi_util.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: usbdi_util.c,v 1.62 2013/09/26 07:25:31 skrll Exp $ */ +/* $NetBSD: usbdi_util.c,v 1.63 2014/09/12 16:40:38 skrll Exp $ */ /* * Copyright (c) 1998, 2012 The NetBSD Foundation, Inc. @@ -31,7 +31,11 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: usbdi_util.c,v 1.62 2013/09/26 07:25:31 skrll Exp $"); +__KERNEL_RCSID(0, "$NetBSD: usbdi_util.c,v 1.63 2014/09/12 16:40:38 skrll Exp $"); + +#ifdef _KERNEL_OPT +#include "opt_usb.h" +#endif #include <sys/param.h> #include <sys/systm.h> @@ -43,10 +47,10 @@ __KERNEL_RCSID(0, "$NetBSD: usbdi_util.c #include <dev/usb/usb.h> #include <dev/usb/usbhid.h> - #include <dev/usb/usbdi.h> #include <dev/usb/usbdivar.h> #include <dev/usb/usbdi_util.h> +#include <dev/usb/usbhist.h> #ifdef USB_DEBUG #define DPRINTF(x) if (usbdebug) printf x @@ -402,8 +406,9 @@ usbd_bulk_transfer(usbd_xfer_handle xfer { usbd_status err; - usbd_setup_xfer(xfer, pipe, 0, buf, *size, flags, timeout, NULL); + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + usbd_setup_xfer(xfer, pipe, 0, buf, *size, flags, timeout, NULL); DPRINTFN(1, ("usbd_bulk_transfer: start transfer %d bytes\n", *size)); err = usbd_sync_transfer_sig(xfer); @@ -413,6 +418,7 @@ usbd_bulk_transfer(usbd_xfer_handle xfer DPRINTF(("usbd_bulk_transfer: error=%d\n", err)); usbd_clear_endpoint_stall(pipe); } + USBHIST_LOG(usbdebug, "<- done err %d", xfer, err, 0, 0); return (err); } @@ -424,6 +430,8 @@ usbd_intr_transfer(usbd_xfer_handle xfer { usbd_status err; + USBHIST_FUNC(); USBHIST_CALLED(usbdebug); + usbd_setup_xfer(xfer, pipe, 0, buf, *size, flags, timeout, NULL); DPRINTFN(1, ("usbd_intr_transfer: start transfer %d bytes\n", *size)); @@ -436,6 +444,8 @@ usbd_intr_transfer(usbd_xfer_handle xfer DPRINTF(("usbd_intr_transfer: error=%d\n", err)); usbd_clear_endpoint_stall(pipe); } + USBHIST_LOG(usbdebug, "<- done err %d", xfer, err, 0, 0); + return (err); } Index: src/sys/dev/usb/uvideo.c diff -u src/sys/dev/usb/uvideo.c:1.40 src/sys/dev/usb/uvideo.c:1.41 --- src/sys/dev/usb/uvideo.c:1.40 Tue Jan 28 13:43:33 2014 +++ src/sys/dev/usb/uvideo.c Fri Sep 12 16:40:38 2014 @@ -1,4 +1,4 @@ -/* $NetBSD: uvideo.c,v 1.40 2014/01/28 13:43:33 martin Exp $ */ +/* $NetBSD: uvideo.c,v 1.41 2014/09/12 16:40:38 skrll Exp $ */ /* * Copyright (c) 2008 Patrick Mahoney @@ -42,10 +42,10 @@ */ #include <sys/cdefs.h> -__KERNEL_RCSID(0, "$NetBSD: uvideo.c,v 1.40 2014/01/28 13:43:33 martin Exp $"); +__KERNEL_RCSID(0, "$NetBSD: uvideo.c,v 1.41 2014/09/12 16:40:38 skrll Exp $"); #ifdef _KERNEL_OPT -#include "opt_uvideo.h" +#include "opt_usb.h" #endif #ifdef _MODULE Index: src/sys/external/bsd/dwc2/conf/files.dwc2 diff -u src/sys/external/bsd/dwc2/conf/files.dwc2:1.1 src/sys/external/bsd/dwc2/conf/files.dwc2:1.2 --- src/sys/external/bsd/dwc2/conf/files.dwc2:1.1 Thu Sep 5 20:25:27 2013 +++ src/sys/external/bsd/dwc2/conf/files.dwc2 Fri Sep 12 16:40:38 2014 @@ -1,12 +1,10 @@ -# $NetBSD: files.dwc2,v 1.1 2013/09/05 20:25:27 skrll Exp $ +# $NetBSD: files.dwc2,v 1.2 2014/09/12 16:40:38 skrll Exp $ # DesignWare HS OTG Controller # device dwctwo: usbus, usbroothub, usb_dma file external/bsd/dwc2/dwc2.c dwctwo needs-flag -defflag opt_usb.h DWC2_DEBUG - makeoptions dwctwo CPPFLAGS+=" -I$S/external/bsd/common/include -I$S/external/bsd -I$S/external/bsd/dwc2/dist" file external/bsd/dwc2/dist/dwc2_core.c dwctwo Added files: Index: src/sys/dev/usb/usbhist.h diff -u /dev/null src/sys/dev/usb/usbhist.h:1.1 --- /dev/null Fri Sep 12 16:40:38 2014 +++ src/sys/dev/usb/usbhist.h Fri Sep 12 16:40:38 2014 @@ -0,0 +1,83 @@ +/* $NetBSD: usbhist.h,v 1.1 2014/09/12 16:40:38 skrll Exp $ */ + +/* + * Copyright (c) 2012 Matthew R. Green + * All rights reserved. + * + * Redistribution and use in source and binary forms, with or without + * modification, are permitted provided that the following conditions + * are met: + * 1. Redistributions of source code must retain the above copyright + * notice, this list of conditions and the following disclaimer. + * 2. Redistributions in binary form must reproduce the above copyright + * notice, this list of conditions and the following disclaimer in the + * documentation and/or other materials provided with the distribution. + * 3. The name of the author may not be used to endorse or promote products + * derived from this software without specific prior written permission. + * + * THIS SOFTWARE IS PROVIDED BY THE AUTHOR ``AS IS'' AND ANY EXPRESS OR + * IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES + * OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED. + * IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR ANY DIRECT, INDIRECT, + * INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, + * BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; + * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED + * AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, + * OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY + * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF + * SUCH DAMAGE. + */ + +#ifndef _DEV_USB_USBHIST_H_ +#define _DEV_USB_USBHIST_H_ + +#if defined(_KERNEL_OPT) +#include "opt_usb.h" +#endif + +/* + * Make USBHIST_PRINT force on KERNHIST_PRINT for at least USBHIST_* usage. + */ +#if defined(USBHIST_PRINT) && !defined(KERNHIST_PRINT) +#define KERNHIST_PRINT 1 +#endif + +#include <sys/kernhist.h> + +#ifdef USBHIST + +extern int usbdebug; + +#define USBHIST_DECL(NAME) KERNHIST_DECL(NAME) +#define USBHIST_DEFINE(NAME) KERNHIST_DEFINE(NAME) +#define USBHIST_INIT(NAME,N) KERNHIST_INIT(NAME,N) +#define USBHIST_INIT_STATIC(NAME,BUF) KERNHIST_INIT_STATIC(NAME,BUF) +#define USBHIST_LOGN(NAME,N,FMT,A,B,C,D) do { \ + if ((NAME) >= (N)) { \ + KERNHIST_LOG(usbhist,FMT,A,B,C,D); \ + } \ +} while (0) +#define USBHIST_LOG(NAME,FMT,A,B,C,D) USBHIST_LOGN(NAME,1,FMT,A,B,C,D) +#define USBHIST_CALLED(NAME) do { \ + if ((NAME) != 0) { \ + KERNHIST_CALLED(usbhist); \ + } \ +} while (0) +#define USBHIST_FUNC() KERNHIST_FUNC(__func__) + +USBHIST_DECL(usbhist); + +#else + +#define USBHIST_DECL(NAME) +#define USBHIST_DEFINE(NAME) +#define USBHIST_INIT(NAME,N) +#define USBHIST_INIT_STATIC(NAME,BUF) +#define USBHIST_LOGN(N,NAME,FMT,A,B,C,D) do { } while(0) +#define USBHIST_LOG(NAME,FMT,A,B,C,D) do { } while(0) +#define USBHIST_CALLED(NAME) +#define USBHIST_FUNC() + +#endif + +#endif /* _DEV_USBUSB_HIST_H_ */