Index: dev/raidframe/files.raidframe =================================================================== RCS file: /cvsroot/src/sys/dev/raidframe/files.raidframe,v retrieving revision 1.8 diff -p -r1.8 files.raidframe *** dev/raidframe/files.raidframe 17 Nov 2009 18:54:26 -0000 1.8 --- dev/raidframe/files.raidframe 6 Aug 2011 09:58:41 -0000 *************** *** 2,7 **** --- 2,8 ---- defflag RAID_AUTOCONFIG defflag RAID_DIAGNOSTIC + defflag opt_rfhist.h RFHIST: KERNHIST defpseudodev raid: disk Index: dev/raidframe/rf_diskqueue.c =================================================================== RCS file: /cvsroot/src/sys/dev/raidframe/rf_diskqueue.c,v retrieving revision 1.53 diff -p -r1.53 rf_diskqueue.c *** dev/raidframe/rf_diskqueue.c 5 May 2011 06:04:09 -0000 1.53 --- dev/raidframe/rf_diskqueue.c 6 Aug 2011 09:58:41 -0000 *************** *** 68,73 **** --- 68,77 ---- #include __KERNEL_RCSID(0, "$NetBSD: rf_diskqueue.c,v 1.53 2011/05/05 06:04:09 mrg Exp $"); + #ifdef _KERNEL_OPT + #include "opt_rfhist.h" + #endif + #include #include "rf_threadstuff.h" *************** __KERNEL_RCSID(0, "$NetBSD: rf_diskqueue *** 83,88 **** --- 87,93 ---- #include "rf_sstf.h" #include "rf_fifo.h" #include "rf_kintf.h" + #include "rf_netbsd.h" static void rf_ShutdownDiskQueueSystem(void *); *************** rf_DiskIOComplete(RF_DiskQueue_t *queue, *** 304,309 **** --- 309,317 ---- { int done = 0; + RFHIST_FUNC("rf_DiskIOComplete"); + RFHIST_CALLED(rfhist); + RF_LOCK_QUEUE_MUTEX(queue, "DiskIOComplete"); queue->numOutstanding--; RF_ASSERT(queue->numOutstanding >= 0); *************** rf_DiskIOComplete(RF_DiskQueue_t *queue, *** 319,327 **** --- 327,337 ---- queue->queueLength--; /* decrement count of number of requests waiting in this queue */ RF_ASSERT(queue->queueLength >= 0); if (RF_OK_TO_DISPATCH(queue, req)) { + RFHIST_LOG(rfhist, "dispatching req %p (bp %p)", req, req->bp, 0, 0); Dprintf2("DiskIOComplete: dispatching pri %d regular req to c %d (ok to dispatch)\n", req->priority, queue->col); rf_DispatchKernelIO(queue, req); } else { + RFHIST_LOG(rfhist, "re-queuing req %p (bp %p)", req, req->bp, 0, 0); /* we can't dispatch it, so just re-enqueue it. potential trouble here if disk queues batch reqs */ Dprintf2("DiskIOComplete: re-enqueueing pri %d regular req to c %d\n", req->priority, queue->col); *************** rf_DiskIOComplete(RF_DiskQueue_t *queue, *** 330,335 **** --- 340,346 ---- done = 1; } } else { + RFHIST_LOG(rfhist, "queue is empty", 0, 0, 0, 0); Dprintf1("DiskIOComplete: no more requests to extract.\n", ""); done = 1; } Index: dev/raidframe/rf_driver.c =================================================================== RCS file: /cvsroot/src/sys/dev/raidframe/rf_driver.c,v retrieving revision 1.129 diff -p -r1.129 rf_driver.c *** dev/raidframe/rf_driver.c 27 May 2011 22:48:24 -0000 1.129 --- dev/raidframe/rf_driver.c 6 Aug 2011 09:58:41 -0000 *************** __KERNEL_RCSID(0, "$NetBSD: rf_driver.c, *** 70,75 **** --- 70,76 ---- #ifdef _KERNEL_OPT #include "opt_raid_diagnostic.h" + #include "opt_rfhist.h" #endif #include *************** __KERNEL_RCSID(0, "$NetBSD: rf_driver.c, *** 110,115 **** --- 111,117 ---- #include "rf_shutdown.h" #include "rf_kintf.h" #include "rf_paritymap.h" + #include "rf_netbsd.h" #include *************** rf_Configure(RF_Raid_t *raidPtr, RF_Conf *** 338,343 **** --- 340,347 ---- DO_INIT_CONFIGURE(rf_ConfigureDiskQueueSystem); DO_INIT_CONFIGURE(rf_ConfigurePSStatus); isconfigged = 1; + + RFHIST_INIT(rfhist, 1000); } rf_unlock_mutex2(configureMutex); *************** rf_AllocRaidAccDesc(RF_Raid_t *raidPtr, *** 570,575 **** --- 574,582 ---- { RF_RaidAccessDesc_t *desc; + RFHIST_FUNC("rf_AllocRaidAccDesc"); + RFHIST_CALLED(rfhist); + desc = pool_get(&rf_pools.rad, PR_WAITOK); rf_lock_mutex2(raidPtr->rad_lock); *************** rf_AllocRaidAccDesc(RF_Raid_t *raidPtr, *** 609,614 **** --- 616,623 ---- desc->iobufs = NULL; desc->stripebufs = NULL; + RFHIST_LOG(rfhist, "creating access for buf %p", bp, 0, 0, 0); + return (desc); } *************** rf_FreeRaidAccDesc(RF_RaidAccessDesc_t * *** 619,626 **** --- 628,640 ---- RF_DagList_t *dagList, *temp; RF_VoidPointerListElem_t *tmp; + RFHIST_FUNC("rf_FreeRaidAccDesc"); + RFHIST_CALLED(rfhist); + RF_ASSERT(desc); + RFHIST_LOG(rfhist, "freeing access for buf %p", desc->bp, 0, 0, 0); + /* Cleanup the dagList(s) */ dagList = desc->dagList; while(dagList != NULL) { Index: dev/raidframe/rf_engine.c =================================================================== RCS file: /cvsroot/src/sys/dev/raidframe/rf_engine.c,v retrieving revision 1.46 diff -p -r1.46 rf_engine.c *** dev/raidframe/rf_engine.c 11 May 2011 18:13:12 -0000 1.46 --- dev/raidframe/rf_engine.c 6 Aug 2011 09:58:41 -0000 *************** *** 57,62 **** --- 57,66 ---- #include __KERNEL_RCSID(0, "$NetBSD: rf_engine.c,v 1.46 2011/05/11 18:13:12 mrg Exp $"); + #ifdef _KERNEL_OPT + #include "opt_rfhist.h" + #endif + #include #include "rf_threadstuff.h" *************** __KERNEL_RCSID(0, "$NetBSD: rf_engine.c, *** 69,74 **** --- 73,79 ---- #include "rf_raid.h" #include "rf_kintf.h" #include "rf_paritymap.h" + #include "rf_netbsd.h" static void rf_ShutdownEngine(void *); static void DAGExecutionThread(RF_ThreadArg_t arg); *************** rf_RaidIOThread(RF_ThreadArg_t arg) *** 855,869 **** --- 860,879 ---- RF_Raid_t *raidPtr; RF_DiskQueueData_t *req; + RFHIST_FUNC("rf_RaidIOThread"); raidPtr = (RF_Raid_t *) arg; + RFHIST_CALLED(rfhist); + rf_lock_mutex2(raidPtr->iodone_lock); while (!raidPtr->shutdown_raidio) { /* if there is nothing to do, then snooze. */ if (TAILQ_EMPTY(&(raidPtr->iodone)) && rf_buf_queue_check(raidPtr->raidid)) { + RFHIST_LOG(rfhist, "calling cv_wait", 0, 0, 0, 0); rf_wait_cond2(raidPtr->iodone_cv, raidPtr->iodone_lock); + RFHIST_LOG(rfhist, "back from cv_wait", 0, 0, 0, 0); } /* Check for deferred parity-map-related work. */ *************** rf_RaidIOThread(RF_ThreadArg_t arg) *** 875,880 **** --- 885,891 ---- /* See what I/Os, if any, have arrived */ while ((req = TAILQ_FIRST(&(raidPtr->iodone))) != NULL) { + RFHIST_LOG(rfhist, "processing req %p (buf %p)", req, req->bp, 0, 0); TAILQ_REMOVE(&(raidPtr->iodone), req, iodone_entries); rf_unlock_mutex2(raidPtr->iodone_lock); rf_DiskIOComplete(req->queue, req, req->error); Index: dev/raidframe/rf_history.h =================================================================== RCS file: dev/raidframe/rf_history.h diff -N dev/raidframe/rf_history.h *** /dev/null 1 Jan 1970 00:00:00 -0000 --- dev/raidframe/rf_history.h 6 Aug 2011 09:58:41 -0000 *************** *** 0 **** --- 1,51 ---- + /* $NetBSD$ */ + + /* + * Copyright (c) 2011 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. + */ + + #ifdef _KERNEL_OPT + #include "opt_rfhist.h" + #endif + + #ifdef RFHIST + + #define RFHIST_DECL(NAME) KERNHIST_DECL(NAME) + #define RFHIST_INIT(NAME,N) KERNHIST_INIT(NAME,N) + #define RFHIST_LOG(NAME,FMT,A,B,C,D) KERNHIST_LOG(NAME,FMT,A,B,C,D) + #define RFHIST_CALLED(NAME) KERNHIST_CALLED(NAME) + #define RFHIST_FUNC(FNAME) KERNHIST_FUNC(FNAME) + + #else + + #define RFHIST_DECL(NAME) + #define RFHIST_INIT(NAME,N) + #define RFHIST_LOG(NAME,FMT,A,B,C,D) + #define RFHIST_CALLED(NAME) + #define RFHIST_FUNC(FNAME) + + #endif Index: dev/raidframe/rf_netbsd.h =================================================================== RCS file: /cvsroot/src/sys/dev/raidframe/rf_netbsd.h,v retrieving revision 1.29 diff -p -r1.29 rf_netbsd.h *** dev/raidframe/rf_netbsd.h 28 Apr 2008 20:23:56 -0000 1.29 --- dev/raidframe/rf_netbsd.h 6 Aug 2011 09:58:41 -0000 *************** *** 32,46 **** --- 32,53 ---- #ifndef _RF__RF_NETBSDSTUFF_H_ #define _RF__RF_NETBSDSTUFF_H_ + #ifdef _KERNEL_OPT + #include "opt_rfhist.h" + #endif + #include #include #include #include #include + #include #include #include + #include "rf_history.h" + struct raidcinfo { struct vnode *ci_vp; /* component device's vnode */ dev_t ci_dev; /* component device's dev_t */ *************** typedef struct RF_ConfigSet_s { *** 103,106 **** --- 110,115 ---- struct RF_ConfigSet_s *next; } RF_ConfigSet_t; + RFHIST_DECL(rfhist); + #endif /* _RF__RF_NETBSDSTUFF_H_ */ Index: dev/raidframe/rf_netbsdkintf.c =================================================================== RCS file: /cvsroot/src/sys/dev/raidframe/rf_netbsdkintf.c,v retrieving revision 1.291 diff -p -r1.291 rf_netbsdkintf.c *** dev/raidframe/rf_netbsdkintf.c 11 May 2011 18:13:12 -0000 1.291 --- dev/raidframe/rf_netbsdkintf.c 6 Aug 2011 09:58:42 -0000 *************** __KERNEL_RCSID(0, "$NetBSD: rf_netbsdkin *** 106,111 **** --- 106,112 ---- #ifdef _KERNEL_OPT #include "opt_compat_netbsd.h" #include "opt_raid_autoconfig.h" + #include "opt_rfhist.h" #include "raid.h" #endif *************** raidstrategy(struct buf *bp) *** 838,843 **** --- 839,846 ---- struct raid_softc *rs = &raid_softc[raidID]; int wlabel; + RFHIST_FUNC("raidstrategy"); + if ((rs->sc_flags & RAIDF_INITED) ==0) { bp->b_error = ENXIO; goto done; *************** raidstrategy(struct buf *bp) *** 847,852 **** --- 850,856 ---- goto done; } raidPtr = raidPtrs[raidID]; + RFHIST_CALLED(rfhist); if (!raidPtr->valid) { bp->b_error = ENODEV; goto done; *************** raidstrategy(struct buf *bp) *** 892,897 **** --- 896,902 ---- /* scheduled the IO to happen at the next convenient time */ rf_signal_cond2(raidPtr->iodone_cv); + RFHIST_LOG(rfhist, "starting io on buf %p, poked iodone", bp, 0, 0, 0); rf_unlock_mutex2(raidPtr->iodone_lock); return; *************** rf_DispatchKernelIO(RF_DiskQueue_t *queu *** 2089,2097 **** --- 2094,2106 ---- int op = (req->type == RF_IO_TYPE_READ) ? B_READ : B_WRITE; struct buf *bp; + RFHIST_FUNC("rf_DispatchKernelIO"); + req->queue = queue; bp = req->bp; + RFHIST_CALLED(rfhist); + switch (req->type) { case RF_IO_TYPE_NOP: /* used primarily to unlock a locked queue */ /* XXX need to do something extra here.. */ *************** rf_DispatchKernelIO(RF_DiskQueue_t *queu *** 2144,2149 **** --- 2153,2159 ---- * to minimize fuss with calling interfaces. */ + RFHIST_LOG(rfhist, "calling bdev_strategy on buf %p (req %p)", bp, req, 0, 0); RF_UNLOCK_QUEUE_MUTEX(queue, "unusedparam"); bdev_strategy(bp); RF_LOCK_QUEUE_MUTEX(queue, "unusedparam"); *************** KernelWakeupFunc(struct buf *bp) *** 2165,2176 **** --- 2175,2190 ---- RF_DiskQueueData_t *req = NULL; RF_DiskQueue_t *queue; + RFHIST_FUNC("KernelWakeupFunc"); + db1_printf(("recovering the request queue:\n")); req = bp->b_private; queue = (RF_DiskQueue_t *) req->queue; + RFHIST_CALLED(rfhist); + rf_lock_mutex2(queue->raidPtr->iodone_lock); #if RF_ACC_TRACE > 0 *************** KernelWakeupFunc(struct buf *bp) *** 2222,2227 **** --- 2236,2243 ---- /* Let the raidio thread know there is work to be done. */ rf_signal_cond2(queue->raidPtr->iodone_cv); + RFHIST_LOG(rfhist, "finished io on buf %p (req %p), poked iodone", bp, req, 0, 0); + rf_unlock_mutex2(queue->raidPtr->iodone_lock); } Index: dev/raidframe/rf_reconstruct.c =================================================================== RCS file: /cvsroot/src/sys/dev/raidframe/rf_reconstruct.c,v retrieving revision 1.115 diff -p -r1.115 rf_reconstruct.c *** dev/raidframe/rf_reconstruct.c 28 May 2011 00:53:04 -0000 1.115 --- dev/raidframe/rf_reconstruct.c 6 Aug 2011 09:58:42 -0000 *************** rf_ReconstructInPlace(RF_Raid_t *raidPtr *** 348,357 **** const RF_LayoutSW_t *lp; RF_ComponentLabel_t *c_label; int numDisksDone = 0, rc; - struct partinfo dpart; struct pathbuf *pb; struct vnode *vp; struct vattr va; int retcode; int ac; --- 348,358 ---- const RF_LayoutSW_t *lp; RF_ComponentLabel_t *c_label; int numDisksDone = 0, rc; struct pathbuf *pb; struct vnode *vp; struct vattr va; + uint64_t numsec; + unsigned secsize; int retcode; int ac; *************** rf_ReconstructInPlace(RF_Raid_t *raidPtr *** 464,470 **** return(retcode); } ! retcode = VOP_IOCTL(vp, DIOCGPART, &dpart, FREAD, curlwp->l_cred); if (retcode) { vn_close(vp, FREAD | FWRITE, kauth_cred_get()); rf_lock_mutex2(raidPtr->mutex); --- 465,471 ---- return(retcode); } ! retcode = getdisksize(vp, &numsec, &secsize); if (retcode) { vn_close(vp, FREAD | FWRITE, kauth_cred_get()); rf_lock_mutex2(raidPtr->mutex); *************** rf_ReconstructInPlace(RF_Raid_t *raidPtr *** 474,483 **** return(retcode); } rf_lock_mutex2(raidPtr->mutex); ! raidPtr->Disks[col].blockSize = dpart.disklab->d_secsize; ! ! raidPtr->Disks[col].numBlocks = dpart.part->p_size - ! rf_protectedSectors; raidPtr->raid_cinfo[col].ci_vp = vp; raidPtr->raid_cinfo[col].ci_dev = va.va_rdev; --- 475,482 ---- return(retcode); } rf_lock_mutex2(raidPtr->mutex); ! raidPtr->Disks[col].blockSize = secsize; ! raidPtr->Disks[col].numBlocks = numsec - rf_protectedSectors; raidPtr->raid_cinfo[col].ci_vp = vp; raidPtr->raid_cinfo[col].ci_dev = va.va_rdev; Index: dev/raidframe/rf_states.c =================================================================== RCS file: /cvsroot/src/sys/dev/raidframe/rf_states.c,v retrieving revision 1.49 diff -p -r1.49 rf_states.c *** dev/raidframe/rf_states.c 11 May 2011 18:13:12 -0000 1.49 --- dev/raidframe/rf_states.c 6 Aug 2011 09:58:42 -0000 *************** __KERNEL_RCSID(0, "$NetBSD: rf_states.c, *** 31,36 **** --- 31,40 ---- #include + #ifdef _KERNEL_OPT + #include "opt_rfhist.h" + #endif + #include "rf_archs.h" #include "rf_threadstuff.h" #include "rf_raid.h" *************** __KERNEL_RCSID(0, "$NetBSD: rf_states.c, *** 64,74 **** */ #if RF_DEBUG_STATES ! static char * StateName(RF_AccessState_t state) { switch (state) { ! case rf_QuiesceState:return "QuiesceState"; case rf_MapState: return "MapState"; case rf_LockState: --- 68,79 ---- */ #if RF_DEBUG_STATES ! static const char * StateName(RF_AccessState_t state) { switch (state) { ! case rf_QuiesceState: ! return "QuiesceState"; case rf_MapState: return "MapState"; case rf_LockState: *************** rf_ContinueRaidAccess(RF_RaidAccessDesc_ *** 103,113 **** --- 108,122 ---- int unit = desc->raidPtr->raidid; #endif + RFHIST_FUNC("rf_ContinueRaidAccess"); + RFHIST_CALLED(rfhist); + do { current_state_index = desc->state; current_state = desc->states[current_state_index]; + RFHIST_LOG(rfhist, "loop top: state = %d", current_state, 0, 0, 0); switch (current_state) { case rf_QuiesceState: *************** rf_ContinueRaidAccess(RF_RaidAccessDesc_ *** 142,147 **** --- 151,158 ---- break; } + RFHIST_LOG(rfhist, "loop bot: state = %d, suspended = %d", current_state, suspended, 0, 0); + /* after this point, we cannot dereference desc since * desc may have been freed. desc is only freed in * LastState, so if we renter this function or loop *************** rf_State_LastState(RF_RaidAccessDesc_t * *** 214,219 **** --- 225,233 ---- void (*callbackFunc) (RF_CBParam_t) = desc->callbackFunc; RF_CBParam_t callbackArg; + RFHIST_FUNC("rf_State_LastState"); + RFHIST_CALLED(rfhist); + callbackArg.p = desc->callbackArg; /* *************** rf_State_LastState(RF_RaidAccessDesc_t * *** 237,242 **** --- 251,257 ---- rf_lock_mutex2(desc->raidPtr->iodone_lock); rf_signal_cond2(desc->raidPtr->iodone_cv); + RFHIST_LOG(rfhist, "done io on buf %p, poked iodone", desc->bp, 0, 0, 0); rf_unlock_mutex2(desc->raidPtr->iodone_lock); /* Index: sys/kernhist.h =================================================================== RCS file: /cvsroot/src/sys/sys/kernhist.h,v retrieving revision 1.2 diff -p -r1.2 kernhist.h *** sys/kernhist.h 10 Jun 2011 14:59:35 -0000 1.2 --- sys/kernhist.h 6 Aug 2011 09:58:42 -0000 *************** LIST_HEAD(kern_history_head, kern_histor *** 84,89 **** --- 84,90 ---- #define KERNHIST_UVMPDHIST 0x00000002 /* pdhist */ #define KERNHIST_UVMUBCHIST 0x00000004 /* ubchist */ #define KERNHIST_UVMLOANHIST 0x00000008 /* loanhist */ + #define KERNHIST_RFHIST 0x00000010 /* rfhistory */ #ifdef _KERNEL