Index: sys/kern/kern_lock.c =================================================================== RCS file: /usr/home/kmacy/freebsd/ncvs/src/sys/kern/kern_lock.c,v retrieving revision 1.103 diff -d -u -r1.103 kern_lock.c --- sys/kern/kern_lock.c 13 Nov 2006 05:41:46 -0000 1.103 +++ sys/kern/kern_lock.c 23 Feb 2007 11:48:37 -0000 @@ -84,7 +84,7 @@ #define LK_ALL (LK_HAVE_EXCL | LK_WANT_EXCL | LK_WANT_UPGRADE | \ LK_SHARE_NONZERO | LK_WAIT_NONZERO) -static int acquire(struct lock **lkpp, int extflags, int wanted); +static int acquire(struct lock **lkpp, int extflags, int wanted, int *contested, uint64_t *waittime); static int acquiredrain(struct lock *lkp, int extflags) ; static __inline void @@ -112,7 +112,7 @@ } static int -acquire(struct lock **lkpp, int extflags, int wanted) +acquire(struct lock **lkpp, int extflags, int wanted, int *contested, uint64_t *waittime) { struct lock *lkp = *lkpp; int error; @@ -123,6 +123,9 @@ if ((extflags & LK_NOWAIT) && (lkp->lk_flags & wanted)) return EBUSY; error = 0; + if ((lkp->lk_flags & wanted) != 0) + lock_profile_obtain_lock_failed(&lkp->lk_object, contested, waittime); + while ((lkp->lk_flags & wanted) != 0) { CTR2(KTR_LOCK, "acquire(): lkp == %p, lk_flags == 0x%x sleeping", @@ -168,15 +171,15 @@ int error; struct thread *thr; int extflags, lockflags; - uint64_t waitstart; - + int contested = 0; + uint64_t waitstart = 0; + error = 0; if (td == NULL) thr = LK_KERNPROC; else thr = td; - lock_profile_waitstart(&waitstart); if ((flags & LK_INTERNAL) == 0) mtx_lock(lkp->lk_interlock); CTR6(KTR_LOCK, @@ -228,12 +231,12 @@ lockflags = LK_HAVE_EXCL; if (td != NULL && !(td->td_pflags & TDP_DEADLKTREAT)) lockflags |= LK_WANT_EXCL | LK_WANT_UPGRADE; - error = acquire(&lkp, extflags, lockflags); + error = acquire(&lkp, extflags, lockflags, &contested, &waitstart); if (error) break; sharelock(td, lkp, 1); if (lkp->lk_sharecount == 1) - lock_profile_obtain_lock_success(&lkp->lk_object, waitstart, file, line); + lock_profile_obtain_lock_success(&lkp->lk_object, contested, waitstart, file, line); #if defined(DEBUG_LOCKS) stack_save(&lkp->lk_stack); @@ -246,7 +249,7 @@ */ sharelock(td, lkp, 1); if (lkp->lk_sharecount == 1) - lock_profile_obtain_lock_success(&lkp->lk_object, waitstart, file, line); + lock_profile_obtain_lock_success(&lkp->lk_object, contested, waitstart, file, line); /* FALLTHROUGH downgrade */ case LK_DOWNGRADE: @@ -308,7 +311,7 @@ * drop to zero, then take exclusive lock. */ lkp->lk_flags |= LK_WANT_UPGRADE; - error = acquire(&lkp, extflags, LK_SHARE_NONZERO); + error = acquire(&lkp, extflags, LK_SHARE_NONZERO, &contested, &waitstart); lkp->lk_flags &= ~LK_WANT_UPGRADE; if (error) { @@ -322,7 +325,7 @@ lkp->lk_lockholder = thr; lkp->lk_exclusivecount = 1; COUNT(td, 1); - lock_profile_obtain_lock_success(&lkp->lk_object, waitstart, file, line); + lock_profile_obtain_lock_success(&lkp->lk_object, contested, waitstart, file, line); #if defined(DEBUG_LOCKS) stack_save(&lkp->lk_stack); #endif @@ -362,14 +365,14 @@ /* * Try to acquire the want_exclusive flag. */ - error = acquire(&lkp, extflags, (LK_HAVE_EXCL | LK_WANT_EXCL)); + error = acquire(&lkp, extflags, (LK_HAVE_EXCL | LK_WANT_EXCL), &contested, &waitstart); if (error) break; lkp->lk_flags |= LK_WANT_EXCL; /* * Wait for shared locks and upgrades to finish. */ - error = acquire(&lkp, extflags, LK_HAVE_EXCL | LK_WANT_UPGRADE | LK_SHARE_NONZERO); + error = acquire(&lkp, extflags, LK_HAVE_EXCL | LK_WANT_UPGRADE | LK_SHARE_NONZERO, &contested, &waitstart); lkp->lk_flags &= ~LK_WANT_EXCL; if (error) { if (lkp->lk_flags & LK_WAIT_NONZERO) @@ -382,7 +385,7 @@ panic("lockmgr: non-zero exclusive count"); lkp->lk_exclusivecount = 1; COUNT(td, 1); - lock_profile_obtain_lock_success(&lkp->lk_object, waitstart, file, line); + lock_profile_obtain_lock_success(&lkp->lk_object, contested, waitstart, file, line); #if defined(DEBUG_LOCKS) stack_save(&lkp->lk_stack); #endif Index: sys/kern/kern_mutex.c =================================================================== RCS file: /usr/home/kmacy/freebsd/ncvs/src/sys/kern/kern_mutex.c,v retrieving revision 1.179 diff -d -u -r1.179 kern_mutex.c --- sys/kern/kern_mutex.c 16 Dec 2006 02:37:57 -0000 1.179 +++ sys/kern/kern_mutex.c 23 Feb 2007 12:08:53 -0000 @@ -137,7 +137,6 @@ void _mtx_lock_flags(struct mtx *m, int opts, const char *file, int line) { - uint64_t waittime; MPASS(curthread != NULL); KASSERT(m->mtx_lock != MTX_DESTROYED, @@ -148,13 +147,11 @@ WITNESS_CHECKORDER(&m->mtx_object, opts | LOP_NEWORDER | LOP_EXCLUSIVE, file, line); - lock_profile_waitstart(&waittime); _get_sleep_lock(m, curthread, opts, file, line); LOCK_LOG_LOCK("LOCK", &m->mtx_object, opts, m->mtx_recurse, file, line); WITNESS_LOCK(&m->mtx_object, opts | LOP_EXCLUSIVE, file, line); curthread->td_locks++; - lock_profile_obtain_lock_success(&m->mtx_object, waittime, file, line); } void @@ -181,8 +178,6 @@ _mtx_lock_spin_flags(struct mtx *m, int opts, const char *file, int line) { - uint64_t waittime; - MPASS(curthread != NULL); KASSERT(m->mtx_lock != MTX_DESTROYED, ("mtx_lock_spin() of destroyed mutex @ %s:%d", file, line)); @@ -191,12 +186,10 @@ m->mtx_object.lo_name, file, line)); WITNESS_CHECKORDER(&m->mtx_object, opts | LOP_NEWORDER | LOP_EXCLUSIVE, file, line); - lock_profile_waitstart(&waittime); _get_spin_lock(m, curthread, opts, file, line); LOCK_LOG_LOCK("LOCK", &m->mtx_object, opts, m->mtx_recurse, file, line); WITNESS_LOCK(&m->mtx_object, opts | LOP_EXCLUSIVE, file, line); - lock_profile_obtain_lock_success(&m->mtx_object, waittime, file, line); } void @@ -225,9 +218,9 @@ int _mtx_trylock(struct mtx *m, int opts, const char *file, int line) { - int rval; + int rval, contested = 0; uint64_t waittime = 0; - + MPASS(curthread != NULL); KASSERT(m->mtx_lock != MTX_DESTROYED, ("mtx_trylock() of destroyed mutex @ %s:%d", file, line)); @@ -247,7 +240,9 @@ WITNESS_LOCK(&m->mtx_object, opts | LOP_EXCLUSIVE | LOP_TRYLOCK, file, line); curthread->td_locks++; - lock_profile_obtain_lock_success(&m->mtx_object, waittime, file, line); + if (m->mtx_recurse == 0) + lock_profile_obtain_lock_success(&m->mtx_object, contested, + waittime, file, line); } @@ -271,8 +266,7 @@ int cont_logged = 0; #endif uintptr_t v; - int contested = 0; - + if (mtx_owned(m)) { KASSERT((m->mtx_object.lo_flags & LO_RECURSABLE) != 0, ("_mtx_lock_sleep: recursed on non-recursive mutex %s @ %s:%d\n", @@ -289,8 +283,7 @@ "_mtx_lock_sleep: %s contested (lock=%p) at %s:%d", m->mtx_object.lo_name, (void *)m->mtx_lock, file, line); - while (!_obtain_lock(m, tid)) { - lock_profile_obtain_lock_failed(&m->mtx_object, &contested); + while (!_obtain_lock(m, tid)) { turnstile_lock(&m->mtx_object); v = m->mtx_lock; @@ -381,11 +374,6 @@ m->mtx_object.lo_name, (void *)tid, file, line); } #endif -#ifdef LOCK_PROFILING - m->mtx_object.lo_profile_obj.lpo_contest_holding = 0; - if (contested) - m->mtx_object.lo_profile_obj.lpo_contest_locking++; -#endif return; } @@ -400,14 +388,13 @@ _mtx_lock_spin(struct mtx *m, uintptr_t tid, int opts, const char *file, int line) { + int i = 0; struct thread *td; - int contested = 0, i = 0; if (LOCK_LOG_TEST(&m->mtx_object, opts)) CTR1(KTR_LOCK, "_mtx_lock_spin: %p spinning", m); while (!_obtain_lock(m, tid)) { - lock_profile_obtain_lock_failed(&m->mtx_object, &contested); /* Give interrupts a chance while we spin. */ spinlock_exit(); Index: sys/kern/kern_rwlock.c =================================================================== RCS file: /usr/home/kmacy/freebsd/ncvs/src/sys/kern/kern_rwlock.c,v retrieving revision 1.12 diff -d -u -r1.12 kern_rwlock.c --- sys/kern/kern_rwlock.c 13 Nov 2006 05:41:46 -0000 1.12 +++ sys/kern/kern_rwlock.c 23 Feb 2007 11:53:54 -0000 @@ -111,17 +111,17 @@ void _rw_wlock(struct rwlock *rw, const char *file, int line) { - uint64_t waitstart; - + int contested = 0; + uint64_t waitstart = 0; + MPASS(curthread != NULL); KASSERT(rw_wowner(rw) != curthread, ("%s (%s): wlock already held @ %s:%d", __func__, rw->rw_object.lo_name, file, line)); WITNESS_CHECKORDER(&rw->rw_object, LOP_NEWORDER | LOP_EXCLUSIVE, file, line); - lock_profile_waitstart(&waitstart); - __rw_wlock(rw, curthread, file, line); - lock_profile_obtain_lock_success(&rw->rw_object, waitstart, file, line); + __rw_wlock(rw, curthread, &contested, &waitstart, file, line); + lock_profile_obtain_lock_success(&rw->rw_object, contested, waitstart, file, line); LOCK_LOG_LOCK("WLOCK", &rw->rw_object, 0, 0, file, line); WITNESS_LOCK(&rw->rw_object, LOP_EXCLUSIVE, file, line); curthread->td_locks++; @@ -146,8 +146,8 @@ #ifdef SMP volatile struct thread *owner; #endif - uint64_t waitstart; - int contested; + uint64_t waittime = 0; + int contested = 0; uintptr_t x; KASSERT(rw_wowner(rw) != curthread, @@ -166,7 +166,6 @@ * be blocked on the writer, and the writer would be blocked * waiting for the reader to release its original read lock. */ - lock_profile_waitstart(&waitstart); for (;;) { /* * Handle the easy case. If no other thread has a write @@ -189,7 +188,7 @@ MPASS((x & RW_LOCK_READ_WAITERS) == 0); if (atomic_cmpset_acq_ptr(&rw->rw_lock, x, x + RW_ONE_READER)) { - lock_profile_obtain_lock_success(&rw->rw_object, waitstart, file, line); + lock_profile_obtain_lock_success(&rw->rw_object, contested, waittime, file, line); if (LOCK_LOG_TEST(&rw->rw_object, 0)) CTR4(KTR_LOCK, "%s: %p succeed %p -> %p", __func__, @@ -198,7 +197,7 @@ break; } cpu_spinwait(); - lock_profile_obtain_lock_failed(&rw->rw_object, &contested); + lock_profile_obtain_lock_failed(&rw->rw_object, &contested, &waittime); continue; } @@ -247,7 +246,7 @@ */ owner = (struct thread *)RW_OWNER(x); if (TD_IS_RUNNING(owner)) { - lock_profile_obtain_lock_failed(&rw->rw_object, &contested); + lock_profile_obtain_lock_failed(&rw->rw_object, &contested, &waittime); turnstile_release(&rw->rw_object); if (LOCK_LOG_TEST(&rw->rw_object, 0)) CTR3(KTR_LOCK, "%s: spinning on %p held by %p", @@ -411,7 +410,8 @@ #ifdef SMP volatile struct thread *owner; #endif - int contested; + int contested = 0; + uint64_t waittime = 0; uintptr_t v; if (LOCK_LOG_TEST(&rw->rw_object, 0)) @@ -453,7 +453,7 @@ } turnstile_release(&rw->rw_object); cpu_spinwait(); - lock_profile_obtain_lock_failed(&rw->rw_object, &contested); + lock_profile_obtain_lock_failed(&rw->rw_object, &contested, &waittime); continue; } @@ -467,7 +467,7 @@ v | RW_LOCK_WRITE_WAITERS)) { turnstile_release(&rw->rw_object); cpu_spinwait(); - lock_profile_obtain_lock_failed(&rw->rw_object, &contested); + lock_profile_obtain_lock_failed(&rw->rw_object, &contested, &waittime); continue; } if (LOCK_LOG_TEST(&rw->rw_object, 0)) @@ -483,8 +483,8 @@ */ owner = (struct thread *)RW_OWNER(v); if (!(v & RW_LOCK_READ) && TD_IS_RUNNING(owner)) { - lock_profile_obtain_lock_failed(&rw->rw_object, &contested); + lock_profile_obtain_lock_failed(&rw->rw_object, &contested, &waittime); turnstile_release(&rw->rw_object); if (LOCK_LOG_TEST(&rw->rw_object, 0)) CTR3(KTR_LOCK, "%s: spinning on %p held by %p", Index: sys/kern/kern_sx.c =================================================================== RCS file: /usr/home/kmacy/freebsd/ncvs/src/sys/kern/kern_sx.c,v retrieving revision 1.32 diff -d -u -r1.32 kern_sx.c --- sys/kern/kern_sx.c 13 Nov 2006 05:41:46 -0000 1.32 +++ sys/kern/kern_sx.c 23 Feb 2007 11:37:21 -0000 @@ -111,7 +111,7 @@ _sx_slock(struct sx *sx, const char *file, int line) { uint64_t waittime = 0; - int contested; + int contested = 0; mtx_lock(sx->sx_lock); KASSERT(sx->sx_xholder != curthread, @@ -122,11 +122,9 @@ /* * Loop in case we lose the race for lock acquisition. */ - if (sx->sx_cnt < 0) - lock_profile_waitstart(&waittime); while (sx->sx_cnt < 0) { sx->sx_shrd_wcnt++; - lock_profile_obtain_lock_failed(&sx->sx_object, &contested); + lock_profile_obtain_lock_failed(&sx->sx_object, &contested, &waittime); cv_wait(&sx->sx_shrd_cv, sx->sx_lock); sx->sx_shrd_wcnt--; } @@ -135,7 +133,7 @@ sx->sx_cnt++; if (sx->sx_cnt == 1) - lock_profile_obtain_lock_success(&sx->sx_object, waittime, file, line); + lock_profile_obtain_lock_success(&sx->sx_object, contested, waittime, file, line); LOCK_LOG_LOCK("SLOCK", &sx->sx_object, 0, 0, file, line); WITNESS_LOCK(&sx->sx_object, 0, file, line); @@ -166,7 +164,7 @@ void _sx_xlock(struct sx *sx, const char *file, int line) { - int contested; + int contested = 0; uint64_t waittime = 0; mtx_lock(sx->sx_lock); @@ -184,12 +182,10 @@ WITNESS_CHECKORDER(&sx->sx_object, LOP_NEWORDER | LOP_EXCLUSIVE, file, line); - if (sx->sx_cnt) - lock_profile_waitstart(&waittime); /* Loop in case we lose the race for lock acquisition. */ while (sx->sx_cnt != 0) { sx->sx_excl_wcnt++; - lock_profile_obtain_lock_failed(&sx->sx_object, &contested); + lock_profile_obtain_lock_failed(&sx->sx_object, &contested, &waittime); cv_wait(&sx->sx_excl_cv, sx->sx_lock); sx->sx_excl_wcnt--; } @@ -200,7 +196,7 @@ sx->sx_cnt--; sx->sx_xholder = curthread; - lock_profile_obtain_lock_success(&sx->sx_object, waittime, file, line); + lock_profile_obtain_lock_success(&sx->sx_object, contested, waittime, file, line); LOCK_LOG_LOCK("XLOCK", &sx->sx_object, 0, 0, file, line); WITNESS_LOCK(&sx->sx_object, LOP_EXCLUSIVE, file, line); curthread->td_locks++; Index: sys/kern/subr_lock.c =================================================================== RCS file: /usr/home/kmacy/freebsd/ncvs/src/sys/kern/subr_lock.c,v retrieving revision 1.12 diff -d -u -r1.12 subr_lock.c --- sys/kern/subr_lock.c 4 Dec 2006 22:15:50 -0000 1.12 +++ sys/kern/subr_lock.c 23 Feb 2007 12:17:04 -0000 @@ -250,8 +250,7 @@ #endif #ifdef LOCK_PROFILING -void _lock_profile_obtain_lock_success(struct lock_object *lo, uint64_t waittime, con\ -st char *file, int line) +void _lock_profile_obtain_lock_success(struct lock_object *lo, int contested, uint64_t waittime, const char *file, int line) { struct lock_profile_object *l = &lo->lo_profile_obj; @@ -259,7 +258,10 @@ if (l->lpo_acqtime == 0) { l->lpo_filename = file; l->lpo_lineno = line; - l->lpo_acqtime = nanoseconds(); + if (contested) + l->lpo_acqtime = nanoseconds(); + else + l->lpo_acqtime = 0; if (waittime && (l->lpo_acqtime > waittime)) l->lpo_waittime = l->lpo_acqtime - waittime; else @@ -267,59 +269,6 @@ } } -void _lock_profile_update_wait(struct lock_object *lo, uint64_t waitstart) -{ - struct lock_profile_object *l = &lo->lo_profile_obj; - - if (lock_prof_enable && waitstart) { - uint64_t now, waittime; - struct lock_prof *mpp; - u_int hash; - const char *p = l->lpo_filename; - int collision = 0; - now = nanoseconds(); - if (now < waitstart) - return; - waittime = now - waitstart; - hash = (l->lpo_namehash * 31 * 31 + (uintptr_t)p * 31 + l->lpo_lineno) & LPROF_HASH_MASK; - - mpp = &lprof_buf[hash]; - while (mpp->name != NULL) { - if (mpp->line == l->lpo_lineno && - mpp->file == p && - mpp->namehash == l->lpo_namehash) - break; - /* If the lprof_hash entry is allocated to someone else, try the next one */ - collision = 1; - CTR4(KTR_SPARE1, "Hash collision, %s:%d %s(%x)", mpp->file, mpp->line, mpp->name, mpp->namehash); - hash = (hash + 1) & LPROF_HASH_MASK; - mpp = &lprof_buf[hash]; - } - if (mpp->name == NULL) { - int buf; - - buf = atomic_fetchadd_int(&allocated_lprof_buf, 1); - /* Just exit if we cannot get a trace buffer */ - if (buf >= LPROF_HASH_SIZE) { - ++lock_prof_rejected; - return; - } - mpp->file = p; - mpp->line = l->lpo_lineno; - mpp->namehash = l->lpo_namehash; - mpp->type = l->lpo_type; - mpp->name = lo->lo_name; - if (collision) - ++lock_prof_collisions; - /* We might have raced someone else but who cares, they'll try again next time */ - ++lock_prof_records; - } - LPROF_LOCK(hash); - mpp->cnt_wait += waittime; - LPROF_UNLOCK(hash); - } -} - void _lock_profile_release_lock(struct lock_object *lo) { struct lock_profile_object *l = &lo->lo_profile_obj; @@ -332,7 +281,14 @@ const char *p = l->lpo_filename; int collision = 0; - now = nanoseconds(); + /* + * Don't track release time unless contested + * on acquire we really want to check if others + * wanted to acquire while it was held + */ + if (l->lpo_acqtime ! = 0) + now = nanoseconds(); + acqtime = l->lpo_acqtime; waittime = l->lpo_waittime; if (now <= acqtime)