From owner-p4-projects@FreeBSD.ORG Fri Jun 23 19:54:27 2006 Return-Path: X-Original-To: p4-projects@freebsd.org Delivered-To: p4-projects@freebsd.org Received: by hub.freebsd.org (Postfix, from userid 32767) id 2887B16A4A9; Fri, 23 Jun 2006 19:54:27 +0000 (UTC) X-Original-To: perforce@freebsd.org Delivered-To: perforce@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 0406416A4A6 for ; Fri, 23 Jun 2006 19:54:27 +0000 (UTC) (envelope-from kmacy@freebsd.org) Received: from repoman.freebsd.org (repoman.freebsd.org [216.136.204.115]) by mx1.FreeBSD.org (Postfix) with ESMTP id ABF1243D45 for ; Fri, 23 Jun 2006 19:54:26 +0000 (GMT) (envelope-from kmacy@freebsd.org) Received: from repoman.freebsd.org (localhost [127.0.0.1]) by repoman.freebsd.org (8.13.6/8.13.6) with ESMTP id k5NJsQb2046290 for ; Fri, 23 Jun 2006 19:54:26 GMT (envelope-from kmacy@freebsd.org) Received: (from perforce@localhost) by repoman.freebsd.org (8.13.6/8.13.4/Submit) id k5NJsQTp046287 for perforce@freebsd.org; Fri, 23 Jun 2006 19:54:26 GMT (envelope-from kmacy@freebsd.org) Date: Fri, 23 Jun 2006 19:54:26 GMT Message-Id: <200606231954.k5NJsQTp046287@repoman.freebsd.org> X-Authentication-Warning: repoman.freebsd.org: perforce set sender to kmacy@freebsd.org using -f From: Kip Macy To: Perforce Change Reviews Cc: Subject: PERFORCE change 99891 for review X-BeenThere: p4-projects@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: p4 projects tree changes List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 23 Jun 2006 19:54:27 -0000 http://perforce.freebsd.org/chv.cgi?CH=99891 Change 99891 by kmacy@kmacy_storage:sun4v_work_sleepq on 2006/06/23 19:53:42 re-factor MUTEX_PROFILING code into inline functions re-enable (in a architecture dependent way) hold time collection Affected files ... .. //depot/projects/kmacy_sun4v/src/sys/kern/kern_mutex.c#11 edit Differences ... ==== //depot/projects/kmacy_sun4v/src/sys/kern/kern_mutex.c#11 (text+ko) ==== @@ -156,24 +156,19 @@ #endif #ifdef MUTEX_PROFILING -SYSCTL_NODE(_debug, OID_AUTO, mutex, CTLFLAG_RD, NULL, "mutex debugging"); -SYSCTL_NODE(_debug_mutex, OID_AUTO, prof, CTLFLAG_RD, NULL, "mutex profiling"); -static int mutex_prof_enable = 0; -SYSCTL_INT(_debug_mutex_prof, OID_AUTO, enable, CTLFLAG_RW, - &mutex_prof_enable, 0, "Enable tracing of mutex holdtime/contention"); -static int mutex_prof_global = 1; -SYSCTL_INT(_debug_mutex_prof, OID_AUTO, global, CTLFLAG_RW, - &mutex_prof_global, 0, "Enable tracing of all mutexes"); +#include +#ifndef MPROF_HASH_SIZE +#define MPROF_HASH_SIZE 4096 +#define MPROF_HASH_MASK (MPROF_HASH_SIZE - 1) +#endif struct mutex_prof { const char *name; + const char *file; u_int namehash; - const char *file; int line; -#if 0 uintmax_t cnt_max; uintmax_t cnt_tot; -#endif uintmax_t cnt_cur; uintmax_t cnt_contest_holding; uintmax_t cnt_contest_locking; @@ -183,10 +178,6 @@ * mprof_buf is a static pool of profiling records to avoid possible * reentrance of the memory allocation functions. */ -#ifndef MPROF_HASH_SIZE -#define MPROF_HASH_SIZE 4096 -#define MPROF_HASH_MASK (MPROF_HASH_SIZE - 1) -#endif static struct mutex_prof mprof_buf[MPROF_HASH_SIZE]; static int allocated_mprof_buf; /* SWAG: sbuf size = avg stat. line size * number of locks */ @@ -199,9 +190,13 @@ #define MPROF_LOCK(hash) mtx_lock_spin(&mprof_locks[MPROF_LHASH(hash)]) #define MPROF_UNLOCK(hash) mtx_unlock_spin(&mprof_locks[MPROF_LHASH(hash)]) - struct mtx mprof_locks[MPROF_LOCK_SIZE]; +SYSCTL_NODE(_debug, OID_AUTO, mutex, CTLFLAG_RD, NULL, "mutex debugging"); +SYSCTL_NODE(_debug_mutex, OID_AUTO, prof, CTLFLAG_RD, NULL, "mutex profiling"); +static int mutex_prof_enable = 0; +SYSCTL_INT(_debug_mutex_prof, OID_AUTO, enable, CTLFLAG_RW, + &mutex_prof_enable, 0, "Enable tracing of mutex holdtime/contention"); static int mutex_prof_acquisitions; SYSCTL_INT(_debug_mutex_prof, OID_AUTO, acquisitions, CTLFLAG_RD, &mutex_prof_acquisitions, 0, "Number of mutex acquistions recorded"); @@ -226,17 +221,148 @@ &stack_scale, 0, "How often to sample stack traces"); #endif + + +static inline void +mtx_profile_init(struct mtx *m, const char *name) { + const char *p; + u_int hash = 0; + + m->mtx_acqtime = 0; + m->mtx_filename = NULL; + m->mtx_lineno = 0; + m->mtx_contest_holding = 0; + m->mtx_contest_locking = 0; + + /* Hash the mutex name to an int so we don't have to strcmp() it repeatedly */ + for (p = name; *p != '\0'; p++) + hash = 31 * hash + *p; + m->mtx_namehash = hash; +#if 0 + if (opts & MTX_PROFILE) + m->mtx_stack = stack_create(); +#endif +} + +static inline void +mtx_profile_destroy(struct mtx *m) +{ #if 0 -static u_int64_t -nanoseconds(void) + if (m->mtx_object.lo_flags & LO_PROFILE) + stack_destroy(m->mtx_stack); +#endif +} + +static inline void +mutex_profile_init(void) { - struct timespec tv; + int i; + /* Initialize the mutex profiling locks */ + for (i = 0; i < MPROF_LOCK_SIZE; i++) { + mtx_init(&mprof_locks[i], "mprof lock", + NULL, MTX_SPIN|MTX_QUIET); + } +} - nanotime(&tv); - return (tv.tv_sec * (u_int64_t)1000000000 + tv.tv_nsec); +static inline void +mtx_profile_obtain_lock_failed(struct mtx *m, int *contested) +{ + if (mutex_prof_enable) { + *contested = 1; + atomic_add_int(&m->mtx_contest_holding, 1); + } } + +static inline void +mtx_profile_obtain_lock_success(struct mtx *m, const char *file, int line) +{ + /* don't reset the timer when/if recursing */ + if (mutex_prof_enable && m->mtx_acqtime == 0) { + m->mtx_filename = file; + m->mtx_lineno = line; + m->mtx_acqtime = rd(tick); /* substitute for more general TSC read */ +#if 0 + ++mutex_prof_acquisitions; #endif + } +} + +static void +mtx_profile_release_lock(struct mtx *m) +{ + + if (m->mtx_acqtime) { + const char *unknown = "(unknown)"; + struct mutex_prof *mpp; + u_int64_t acqtime, now; + u_int hash; + const char *p = m->mtx_filename; + int collision = 0; + + now = rd(tick); + acqtime = m->mtx_acqtime; + m->mtx_acqtime = 0; + if (now <= acqtime) + return; + if (p == NULL || *p == '\0') + p = unknown; + hash = (m->mtx_namehash * 31 * 31 + (uintptr_t)p * 31 + m->mtx_lineno) & MPROF_HASH_MASK; + CTR5(KTR_SPARE1, "Hashing %s(%x) %s:%d to %d", mtx_name(m), m->mtx_namehash, p, m->mtx_lineno, hash); + mpp = &mprof_buf[hash]; + while (mpp->name != NULL) { + if (mpp->line == m->mtx_lineno && + mpp->file == p && + mpp->namehash == m->mtx_namehash) + break; + /* If the mprof_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) & MPROF_HASH_MASK; + mpp = &mprof_buf[hash]; + } + if (mpp->name == NULL) { + int buf; + buf = atomic_fetchadd_int(&allocated_mprof_buf, 1); + /* Just exit if we cannot get a trace buffer */ + if (buf >= MPROF_HASH_SIZE) { + ++mutex_prof_rejected; + return; + } + mpp->file = p; + mpp->line = m->mtx_lineno; + mpp->name = mtx_name(m); + mpp->namehash = m->mtx_namehash; + if (collision) + ++mutex_prof_collisions; + /* We might have raced someone else but who cares, they'll try again next time */ + ++mutex_prof_records; + } + MPROF_LOCK(hash); + /* + * Record if the mutex has been held longer now than ever + * before. + */ + if (now - acqtime > mpp->cnt_max) + mpp->cnt_max = now - acqtime; + mpp->cnt_tot += now - acqtime; + mpp->cnt_cur++; + /* + * There's a small race, really we should cmpxchg + * 0 with the current value, but that would bill + * the contention to the wrong lock instance if + * it followed this also. + */ + mpp->cnt_contest_holding += m->mtx_contest_holding; + m->mtx_contest_holding = 0; + mpp->cnt_contest_locking += m->mtx_contest_locking; + m->mtx_contest_locking = 0; + MPROF_UNLOCK(hash); + } +} + + + static int dump_mutex_prof_stats(SYSCTL_HANDLER_ARGS) { @@ -260,18 +386,11 @@ p != NULL && strncmp(p, "../", 3) == 0; p += 3) /* nothing */ ; sbuf_printf(sb, "%6ju %12ju %11ju %5ju %12ju %12ju %s:%d (%s)\n", -#if 0 mprof_buf[i].cnt_max / 1000, mprof_buf[i].cnt_tot / 1000, -#endif - (uintmax_t)0, - (uintmax_t)0, mprof_buf[i].cnt_cur, - (uintmax_t)0, -#if 0 mprof_buf[i].cnt_cur == 0 ? (uintmax_t)0 : mprof_buf[i].cnt_tot / (mprof_buf[i].cnt_cur * 1000), -#endif mprof_buf[i].cnt_contest_holding, mprof_buf[i].cnt_contest_locking, p, mprof_buf[i].line, mprof_buf[i].name); @@ -313,6 +432,15 @@ } SYSCTL_PROC(_debug_mutex_prof, OID_AUTO, reset, CTLTYPE_INT | CTLFLAG_RW, NULL, 0, reset_mutex_prof_stats, "I", "Reset mutex profiling statistics"); + +#else +static inline void mtx_profile_init(struct mtx *m, const char *name) {;} +static inline void mtx_profile_destroy(struct mtx *m) {;} +static inline void mtx_profile_obtain_lock_failed(struct mtx *m, int *contested) {;} +static inline void mtx_profile_obtain_lock_success(struct mtx *m, const char *file, int line) {;} +static inline void mtx_profile_release_lock(struct mtx *m) {;} + +static inline void mutex_profile_init(void) {;} #endif /* @@ -333,17 +461,7 @@ LOCK_LOG_LOCK("LOCK", &m->mtx_object, opts, m->mtx_recurse, file, line); WITNESS_LOCK(&m->mtx_object, opts | LOP_EXCLUSIVE, file, line); -#ifdef MUTEX_PROFILING - /* don't reset the timer when/if recursing */ - if (mutex_prof_enable == 1 && mutex_prof_global && m->mtx_acqtime == 0) { - m->mtx_filename = file; - m->mtx_lineno = line; - m->mtx_acqtime = 1; -#if 0 - ++mutex_prof_acquisitions; -#endif - } -#endif + mtx_profile_obtain_lock_success(m, file, line); } void @@ -358,79 +476,8 @@ LOCK_LOG_LOCK("UNLOCK", &m->mtx_object, opts, m->mtx_recurse, file, line); mtx_assert(m, MA_OWNED); -#ifdef MUTEX_PROFILING - if (mutex_prof_global && m->mtx_acqtime != 0) { - const char *unknown = "(unknown)"; - struct mutex_prof *mpp; - u_int64_t acqtime, now; - u_int hash; - const char *p = m->mtx_filename; - int collision = 0; - now = 2; - acqtime = m->mtx_acqtime; - m->mtx_acqtime = 0; - if (now <= acqtime) - goto out; - if (p == NULL || *p == '\0') - p = unknown; - hash = (m->mtx_namehash * 31 * 31 + (uintptr_t)p * 31 + m->mtx_lineno) & MPROF_HASH_MASK; - CTR5(KTR_SPARE1, "Hashing %s(%x) %s:%d to %d", mtx_name(m), m->mtx_namehash, p, m->mtx_lineno, hash); - mpp = &mprof_buf[hash]; - while (mpp->name != NULL) { - if (mpp->line == m->mtx_lineno && - mpp->file == p && - mpp->namehash == m->mtx_namehash) - break; - /* If the mprof_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) & MPROF_HASH_MASK; - mpp = &mprof_buf[hash]; - } - if (mpp->name == NULL) { - int buf; - - buf = atomic_fetchadd_int(&allocated_mprof_buf, 1); - /* Just exit if we cannot get a trace buffer */ - if (buf >= MPROF_HASH_SIZE) { - ++mutex_prof_rejected; - goto out; - } - mpp->file = p; - mpp->line = m->mtx_lineno; - mpp->name = mtx_name(m); - mpp->namehash = m->mtx_namehash; - if (collision) - ++mutex_prof_collisions; - /* We might have raced someone else but who cares, they'll try again next time */ - ++mutex_prof_records; - } - MPROF_LOCK(hash); - /* - * Record if the mutex has been held longer now than ever - * before. - */ -#if 0 - if (now - acqtime > mpp->cnt_max) - mpp->cnt_max = now - acqtime; - mpp->cnt_tot += now - acqtime; -#endif - mpp->cnt_cur++; - /* - * There's a small race, really we should cmpxchg - * 0 with the current value, but that would bill - * the contention to the wrong lock instance if - * it followed this also. - */ - mpp->cnt_contest_holding += m->mtx_contest_holding; - m->mtx_contest_holding = 0; - mpp->cnt_contest_locking += m->mtx_contest_locking; - m->mtx_contest_locking = 0; - MPROF_UNLOCK(hash); - } -out: -#endif + mtx_profile_release_lock(m); _rel_sleep_lock(m, curthread, opts, file, line); } @@ -514,9 +561,7 @@ int cont_logged = 0; #endif #endif -#ifdef MUTEX_PROFILING - int contested, oldhold, fine_profiling = 0; -#endif + int contested; if (mtx_owned(m)) { KASSERT((m->mtx_object.lo_flags & LO_RECURSABLE) != 0, @@ -534,35 +579,8 @@ "_mtx_lock_sleep: %s contested (lock=%p) at %s:%d", m->mtx_object.lo_name, (void *)m->mtx_lock, file, line); -#ifdef MUTEX_PROFILING - contested = 0; - if (m->mtx_object.lo_flags & LO_PROFILE) - fine_profiling = 1; -#endif while (!_obtain_lock(m, tid)) { -#ifdef MUTEX_PROFILING - if (mutex_prof_global) { - contested = 1; - atomic_add_int(&m->mtx_contest_holding, 1); - } else if (fine_profiling && !contested) { - contested = 1; - oldhold = atomic_fetchadd_int(&m->mtx_contest_holding, 1); -#if 0 - if (!((oldhold + 1) % stack_scale)) { - mtx_lock_spin(&mprof_mtx); - stack_save(&mtx_stack); - CTR2(KTR_CONTENTION, "cont_hold (%d) of %s", oldhold, m->mtx_object.lo_name); - CTRSTACK(KTR_CONTENTION, &mtx_stack, 4, 0); - mtx_unlock_spin(&mprof_mtx); - } - CTR3(KTR_CONTENTION, - "%s held by %s:%d", - m->mtx_object.lo_name, - m->mtx_filename, - m->mtx_lineno); -#endif - } -#endif + mtx_profile_obtain_lock_failed(m, &contested); turnstile_lock(&m->mtx_object); v = m->mtx_lock; @@ -645,7 +663,7 @@ #endif #endif #ifdef MUTEX_PROFILING - if (fine_profiling || mutex_prof_global) { + if (mutex_prof_enable) { m->mtx_contest_locking = contested; atomic_store_rel_int(&m->mtx_contest_holding,0); } @@ -920,10 +938,6 @@ { struct lock_class *class; int flags; -#ifdef MUTEX_PROFILING - const char *p; - u_int hash = 0; -#endif MPASS((opts & ~(MTX_SPIN | MTX_QUIET | MTX_RECURSE | MTX_NOWITNESS | MTX_DUPOK)) == 0); @@ -953,23 +967,8 @@ /* Initialize mutex. */ m->mtx_lock = MTX_UNOWNED; m->mtx_recurse = 0; -#ifdef MUTEX_PROFILING - m->mtx_acqtime = 0; - m->mtx_filename = NULL; - m->mtx_lineno = 0; - m->mtx_contest_holding = 0; - m->mtx_contest_locking = 0; - /* Hash the mutex name to an int so we don't have to strcmp() it repeatedly */ - for (p = name; *p != '\0'; p++) - hash = 31 * hash + *p; - m->mtx_namehash = hash; -#if 0 - if (opts & MTX_PROFILE) - m->mtx_stack = stack_create(); -#endif -#endif - + mtx_profile_init(m, name); lock_init(&m->mtx_object, class, name, type, flags); } @@ -996,14 +995,8 @@ WITNESS_UNLOCK(&m->mtx_object, LOP_EXCLUSIVE, __FILE__, __LINE__); } - -#ifdef MUTEX_PROFILING -#if 0 - if (m->mtx_object.lo_flags & LO_PROFILE) - stack_destroy(m->mtx_stack); -#endif -#endif - + + mtx_profile_destroy(m); lock_destroy(&m->mtx_object); } @@ -1015,20 +1008,12 @@ void mutex_init(void) { -#ifdef MUTEX_PROFILING - int i; -#endif - /* Setup turnstiles so that sleep mutexes work. */ init_turnstiles(); -#ifdef MUTEX_PROFILING - /* Initialize the mutex profiling locks */ - for (i = 0; i < MPROF_LOCK_SIZE; i++) { - mtx_init(&mprof_locks[i], "mprof lock", - NULL, MTX_SPIN|MTX_QUIET); - } -#endif + printf("calling profile init\n"); + mutex_profile_init(); + printf("called profile init\n"); /* * Initialize mutexes.