Date: 01 Apr 2002 00:07:18 +0200 From: Dag-Erling Smorgrav <des@ofug.org> To: arch@freebsd.org Subject: mutex profiling Message-ID: <xzp8z88e6i1.fsf@flood.ping.uio.no>
next in thread | raw e-mail | index | archive | help
--=-=-=
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 <sys/param.h>
+#include <sys/systm.h>
#include <sys/bus.h>
#include <sys/kernel.h>
+#include <sys/ktr.h>
#include <sys/lock.h>
#include <sys/malloc.h>
#include <sys/mutex.h>
#include <sys/proc.h>
#include <sys/resourcevar.h>
+#include <sys/sbuf.h>
#include <sys/sysctl.h>
-#include <sys/systm.h>
#include <sys/vmmeter.h>
-#include <sys/ktr.h>
#include <machine/atomic.h>
#include <machine/bus.h>
@@ -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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?xzp8z88e6i1.fsf>