Index: dev/usb/files.usb =================================================================== RCS file: /cvsroot/src/sys/dev/usb/files.usb,v retrieving revision 1.124 diff -p -r1.124 files.usb *** dev/usb/files.usb 4 Aug 2012 04:34:54 -0000 1.124 --- dev/usb/files.usb 24 Aug 2012 14:33:30 -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: dev/usb/umass.c =================================================================== RCS file: /cvsroot/src/sys/dev/usb/umass.c,v retrieving revision 1.145 diff -p -r1.145 umass.c *** dev/usb/umass.c 10 Jun 2012 06:15:54 -0000 1.145 --- dev/usb/umass.c 24 Aug 2012 14:33:30 -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: dev/usb/usb.c =================================================================== RCS file: /cvsroot/src/sys/dev/usb/usb.c,v retrieving revision 1.135 diff -p -r1.135 usb.c *** dev/usb/usb.c 20 Jul 2012 23:18:02 -0000 1.135 --- dev/usb/usb.c 24 Aug 2012 14:33:30 -0000 *************** __KERNEL_RCSID(0, "$NetBSD: usb.c,v 1.13 *** 67,72 **** --- 67,75 ---- #include #include #include + #include + + USBHIST_DECL(usbxferhist); #define USB_DEV_MINOR 255 *************** usb_attach(device_t parent, device_t sel *** 201,211 **** --- 204,225 ---- } aprint_normal("\n"); + <<<<<<< usb.c + /* 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 sc->sc_bus->lock = NULL; + >>>>>>> 1.135 RUN_ONCE(&init_control, usb_once_init); config_interrupts(self, usb_doattach); } Index: dev/usb/usbdi.c =================================================================== RCS file: /cvsroot/src/sys/dev/usb/usbdi.c,v retrieving revision 1.139 diff -p -r1.139 usbdi.c *** dev/usb/usbdi.c 15 Jul 2012 21:13:31 -0000 1.139 --- dev/usb/usbdi.c 24 Aug 2012 14:33:30 -0000 *************** __KERNEL_RCSID(0, "$NetBSD: usbdi.c,v 1. *** 51,56 **** --- 51,57 ---- #include #include #include + #include /* UTF-8 encoding stuff */ #include *************** usbd_transfer(usbd_xfer_handle xfer) *** 265,270 **** --- 266,273 ---- 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) *** 274,281 **** #endif xfer->done = 0; ! if (pipe->aborting) return (USBD_CANCELLED); size = xfer->length; /* If there is no buffer, allocate one. */ --- 277,286 ---- #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) *** 287,294 **** printf("usbd_transfer: has old buffer!\n"); #endif err = bus->methods->allocm(bus, dmap, size); ! if (err) return (err); xfer->rqflags |= URQ_AUTO_DMABUF; } --- 292,301 ---- 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) *** 300,305 **** --- 307,313 ---- /* 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) *** 311,326 **** } } ! if (!(flags & USBD_SYNCHRONOUS)) return (err); /* Sync transfer, wait for completion. */ ! if (err != USBD_IN_PROGRESS) return (err); usbd_lock_pipe(pipe); if (!xfer->done) { if (pipe->device->bus->use_polling) panic("usbd_transfer: not done"); if ((flags & USBD_SYNCHRONOUS_SIG) != 0) { if (pipe->device->bus->lock) --- 319,339 ---- } } ! 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); if (!xfer->done) { if (pipe->device->bus->use_polling) panic("usbd_transfer: not done"); + USBHIST_LOG(usbxferhist, "<- sleeping on xfer %p", xfer, 0, 0, 0); if ((flags & USBD_SYNCHRONOUS_SIG) != 0) { if (pipe->device->bus->lock) *************** usb_transfer_complete(usbd_xfer_handle x *** 787,792 **** --- 800,807 ---- 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 *** 845,850 **** --- 860,867 ---- 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 *** 858,873 **** --- 875,894 ---- } 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); xfer->callback(xfer, xfer->priv, xfer->status); + USBHIST_LOG(usbxferhist, "xfer %p doing done %p", xfer, pipe->methods->done, 0, 0); if (pipe->device->bus->lock) mutex_enter(pipe->device->bus->lock); } 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 *** 878,887 **** --- 899,911 ---- } 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 *** 900,905 **** --- 924,931 ---- 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 *** 907,912 **** --- 933,939 ---- #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 *** 920,925 **** --- 947,953 ---- pipe->running = 1; err = USBD_NORMAL_COMPLETION; } + USBHIST_LOG(usbxferhist, "<- done xfer %p, err %d", xfer, err, 0, 0); return (err); } Index: dev/usb/usbdi_util.c =================================================================== RCS file: /cvsroot/src/sys/dev/usb/usbdi_util.c,v retrieving revision 1.57 diff -p -r1.57 usbdi_util.c *** dev/usb/usbdi_util.c 10 Jun 2012 06:15:55 -0000 1.57 --- dev/usb/usbdi_util.c 24 Aug 2012 14:33:30 -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); }