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_ */

Reply via email to