Index: files.usb =================================================================== RCS file: /cvsroot/src/sys/dev/usb/files.usb,v retrieving revision 1.127 diff -p -r1.127 files.usb *** files.usb 13 Jan 2013 01:15:02 -0000 1.127 --- files.usb 24 Jan 2013 08:49:55 -0000 *************** defflag opt_usb.h EHCI_DEBUG OHCI_DEBUG *** 11,16 **** --- 11,18 ---- defflag opt_uvideo.h UVIDEO_DEBUG defflag opt_umass.h UMASS_DEBUG + defflag opt_usbhist.h USBHIST + define usbroothubif { } define usbdevif { [port = -1], [configuration = -1], [interface = -1], [vendor = -1], [product = -1], [release = -1] } Index: umass.c =================================================================== RCS file: /cvsroot/src/sys/dev/usb/umass.c,v retrieving revision 1.147 diff -p -r1.147 umass.c *** umass.c 11 Jan 2013 06:22:23 -0000 1.147 --- umass.c 24 Jan 2013 08:49:55 -0000 *************** __KERNEL_RCSID(0, "$NetBSD: umass.c,v 1. *** 146,151 **** --- 146,152 ---- #include #include #include + #include #include #include *************** umass_setup_transfer(struct umass_softc *** 761,766 **** --- 762,769 ---- { usbd_status err; + USBHIST_FUNC(); USBHIST_CALLED(usbxferhist); + if (sc->sc_dying) return (USBD_IOERROR); *************** umass_setup_transfer(struct umass_softc *** 769,774 **** --- 772,779 ---- 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), *************** umass_bbb_state(usbd_xfer_handle xfer, u *** 1012,1017 **** --- 1017,1024 ---- 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); *************** umass_bbb_state(usbd_xfer_handle xfer, u *** 1034,1039 **** --- 1041,1048 ---- 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: usb.c =================================================================== RCS file: /cvsroot/src/sys/dev/usb/usb.c,v retrieving revision 1.140 diff -p -r1.140 usb.c *** usb.c 22 Jan 2013 12:40:43 -0000 1.140 --- usb.c 24 Jan 2013 08:49:55 -0000 *************** __KERNEL_RCSID(0, "$NetBSD: usb.c,v 1.14 *** 68,73 **** --- 68,76 ---- #include #include #include + #include + + USBHIST_DECL(usbxferhist); #define USB_DEV_MINOR 255 *************** usb_attach(device_t parent, device_t sel *** 202,207 **** --- 205,218 ---- } aprint_normal("\n"); + /* XXX RUN_ONCE */ + { static int first = 1; + if (first) { + USBHIST_INIT(usbxferhist, 400); + first = 0; + } + } + if (mpsafe) sc->sc_bus->methods->get_lock(sc->sc_bus, &sc->sc_bus->lock); else Index: usb_hist.h =================================================================== RCS file: usb_hist.h diff -N usb_hist.h *** /dev/null 1 Jan 1970 00:00:00 -0000 --- usb_hist.h 24 Jan 2013 08:49:55 -0000 *************** *** 0 **** --- 1,70 ---- + /* $NetBSD$ */ + + /* + * 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_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_INIT(NAME,N) KERNHIST_INIT(NAME,N) + #define USBHIST_INIT_STATIC(NAME,BUF) KERNHIST_INIT_STATIC(NAME,BUF) + #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_INIT(NAME,N) + #define USBHIST_INIT_STATIC(NAME,BUF) + #define USBHIST_LOG(NAME,FMT,A,B,C,D) + #define USBHIST_CALLED(NAME) + #define USBHIST_FUNC() + + #endif + + #endif /* _DEV_USB_USB_HIST_H_ */ Index: usbdi.c =================================================================== RCS file: /cvsroot/src/sys/dev/usb/usbdi.c,v retrieving revision 1.150 diff -p -r1.150 usbdi.c *** usbdi.c 22 Jan 2013 13:27:59 -0000 1.150 --- usbdi.c 24 Jan 2013 08:49:55 -0000 *************** __KERNEL_RCSID(0, "$NetBSD: usbdi.c,v 1. *** 52,57 **** --- 52,58 ---- #include #include #include + #include /* UTF-8 encoding stuff */ #include *************** usbd_transfer(usbd_xfer_handle xfer) *** 267,272 **** --- 268,275 ---- unsigned int size, flags; int s; + USBHIST_FUNC(); USBHIST_CALLED(usbxferhist); + DPRINTFN(5,("usbd_transfer: xfer=%p, flags=%#x, pipe=%p, running=%d\n", xfer, xfer->flags, pipe, pipe->running)); *************** usbd_transfer(usbd_xfer_handle xfer) *** 276,283 **** #endif xfer->done = 0; ! if (pipe->aborting) return (USBD_CANCELLED); size = xfer->length; /* If there is no buffer, allocate one. */ --- 279,288 ---- #endif xfer->done = 0; ! 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. */ *************** usbd_transfer(usbd_xfer_handle xfer) *** 289,296 **** printf("usbd_transfer: has old buffer!\n"); #endif err = bus->methods->allocm(bus, dmap, size); ! if (err) return (err); xfer->rqflags |= URQ_AUTO_DMABUF; } --- 294,303 ---- printf("usbd_transfer: has old buffer!\n"); #endif err = bus->methods->allocm(bus, dmap, size); ! if (err) { ! USBHIST_LOG(usbxferhist, "<- done xfer %p, no mem", xfer, 0, 0, 0); return (err); + } xfer->rqflags |= URQ_AUTO_DMABUF; } *************** usbd_transfer(usbd_xfer_handle xfer) *** 302,307 **** --- 309,315 ---- /* 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. */ *************** usbd_transfer(usbd_xfer_handle xfer) *** 313,328 **** } } ! if (!(flags & USBD_SYNCHRONOUS)) return (err); /* Sync transfer, wait for completion. */ ! if (err != USBD_IN_PROGRESS) return (err); usbd_lock_pipe(pipe); while (!xfer->done) { if (pipe->device->bus->use_polling) panic("usbd_transfer: not done"); err = 0; if ((flags & USBD_SYNCHRONOUS_SIG) != 0) { --- 321,341 ---- } } ! 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) { ! 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) { *************** usb_transfer_complete(usbd_xfer_handle x *** 792,797 **** --- 805,812 ---- xfer->status == USBD_TIMEOUT; int repeat, polling; + 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)); *************** usb_transfer_complete(usbd_xfer_handle x *** 854,859 **** --- 869,876 ---- 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]; *************** usb_transfer_complete(usbd_xfer_handle x *** 867,872 **** --- 884,890 ---- } if (repeat) { + USBHIST_LOG(usbxferhist, "xfer %p doing callback %p status %x", xfer, xfer->callback, xfer->status, 0); if (xfer->callback) { if (pipe->device->bus->lock) mutex_exit(pipe->device->bus->lock); *************** usb_transfer_complete(usbd_xfer_handle x *** 874,879 **** --- 892,898 ---- 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); *************** usb_transfer_complete(usbd_xfer_handle x *** 882,888 **** --- 901,909 ---- } 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 (pipe->device->bus->lock) mutex_exit(pipe->device->bus->lock); *************** usb_transfer_complete(usbd_xfer_handle x *** 899,908 **** --- 920,932 ---- } if (sync && !polling) { + USBHIST_LOG(usbxferhist, "<- done xfer %p, wakeup", xfer, 0, 0, 0); if (pipe->device->bus->lock) cv_broadcast(&xfer->cv); else wakeup(xfer); /* XXXSMP ok */ + } else { + USBHIST_LOG(usbxferhist, "<- done xfer %p, no wakeup", xfer, 0, 0, 0); } if (!repeat) { *************** usb_insert_transfer(usbd_xfer_handle xfe *** 921,926 **** --- 945,952 ---- 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)); *************** usb_insert_transfer(usbd_xfer_handle xfe *** 928,933 **** --- 954,960 ---- #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); *************** usb_insert_transfer(usbd_xfer_handle xfe *** 941,946 **** --- 968,974 ---- pipe->running = 1; err = USBD_NORMAL_COMPLETION; } + USBHIST_LOG(usbxferhist, "<- done xfer %p, err %d", xfer, err, 0, 0); return (err); } Index: usbdi_util.c =================================================================== RCS file: /cvsroot/src/sys/dev/usb/usbdi_util.c,v retrieving revision 1.59 diff -p -r1.59 usbdi_util.c *** usbdi_util.c 5 Jan 2013 23:34:21 -0000 1.59 --- usbdi_util.c 24 Jan 2013 08:49:55 -0000 *************** __KERNEL_RCSID(0, "$NetBSD: usbdi_util.c *** 43,52 **** #include #include - #include #include #include #ifdef USB_DEBUG #define DPRINTF(x) if (usbdebug) printf x --- 43,52 ---- #include #include #include #include #include + #include #ifdef USB_DEBUG #define DPRINTF(x) if (usbdebug) printf x *************** Static void *** 421,431 **** --- 421,433 ---- usbd_bulk_transfer_cb(usbd_xfer_handle xfer, usbd_private_handle priv, usbd_status status) { + USBHIST_FUNC(); USBHIST_CALLED(usbxferhist); if (xfer->pipe->device->bus->lock) cv_broadcast(&xfer->cv); else wakeup(xfer); /* XXXSMP ok */ + USBHIST_LOG(usbxferhist, "<- done wakeup xfer %p", xfer, 0, 0, 0); } usbd_status *************** usbd_bulk_transfer(usbd_xfer_handle xfer *** 435,440 **** --- 437,444 ---- { usbd_status err; + USBHIST_FUNC(); USBHIST_CALLED(usbxferhist); + usbd_setup_xfer(xfer, pipe, 0, buf, *size, flags, timeout, usbd_bulk_transfer_cb); DPRINTFN(1, ("usbd_bulk_transfer: start transfer %d bytes\n", *size)); *************** usbd_bulk_transfer(usbd_xfer_handle xfer *** 446,451 **** --- 450,456 ---- 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); } *************** Static void *** 455,465 **** --- 460,472 ---- usbd_intr_transfer_cb(usbd_xfer_handle xfer, usbd_private_handle priv, usbd_status status) { + USBHIST_FUNC(); USBHIST_CALLED(usbxferhist); if (xfer->pipe->device->bus->lock) cv_broadcast(&xfer->cv); else wakeup(xfer); /* XXXSMP ok */ + USBHIST_LOG(usbxferhist, "<- done wakeup xfer %p", xfer, 0, 0, 0); } usbd_status *************** usbd_intr_transfer(usbd_xfer_handle xfer *** 469,474 **** --- 476,483 ---- { usbd_status err; + USBHIST_FUNC(); USBHIST_CALLED(usbxferhist); + usbd_setup_xfer(xfer, pipe, 0, buf, *size, flags, timeout, usbd_intr_transfer_cb); DPRINTFN(1, ("usbd_intr_transfer: start transfer %d bytes\n", *size)); *************** usbd_intr_transfer(usbd_xfer_handle xfer *** 479,484 **** --- 488,494 ---- 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); }