From owner-freebsd-arch Sun Mar 31 14: 7:35 2002 Delivered-To: freebsd-arch@freebsd.org Received: from flood.ping.uio.no (flood.ping.uio.no [129.240.78.31]) by hub.freebsd.org (Postfix) with ESMTP id 74BAA37B417 for ; Sun, 31 Mar 2002 14:07:22 -0800 (PST) Received: by flood.ping.uio.no (Postfix, from userid 2602) id 4B85B5346; Mon, 1 Apr 2002 00:07:19 +0200 (CEST) X-URL: http://www.ofug.org/~des/ X-Disclaimer: The views expressed in this message do not necessarily coincide with those of any organisation or company with which I am or have been affiliated. To: arch@freebsd.org Subject: mutex profiling From: Dag-Erling Smorgrav Date: 01 Apr 2002 00:07:18 +0200 Message-ID: Lines: 87 User-Agent: Gnus/5.0808 (Gnus v5.8.8) Emacs/21.1 MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="=-=-=" Sender: owner-freebsd-arch@FreeBSD.ORG Precedence: bulk List-ID: List-Archive: (Web Archive) List-Help: (List Instructions) List-Subscribe: List-Unsubscribe: X-Loop: FreeBSD.ORG --=-=-= The attached patch (derived from patches by Eivind) adds code to record statistics about MTX_DEF locks. It's currently i386-only as it uses the TSC to measure the amount of time each mutex is held. Once compiled in and enabled, statistics can be retrieved using sysctl(8). The code records four numbers for each mutex (longest time held in one go, total time held, number of acquisitions, average time held) and returns a top-16 list for each. Each mutex is identified by the place where it was first acquired, so multiple instances of the same type of mutex (e.g. proc lock, filedesc lock) are counted as one. Here's a sample listing (with some annotations): des@des ~% sysctl kern.mtx.trace kern.mtx.trace.enable: 1 kern.mtx.trace.max: 20880774 kern/kern_fork.c:467 12632714 dev/sound/pcm/channel.c:677 10653798 i386/i386/machdep.c:1715 2222570 kern/kern_descrip.c:748 1101574 pci/if_xl.c:1259 812677 vm/uma_core.c:232 723969 dev/random/yarrow.c:265 523384 vm/uma_core.c:1179 500278 kern/kern_lock.c:227 427118 kern/vfs_subr.c:936 357190 kern/vfs_syscalls.c:1692 141822 vm/uma_core.c:985 79442 kern/vfs_lookup.c:149 65260 dev/sound/pcm/sound.c:134 52277 vm/uma_core.c:1301 36987 kern/kern_fork.c:535 kern.mtx.trace.total: 5472784414 i386/i386/machdep.c:1715 # Giant 1155767274 kern/kern_descrip.c:748 # filedesc lock 400100257 kern/kern_fork.c:467 # proc lock 352664142 kern/kern_lock.c:227 229755648 kern/sys_generic.c:800 # select(2) lock 226619967 kern/vfs_syscalls.c:1692 # file lock 116591756 vm/uma_core.c:1179 # zone lock 113001343 kern/vfs_subr.c:1857 # vnode lock 68279100 kern/kern_descrip.c:1108 28700835 pci/if_xl.c:1259 25726912 kern/vfs_lookup.c:149 25351235 kern/vfs_subr.c:1805 24323335 dev/sound/pcm/channel.c:677 21193642 kern/kern_sx.c:147 20097794 kern/vfs_subr.c:1788 18994392 kern/subr_mbuf.c:452 kern.mtx.trace.count: 1780724 kern/kern_fork.c:467 # proc lock 1127992 i386/i386/machdep.c:1715 # Giant 753901 kern/kern_lock.c:227 592171 kern/sys_generic.c:800 # select(2) lock 438879 vm/uma_core.c:1179 # zone lock 419580 kern/kern_descrip.c:748 # filedesc lock 407064 kern/vfs_syscalls.c:1692 258866 kern/vfs_subr.c:1857 104235 kern/kern_sx.c:147 86810 kern/vfs_subr.c:1788 61475 kern/vfs_subr.c:1805 52572 kern/subr_mbuf.c:452 36992 kern/vfs_vnops.c:762 36415 sys/buf.h:278 28884 kern/kern_resource.c:900 28421 kern/kern_descrip.c:1108 kern.mtx.trace.average: 3040416 dev/sound/pcm/channel.c:677 126265 vm/uma_core.c:985 # zone lock 38844 dev/random/yarrow.c:265 11743 pci/if_xl.c:1259 8335 dev/sound/pcm/sound.c:134 6292 kern/kern_fork.c:535 6069 kern/subr_disklabel.c:95 4852 i386/i386/machdep.c:1715 4554 kern/vfs_subr.c:936 3575 vm/uma_core.c:232 3337 vm/uma_core.c:1761 2787 vm/swap_pager.c:306 2754 kern/kern_descrip.c:748 2552 net/bpf.c:254 2402 kern/kern_descrip.c:1108 2321 kern/sys_pipe.c:1302 DES -- Dag-Erling Smorgrav - des@ofug.org --=-=-= Content-Type: text/x-patch Content-Disposition: attachment; filename=mutex_trace.diff Index: sys/_mutex.h =================================================================== RCS file: /home/ncvs/src/sys/sys/_mutex.h,v retrieving revision 1.4 diff -u -r1.4 _mutex.h --- sys/_mutex.h 18 Dec 2001 00:27:18 -0000 1.4 +++ sys/_mutex.h 23 Mar 2002 17:41:05 -0000 @@ -41,6 +41,10 @@ volatile u_int mtx_recurse; /* number of recursive holds */ TAILQ_HEAD(, thread) mtx_blocked; /* threads blocked on this lock */ LIST_ENTRY(mtx) mtx_contested; /* list of all contested locks */ +#ifdef TRACE_MUTEX_TIME + u_int64_t tsc; + char name[64]; +#endif }; #endif /* !_SYS_MUTEX_TYPES_H_ */ Index: kern/kern_mutex.c =================================================================== RCS file: /home/ncvs/src/sys/kern/kern_mutex.c,v retrieving revision 1.83 diff -u -r1.83 kern_mutex.c --- kern/kern_mutex.c 27 Mar 2002 09:23:38 -0000 1.83 +++ kern/kern_mutex.c 31 Mar 2002 21:42:56 -0000 @@ -37,17 +37,18 @@ #include "opt_ddb.h" #include +#include #include #include +#include #include #include #include #include #include +#include #include -#include #include -#include #include #include @@ -196,6 +197,121 @@ } } +#ifdef TRACE_MUTEX_TIME +#define TRACE_HASH_SIZE 1009 +SYSCTL_NODE(_kern, OID_AUTO, mtx, CTLFLAG_RD, NULL, "mutex manipulation"); +SYSCTL_NODE(_kern_mtx, OID_AUTO, trace, CTLFLAG_RD, NULL, "mutex tracing"); +static int kern_mtx_trace_enable = 0; +SYSCTL_INT(_kern_mtx_trace, OID_AUTO, enable, CTLFLAG_RW, + &kern_mtx_trace_enable, 0, "Enable tracing of mutex holdtime"); +static int kern_mtx_trace_numtraced = 0; +#ifdef DIAGNOSTICS +SYSCTL_INT(_kern_mtx_trace, OID_AUTO, numtraced, CTLFLAG_RD, + &kern_mtx_trace_numtraced, 0, "Number of traced mutices"); +static int kern_mtx_trace_hashsize = TRACE_HASH_SIZE; +SYSCTL_INT(_kern_mtx_trace, OID_AUTO, hashsize, CTLFLAG_RD, + &kern_mtx_trace_hashsize, 0, "Trace hash size"); +static int kern_mtx_trace_collisions = 0; +SYSCTL_INT(_kern_mtx_trace, OID_AUTO, collisions, CTLFLAG_RD, + &kern_mtx_trace_collisions, 0, "Number of hash collisions"); +#endif + +static struct mutex_trace { + char name[64]; +#define TRACE_MAX 0 +#define TRACE_TOT 1 +#define TRACE_CNT 2 +#define TRACE_AVG 3 + u_int64_t tsc[4]; + struct mutex_trace *next; +} *mutex_traces[TRACE_HASH_SIZE]; + +static struct mtx trace_mtx; + +static void +mutex_trace_init(void *arg __unused) +{ + mtx_init(&trace_mtx, "mutex trace lock", MTX_SPIN|MTX_QUIET); +} +SYSINIT(mtxtraceinit, SI_SUB_LOCK, SI_ORDER_ANY, mutex_trace_init, NULL); + +/* + * tracebuf is the pool of trace records we have; + * we cannot (reliably) handle more than this number + * of places in the code where mutexes are aquired. + * + * We use a static allocation to avoid interacting + * with the rest of the system. + */ +#define NUM_TRACE_BUFFERS 1000 +static struct mutex_trace tracebuf[NUM_TRACE_BUFFERS]; +static int first_free_mutex_trace = 0; + +static const char *unknown = "(unknown)"; + +/* Number of locks to show in the sysctl. */ +#define NUM_LOCKS_TO_DUMP 16 + +/* + * Output statistics of mutex holders that keep the mutex the longest. + */ +static int dump_mtx_trace(SYSCTL_HANDLER_ARGS); +SYSCTL_PROC(_kern_mtx_trace, OID_AUTO, max, CTLTYPE_STRING|CTLFLAG_RD, + NULL, TRACE_MAX, dump_mtx_trace, "A", ""); +SYSCTL_PROC(_kern_mtx_trace, OID_AUTO, total, CTLTYPE_STRING|CTLFLAG_RD, + NULL, TRACE_TOT, dump_mtx_trace, "A", ""); +SYSCTL_PROC(_kern_mtx_trace, OID_AUTO, count, CTLTYPE_STRING|CTLFLAG_RD, + NULL, TRACE_CNT, dump_mtx_trace, "A", ""); +SYSCTL_PROC(_kern_mtx_trace, OID_AUTO, average, CTLTYPE_STRING|CTLFLAG_RD, + NULL, TRACE_AVG, dump_mtx_trace, "A", ""); +static int +dump_mtx_trace(SYSCTL_HANDLER_ARGS) +{ + struct sbuf *sb; + struct mutex_trace *mtp; + int traces[NUM_LOCKS_TO_DUMP]; + int error, i, j, k, n; + + if (kern_mtx_trace_numtraced == 0) + return SYSCTL_OUT(req, "No locking recorded", + sizeof("No locking recorded")); + n = arg2; + + /* + * Find the 10 largest + */ + mtx_lock_spin(&trace_mtx); + for (i = 0; i < NUM_LOCKS_TO_DUMP; ++i) + traces[i] = -1; + for (k = 0; k < first_free_mutex_trace; ++k) { + for (i = 0; i < NUM_LOCKS_TO_DUMP; ++i) { + if (traces[i] == -1) { + traces[i] = k; + break; + } + if (tracebuf[k].tsc[n] < tracebuf[traces[i]].tsc[n]) + continue; + for (j = NUM_LOCKS_TO_DUMP - 1; j > i; --j) + traces[j] = traces[j - 1]; + traces[i] = k; + break; + } + } + + /* Now dump the garbage */ + sb = sbuf_new(NULL, NULL, 256, SBUF_AUTOEXTEND); + for (i = 0; i < NUM_LOCKS_TO_DUMP && traces[i] != -1; ++i) { + mtp = &tracebuf[traces[i]]; + sbuf_printf(sb, "%12llu %s\n", mtp->tsc[n], mtp->name); + } + sbuf_finish(sb); + mtx_unlock_spin(&trace_mtx); + error = SYSCTL_OUT(req, sbuf_data(sb), sbuf_len(sb) + 1); + sbuf_delete(sb); + return (error); +} +#endif /* TRACE_MUTEX_TIME */ + /* * Function versions of the inlined __mtx_* macros. These are used by * modules and can also be called from assembly language if needed. @@ -209,6 +325,18 @@ LOCK_LOG_LOCK("LOCK", &m->mtx_object, opts, m->mtx_recurse, file, line); WITNESS_LOCK(&m->mtx_object, opts | LOP_EXCLUSIVE, file, line); +#ifdef TRACE_MUTEX_TIME + m->tsc = kern_mtx_trace_enable ? rdtsc() : 0; + if (m->name[0] == '\0') { + const char *p = file; + + while (p && strncmp(p, "../", 3) == 0) + p += 3; + if (p == NULL || *p == '\0') + p = unknown; + snprintf(m->name, sizeof m->name, "%s:%d", p, line); + } +#endif } void @@ -217,6 +345,53 @@ MPASS(curthread != NULL); mtx_assert(m, MA_OWNED); +#ifdef TRACE_MUTEX_TIME + if (m->tsc != 0 && m->name[0] != '\0') { + struct mutex_trace *mtp; + u_int64_t tsc, mtsc; + volatile u_int hash; + char *p; + + tsc = rdtsc(); + mtsc = m->tsc; + m->tsc = 0; + if (tsc <= mtsc) + goto out; + hash = 0; + for (p = m->name; *p != '\0'; ++p) + hash = ((hash << 1) | *p) % TRACE_HASH_SIZE; + mtx_lock_spin(&trace_mtx); + for (mtp = mutex_traces[hash]; mtp != NULL; mtp = mtp->next) + if (strcmp(mtp->name, m->name) == 0) + break; + if (mtp == NULL) { + /* Just exit if we cannot get a trace buffer */ + if (first_free_mutex_trace >= NUM_TRACE_BUFFERS) + goto unlock; + mtp = &tracebuf[first_free_mutex_trace++]; + strcpy(mtp->name, m->name); +#ifdef DIAGNOSTICS + if (mutex_traces[hash] != NULL) + ++kern_mtx_trace_collisions; +#endif + mtp->next = mutex_traces[hash]; + mutex_traces[hash] = mtp; + ++kern_mtx_trace_numtraced; + } + /* + * Record if the mutex has been held longer now than ever + * before + */ + if ((tsc - mtsc) > mtp->tsc[TRACE_MAX]) + mtp->tsc[TRACE_MAX] = tsc - mtsc; + mtp->tsc[TRACE_TOT] += tsc - mtsc; + mtp->tsc[TRACE_CNT] += 1; + mtp->tsc[TRACE_AVG] = mtp->tsc[TRACE_TOT] / mtp->tsc[TRACE_CNT]; +unlock: + mtx_unlock_spin(&trace_mtx); + } +out: +#endif WITNESS_UNLOCK(&m->mtx_object, opts | LOP_EXCLUSIVE, file, line); LOCK_LOG_LOCK("UNLOCK", &m->mtx_object, opts, m->mtx_recurse, file, line); Index: conf/options.i386 =================================================================== RCS file: /home/ncvs/src/sys/conf/options.i386,v retrieving revision 1.169 diff -u -r1.169 options.i386 --- conf/options.i386 27 Feb 2002 09:51:31 -0000 1.169 +++ conf/options.i386 23 Mar 2002 18:04:45 -0000 @@ -188,6 +188,9 @@ # SMB/CIFS filesystem SMBFS +# Mutex profiling +TRACE_MUTEX_TIME opt_global.h + # ------------------------------- # EOF # ------------------------------- --=-=-=-- To Unsubscribe: send mail to majordomo@FreeBSD.org with "unsubscribe freebsd-arch" in the body of the message