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>
index | next in thread | raw e-mail
[-- Attachment #1 --]
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
[-- Attachment #2 --]
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
# -------------------------------
help
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?xzp8z88e6i1.fsf>