Index: sys/dev/usb/files.usb =================================================================== RCS file: /cvsroot/src/sys/dev/usb/files.usb,v retrieving revision 1.133 diff -p -u -r1.133 files.usb --- sys/dev/usb/files.usb 12 Aug 2014 13:28:44 -0000 1.133 +++ sys/dev/usb/files.usb 22 Aug 2014 08:14:01 -0000 @@ -14,6 +14,8 @@ defflag opt_uvideo.h UVIDEO_DEBUG defflag opt_umass.h UMASS_DEBUG defflag opt_uatp.h UATP_DEBUG +defflag opt_usbhist.h USBHIST + define usbroothubif { } define usbdevif { [port = -1], [configuration = -1], [interface = -1], [vendor = -1], [product = -1], [release = -1] } Index: sys/dev/usb/umass.c =================================================================== RCS file: /cvsroot/src/sys/dev/usb/umass.c,v retrieving revision 1.148 diff -p -u -r1.148 umass.c --- sys/dev/usb/umass.c 22 Dec 2013 18:30:21 -0000 1.148 +++ sys/dev/usb/umass.c 22 Aug 2014 08:14:01 -0000 @@ -146,6 +146,7 @@ __KERNEL_RCSID(0, "$NetBSD: umass.c,v 1. #include #include #include +#include #include #include @@ -786,6 +787,8 @@ umass_setup_transfer(struct umass_softc { usbd_status err; + USBHIST_FUNC(); USBHIST_CALLED(usbxferhist); + if (sc->sc_dying) return (USBD_IOERROR); @@ -794,6 +797,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(usbxferhist, "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 +1042,8 @@ umass_bbb_state(usbd_xfer_handle xfer, u usbd_xfer_handle next_xfer; int residue; + USBHIST_FUNC(); USBHIST_CALLED(usbxferhist); + KASSERTMSG(sc->sc_wire & UMASS_WPROTO_BBB, "sc->sc_wire == 0x%02x wrong for umass_bbb_state\n", sc->sc_wire); @@ -1059,6 +1066,8 @@ 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(usbxferhist, "xfer %p, transfer_state %d dir %d", xfer, sc->transfer_state, sc->transfer_dir, 0); + switch (sc->transfer_state) { /***** Bulk Transfer *****/ Index: sys/dev/usb/usb.c =================================================================== RCS file: /cvsroot/src/sys/dev/usb/usb.c,v retrieving revision 1.155 diff -p -u -r1.155 usb.c --- sys/dev/usb/usb.c 12 Aug 2014 13:36:40 -0000 1.155 +++ sys/dev/usb/usb.c 22 Aug 2014 08:14:01 -0000 @@ -69,6 +69,9 @@ __KERNEL_RCSID(0, "$NetBSD: usb.c,v 1.15 #include #include #include +#include + +USBHIST_DEFINE(usbxferhist); #define USB_DEV_MINOR 255 @@ -212,6 +215,14 @@ usb_attach(device_t parent, device_t sel } aprint_normal("\n"); + /* XXX RUN_ONCE */ + { static int first = 1; + if (first) { + USBHIST_INIT(usbxferhist, 400); + first = 0; + } + } + /* XXX we should have our own level */ sc->sc_bus->soft = softint_establish(SOFTINT_NET | SOFTINT_MPSAFE, usb_soft_intr, sc->sc_bus); Index: sys/dev/usb/usb_hist.h =================================================================== RCS file: sys/dev/usb/usb_hist.h diff -N sys/dev/usb/usb_hist.h --- /dev/null 1 Jan 1970 00:00:00 -0000 +++ sys/dev/usb/usb_hist.h 22 Aug 2014 08:14:01 -0000 @@ -0,0 +1,76 @@ +/* $NetBSD$ */ + +/* + * Copyright (c) 2012, 2014 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_USB_HIST_H_ +#define _DEV_USB_USB_HIST_H_ + +#if defined(_KERNEL_OPT) +#include "opt_usbhist.h" +#include "opt_kernhist.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 + +#ifdef USBHIST + +#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_INITIALIZER(NAME,BUF) KERNHIST_INITIALIZER(NAME,BUF) +#define USBHIST_LINK_STATIC(NAME) KERNHIST_LINK_STATIC(NAME) +#define USBHIST_LOG(NAME,FMT,A,B,C,D) KERNHIST_LOG(NAME,FMT,A,B,C,D) +#define USBHIST_CALLED(NAME) KERNHIST_CALLED(NAME) +#define USBHIST_FUNC() KERNHIST_FUNC(__func__) + +USBHIST_DECL(usbxferhist); + +#else + +#define USBHIST_DECL(NAME) +#define USBHIST_DEFINE(NAME) +#define USBHIST_INIT(NAME,N) +#define USBHIST_INIT_STATIC(NAME,BUF) +#define USBHIST_INITIALIZER(NAME,BUF) +#define USBHIST_LINK_STATIC(NAME) +#define USBHIST_LOG(NAME,FMT,A,B,C,D) +#define USBHIST_CALLED(NAME) +#define USBHIST_FUNC() + +#endif + +#endif /* _DEV_USB_USB_HIST_H_ */ Index: sys/dev/usb/usbdi.c =================================================================== RCS file: /cvsroot/src/sys/dev/usb/usbdi.c,v retrieving revision 1.161 diff -p -u -r1.161 usbdi.c --- sys/dev/usb/usbdi.c 5 Aug 2014 06:35:24 -0000 1.161 +++ sys/dev/usb/usbdi.c 22 Aug 2014 08:14:01 -0000 @@ -52,6 +52,7 @@ __KERNEL_RCSID(0, "$NetBSD: usbdi.c,v 1. #include #include #include +#include /* UTF-8 encoding stuff */ #include @@ -263,6 +264,8 @@ usbd_transfer(usbd_xfer_handle xfer) usbd_status err; unsigned int size, flags; + USBHIST_FUNC(); USBHIST_CALLED(usbxferhist); + DPRINTFN(5,("usbd_transfer: xfer=%p, flags=%#x, pipe=%p, running=%d\n", xfer, xfer->flags, pipe, pipe->running)); @@ -272,8 +275,10 @@ usbd_transfer(usbd_xfer_handle xfer) #endif xfer->done = 0; - if (pipe->aborting) + if (pipe->aborting) { + USBHIST_LOG(usbxferhist, "<- done xfer %p, aborting", xfer, 0, 0, 0); return (USBD_CANCELLED); + } size = xfer->length; /* If there is no buffer, allocate one. */ @@ -285,8 +290,10 @@ 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(usbxferhist, "<- done xfer %p, no mem", xfer, 0, 0, 0); return (err); + } xfer->rqflags |= URQ_AUTO_DMABUF; } @@ -298,6 +305,7 @@ usbd_transfer(usbd_xfer_handle xfer) /* xfer is not valid after the transfer method unless synchronous */ err = pipe->methods->transfer(xfer); + USBHIST_LOG(usbxferhist, "<- 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 +317,21 @@ usbd_transfer(usbd_xfer_handle xfer) } } - if (!(flags & USBD_SYNCHRONOUS)) + if (!(flags & USBD_SYNCHRONOUS)) { + USBHIST_LOG(usbxferhist, "<- 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(usbxferhist, "<- 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(usbxferhist, "<- sleeping on xfer %p", xfer, 0, 0, 0); err = 0; if ((flags & USBD_SYNCHRONOUS_SIG) != 0) { @@ -781,6 +794,8 @@ usb_transfer_complete(usbd_xfer_handle x int polling = pipe->device->bus->use_polling; int repeat; + USBHIST_FUNC(); USBHIST_CALLED(usbxferhist); + DPRINTFN(5, ("usb_transfer_complete: pipe=%p xfer=%p status=%d " "actlen=%d\n", pipe, xfer, xfer->status, xfer->actlen)); @@ -842,6 +857,8 @@ usb_transfer_complete(usbd_xfer_handle x DPRINTFN(5,("usb_transfer_complete: repeat=%d new head=%p\n", repeat, SIMPLEQ_FIRST(&pipe->queue))); + USBHIST_LOG(usbxferhist, "xfer %p: repeat %d new head=%p", xfer, repeat, SIMPLEQ_FIRST(&pipe->queue), 0); + /* Count completed transfers. */ ++pipe->device->bus->stats.uds_requests [pipe->endpoint->edesc->bmAttributes & UE_XFERTYPE]; @@ -855,6 +872,7 @@ usb_transfer_complete(usbd_xfer_handle x } if (repeat) { + USBHIST_LOG(usbxferhist, "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 +880,7 @@ 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(usbxferhist, "xfer %p doing done %p", xfer, pipe->methods->done, 0, 0); if (!(pipe->flags & USBD_MPSAFE)) KERNEL_UNLOCK_ONE(curlwp); @@ -870,7 +889,9 @@ usb_transfer_complete(usbd_xfer_handle x } pipe->methods->done(xfer); } else { + USBHIST_LOG(usbxferhist, "xfer %p doing done %p", xfer, pipe->methods->done, 0, 0); pipe->methods->done(xfer); + USBHIST_LOG(usbxferhist, "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 +908,7 @@ usb_transfer_complete(usbd_xfer_handle x } if (sync && !polling) { + USBHIST_LOG(usbxferhist, "<- done xfer %p, wakeup", xfer, 0, 0, 0); cv_broadcast(&xfer->cv); } @@ -906,6 +928,8 @@ usb_insert_transfer(usbd_xfer_handle xfe usbd_pipe_handle pipe = xfer->pipe; usbd_status err; + USBHIST_FUNC(); USBHIST_CALLED(usbxferhist); + DPRINTFN(5,("usb_insert_transfer: pipe=%p running=%d timeout=%d\n", pipe, pipe->running, xfer->timeout)); @@ -913,6 +937,7 @@ usb_insert_transfer(usbd_xfer_handle xfe #ifdef DIAGNOSTIC if (xfer->busy_free != XFER_BUSY) { + USBHIST_LOG(usbxferhist, "<- 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 +951,7 @@ usb_insert_transfer(usbd_xfer_handle xfe pipe->running = 1; err = USBD_NORMAL_COMPLETION; } + USBHIST_LOG(usbxferhist, "<- done xfer %p, err %d", xfer, err, 0, 0); return (err); } Index: sys/dev/usb/usbdi_util.c =================================================================== RCS file: /cvsroot/src/sys/dev/usb/usbdi_util.c,v retrieving revision 1.62 diff -p -u -r1.62 usbdi_util.c --- sys/dev/usb/usbdi_util.c 26 Sep 2013 07:25:31 -0000 1.62 +++ sys/dev/usb/usbdi_util.c 22 Aug 2014 08:14:01 -0000 @@ -43,10 +43,10 @@ __KERNEL_RCSID(0, "$NetBSD: usbdi_util.c #include #include - #include #include #include +#include #ifdef USB_DEBUG #define DPRINTF(x) if (usbdebug) printf x @@ -402,8 +402,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(usbxferhist); + 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 +414,7 @@ usbd_bulk_transfer(usbd_xfer_handle xfer DPRINTF(("usbd_bulk_transfer: error=%d\n", err)); usbd_clear_endpoint_stall(pipe); } + USBHIST_LOG(usbxferhist, "<- done err %d", xfer, err, 0, 0); return (err); } @@ -424,6 +426,8 @@ usbd_intr_transfer(usbd_xfer_handle xfer { usbd_status err; + USBHIST_FUNC(); USBHIST_CALLED(usbxferhist); + usbd_setup_xfer(xfer, pipe, 0, buf, *size, flags, timeout, NULL); DPRINTFN(1, ("usbd_intr_transfer: start transfer %d bytes\n", *size)); @@ -436,6 +440,8 @@ usbd_intr_transfer(usbd_xfer_handle xfer DPRINTF(("usbd_intr_transfer: error=%d\n", err)); usbd_clear_endpoint_stall(pipe); } + USBHIST_LOG(usbxferhist, "<- done err %d", xfer, err, 0, 0); + return (err); }