Index: sys/sys/_mutex.h =================================================================== RCS file: /home/ncvs/src/sys/sys/_mutex.h,v retrieving revision 1.4 diff -u -r1.4 _mutex.h --- sys/sys/_mutex.h 18 Dec 2001 00:27:18 -0000 1.4 +++ sys/sys/_mutex.h 10 Mar 2002 16:43:12 -0000 @@ -41,6 +41,12 @@ 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 + struct timespec tsp; + const char *file; + int line; + int has_trace_time; +#endif }; #endif /* !_SYS_MUTEX_TYPES_H_ */ Index: sys/kern/kern_mutex.c =================================================================== RCS file: /home/ncvs/src/sys/kern/kern_mutex.c,v retrieving revision 1.81 diff -u -r1.81 kern_mutex.c --- sys/kern/kern_mutex.c 20 Feb 2002 21:25:44 -0000 1.81 +++ sys/kern/kern_mutex.c 13 Mar 2002 00:41:24 -0000 @@ -37,17 +37,19 @@ #include "opt_ddb.h" #include +#include #include +#include #include +#include #include #include #include #include #include +#include #include -#include #include -#include #include #include @@ -196,6 +198,106 @@ } } +#ifdef TRACE_MUTEX_TIME +#define TRACE_LOCK_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_hashsize = TRACE_LOCK_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_numtraced = 0; +SYSCTL_INT(_kern_mtx_trace, OID_AUTO, numtraced, CTLFLAG_RD, + &kern_mtx_trace_numtraced, 0, "Number of traced mutices"); +static int kern_mtx_trace_collisions = 0; +SYSCTL_INT(_kern_mtx_trace, OID_AUTO, collisions, CTLFLAG_RD, + &kern_mtx_trace_numtraced, 0, "Number of hash collisions"); +static int kern_mtx_trace_nonzero = 0; +SYSCTL_INT(_kern_mtx_trace, OID_AUTO, nonzero, CTLFLAG_RD, + &kern_mtx_trace_nonzero, 0, "Number of non-zero counts"); +#define mtrace_swap(a, b) do { \ + struct mutex_trace *_swaptmp; \ + \ + _swaptmp = (a); \ + (a) = (b); \ + (b) = _swaptmp; \ +} while (0) + +static struct mutex_trace { + struct mutex_trace *next; + const char *file; + int line; + struct timespec maxtime; /* Maximum time spent by this locking */ + struct timespec totaltime; /* Total time spent by this locking */ +} *mutex_traces[TRACE_LOCK_HASH_SIZE]; + + +/* Number of locks to show in the sysctl. MUST BE AN EVEN NUMBER. */ +#define NUM_LOCKS_TO_DUMP 10 +static long +mutex_trace_cmp(struct mutex_trace *a, struct mutex_trace *b) { + + if (a->maxtime.tv_sec == b->maxtime.tv_sec) + return (long)(a->maxtime.tv_nsec - b->maxtime.tv_nsec); + return (long)(a->maxtime.tv_sec - b->maxtime.tv_sec); +} + +/* + * Output statistics of mutex holders that keep the mutex the longest. + */ +static int +dump_mtx_trace(SYSCTL_HANDLER_ARGS) +{ + struct sbuf *sb; + struct mutex_trace *tlp; + struct mutex_trace *badtraces[NUM_LOCKS_TO_DUMP]; + int error, i, j, tl; + + if (kern_mtx_trace_numtraced == 0) + return SYSCTL_OUT(req, "No locking recorded", + sizeof("No locking recorded")); + + /* + * Find the 10 largest + */ + for (i = 0; i < NUM_LOCKS_TO_DUMP; ++i) + badtraces[i] = NULL; + for (tl = 0; tl < TRACE_LOCK_HASH_SIZE; ++tl) { + for (tlp = mutex_traces[tl]; tlp != NULL; tlp = tlp->next) { + for (i = 0; i < NUM_LOCKS_TO_DUMP; ++i) { + if (badtraces[i] == NULL) { + badtraces[i] = tlp; + break; + } + if (mutex_trace_cmp(tlp, badtraces[i]) < 0) + continue; + for (j = NUM_LOCKS_TO_DUMP - 1; j > i; --j) + badtraces[j] = badtraces[j - 1]; + badtraces[i] = tlp; + break; + } + } + } + + /* Now dump the garbage */ + sb = sbuf_new(NULL, NULL, 256, SBUF_AUTOEXTEND); + for (i = 0; i < NUM_LOCKS_TO_DUMP && badtraces[i] != NULL; i++) + sbuf_printf(sb, "%s:%d: held %d.%09ds\n", + badtraces[i]->file, + badtraces[i]->line, + badtraces[i]->maxtime.tv_sec, + badtraces[i]->maxtime.tv_sec); + sbuf_finish(sb); + error = SYSCTL_OUT(req, sbuf_data(sb), sbuf_len(sb)); + sbuf_delete(sb); + return (error); +} +SYSCTL_PROC(_kern_mtx_trace, OID_AUTO, stats, CTLTYPE_STRING|CTLFLAG_RD, + NULL, 0, dump_mtx_trace, "A", "Statistics about how long mutexes are held"); +#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,14 +311,107 @@ 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 + if (kern_mtx_trace_enable) { + nanouptime(&m->tsp); + m->has_trace_time = 1; + } else { + m->has_trace_time = 0; + } + m->file = file ? file : "N/A"; + m->line = line; +#endif } +/* + * tracebuffers 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. + */ +static struct mutex_trace tracebuffers[1000]; +static int first_free_mutex_trace = 0; + void _mtx_unlock_flags(struct mtx *m, int opts, const char *file, int line) { MPASS(curthread != NULL); mtx_assert(m, MA_OWNED); +#ifdef TRACE_MUTEX_TIME + if (m->has_trace_time) { + int hash; + const unsigned char *p; + struct mutex_trace *trace; + int newtrace = 0; /* record record in the hash? */ + struct timespec now; + + m->has_trace_time = 0; + nanouptime(&now); + hash = m->line; + for (p = m->file; *p; p++) { + hash *= 257; + hash += *p; + hash %= TRACE_LOCK_HASH_SIZE; + } + for (trace = mutex_traces[hash]; trace; trace = trace->next) + if (trace->line == m->line && + strcmp(trace->file, m->file) == 0) + break; + if (trace == NULL) { + /* Just exit if we cannot get a trace buffer */ + if (first_free_mutex_trace >= + sizeof(tracebuffers) / sizeof(tracebuffers[0])) + goto out; + trace = &tracebuffers[first_free_mutex_trace++]; + /* Race protection */ + if (first_free_mutex_trace > + sizeof(tracebuffers) / sizeof(tracebuffers[0])) + goto out; + trace->line = m->line; + trace->file = m->file; + newtrace = 1; + } + /* + * XXX Not sure if these are the best kind of measurements, + * but they should work. + */ + /* + * Record it if the mutex has been held longer now than ever + * before + */ + now.tv_nsec -= m->tsp.tv_nsec; + now.tv_sec -= m->tsp.tv_sec; + if (now.tv_nsec < 0) { + now.tv_nsec += 1000000000; + now.tv_sec -= 1; + } + if (now.tv_sec > trace->maxtime.tv_sec || + (now.tv_sec == trace->maxtime.tv_sec && + now.tv_nsec > trace->maxtime.tv_nsec)) { + trace->maxtime = now; + ++kern_mtx_trace_nonzero; + } + /* XXX Disable registration as a test */ + if (newtrace) { + if (mutex_traces[hash] != NULL) + ++kern_mtx_trace_collisions; + trace->next = mutex_traces[hash]; + /* + * The next statement is assumed to be an atomic + * assignment. If we are raced to this assignment, we + * just lose a trace buffer - no big deal. This + * assignment only happens when we encounter a mutex + * statement that is not in the hash, anyway. + */ + mutex_traces[hash] = trace; + ++kern_mtx_trace_numtraced; + } + } +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);