Add some improvements to lock debugging. These changes take effect

with DEBUG_THREADS enabled and provide the following:

 * This will keep track of which locks are held by which thread as well as
   which lock a thread is waiting for in a thread-local data structure.  A
   reference to this structure is available on the stack in the dummy_start()
   function, which is the common entry point for all threads.  This information
   can be easily retrieved using gdb if you switch to the dummy_start() stack
   frame of any thread and print the contents of the lock_info variable.

 * All of the thread-local structures for keeping track of this lock information
   are also stored in a list so that the information can be dumped to the CLI
   using the "core show locks" CLI command.  This introduces a little bit of a
   performance hit as it requires additional underlying locking operations
   inside of every lock/unlock on an ast_mutex.  However, the benefits of
   having this information available at the CLI is huge, especially considering
   this is only done in DEBUG_THREADS mode.  It means that in most cases where
   we debug deadlocks, we no longer have to request access to the machine to
   analyze the contents of ast_mutex_t structures.  We can now just ask them
   to get the output of "core show locks", which gives us all of the information
   we needed in most cases.

I also had to make some additional changes to astmm.c to make this work when
both MALLOC_DEBUG and DEBUG_THREADS are enabled.  I disabled tracking of one
of the locks in astmm.c because it gets used inside the replacement memory
allocation routines, and the lock tracking code allocates memory.  This caused
infinite recursion.


git-svn-id: http://svn.digium.com/svn/asterisk/branches/1.4@78095 f38db490-d61c-443f-a65b-d21fe96a405b

3 files changed, 316 insertions, 16 deletions

diff --git a/include/asterisk/lock.h b/include/asterisk/lock.h
index d3a299b64..7f5640561 100644
--- a/include/asterisk/lock.h
+++ b/include/asterisk/lock.h
@@ -103,12 +103,16 @@
 #include <stdio.h>
 #include <unistd.h>
 
-#define AST_MUTEX_INIT_VALUE { PTHREAD_MUTEX_INIT_VALUE, { NULL }, { 0 }, 0, { NULL }, { 0 } }
+#define AST_MUTEX_INIT_VALUE { PTHREAD_MUTEX_INIT_VALUE, 1, { NULL }, { 0 }, 0, { NULL }, { 0 } }
+#define AST_MUTEX_INIT_VALUE_NOTRACKING \
+                             { PTHREAD_MUTEX_INIT_VALUE, 0, { NULL }, { 0 }, 0, { NULL }, { 0 } }
 
 #define AST_MAX_REENTRANCY 10
 
 struct ast_mutex_info {
 	pthread_mutex_t mutex;
+	/*! Track which thread holds this lock */
+	unsigned int track:1;
 	const char *file[AST_MAX_REENTRANCY];
 	int lineno[AST_MAX_REENTRANCY];
 	int reentrancy;
@@ -122,6 +126,30 @@ typedef pthread_cond_t ast_cond_t;
 
 static pthread_mutex_t empty_mutex;
 
+/*!
+ * \brief Store lock info for the current thread
+ *
+ * This function gets called in ast_mutex_lock() and ast_mutex_trylock() so
+ * that information about this lock can be stored in this thread's
+ * lock info struct.  The lock is marked as pending as the thread is waiting
+ * on the lock.  ast_mark_lock_acquired() will mark it as held by this thread.
+ */
+void ast_store_lock_info(const char *filename, int line_num, 
+	const char *func, const char *lock_name, void *lock_addr);
+
+/*!
+ * \brief Mark the last lock as acquired
+ */
+void ast_mark_lock_acquired(void);
+
+/*!
+ * \brief remove lock info for the current thread
+ *
+ * this gets called by ast_mutex_unlock so that information on the lock can
+ * be removed from the current thread's lock info struct.
+ */
+void ast_remove_lock_info(void *lock_addr);
+
 static void __attribute__((constructor)) init_empty_mutex(void)
 {
 	memset(&empty_mutex, 0, sizeof(empty_mutex));
@@ -217,6 +245,9 @@ static inline int __ast_pthread_mutex_lock(const char *filename, int lineno, con
 	int res;
 	int canlog = strcmp(filename, "logger.c");
 
+	if (t->track)
+		ast_store_lock_info(filename, lineno, func, mutex_name, &t->mutex);
+
 #if defined(AST_MUTEX_INIT_W_CONSTRUCTORS)
 	if ((t->mutex) == ((pthread_mutex_t) PTHREAD_MUTEX_INITIALIZER)) {
 		__ast_mutex_logger("%s line %d (%s): Error: mutex '%s' is uninitialized.\n",
@@ -261,6 +292,8 @@ static inline int __ast_pthread_mutex_lock(const char *filename, int lineno, con
 #endif /* DETECT_DEADLOCKS */
 
 	if (!res) {
+		if (t->track)
+			ast_mark_lock_acquired();
 		if (t->reentrancy < AST_MAX_REENTRANCY) {
 			t->file[t->reentrancy] = filename;
 			t->lineno[t->reentrancy] = lineno;
@@ -272,6 +305,8 @@ static inline int __ast_pthread_mutex_lock(const char *filename, int lineno, con
 							   filename, lineno, func, mutex_name);
 		}
 	} else {
+		if (t->track)
+			ast_remove_lock_info(&t->mutex);
 		__ast_mutex_logger("%s line %d (%s): Error obtaining mutex: %s\n",
 				   filename, lineno, func, strerror(res));
 		DO_THREAD_CRASH;
@@ -294,7 +329,12 @@ static inline int __ast_pthread_mutex_trylock(const char *filename, int lineno,
 	}
 #endif /* AST_MUTEX_INIT_W_CONSTRUCTORS */
 
+	if (t->track)
+		ast_store_lock_info(filename, lineno, func, mutex_name, &t->mutex);
+
 	if (!(res = pthread_mutex_trylock(&t->mutex))) {
+		if (t->track)
+			ast_mark_lock_acquired();
 		if (t->reentrancy < AST_MAX_REENTRANCY) {
 			t->file[t->reentrancy] = filename;
 			t->lineno[t->reentrancy] = lineno;
@@ -303,8 +343,10 @@ static inline int __ast_pthread_mutex_trylock(const char *filename, int lineno,
 			t->reentrancy++;
 		} else {
 			__ast_mutex_logger("%s line %d (%s): '%s' really deep reentrancy!\n",
-							   filename, lineno, func, mutex_name);
+					   filename, lineno, func, mutex_name);
 		}
+	} else if (t->track) {
+			ast_remove_lock_info(&t->mutex);
 	}
 
 	return res;
@@ -344,6 +386,9 @@ static inline int __ast_pthread_mutex_unlock(const char *filename, int lineno, c
 		t->thread[t->reentrancy] = 0;
 	}
 
+	if (t->track)
+		ast_remove_lock_info(&t->mutex);
+
 	if ((res = pthread_mutex_unlock(&t->mutex))) {
 		__ast_mutex_logger("%s line %d (%s): Error releasing mutex: %s\n", 
 				   filename, lineno, func, strerror(res));
@@ -412,11 +457,17 @@ static inline int __ast_cond_wait(const char *filename, int lineno, const char *
 		t->thread[t->reentrancy] = 0;
 	}
 
+	if (t->track)
+		ast_remove_lock_info(&t->mutex);
+
 	if ((res = pthread_cond_wait(cond, &t->mutex))) {
 		__ast_mutex_logger("%s line %d (%s): Error waiting on condition mutex '%s'\n", 
 				   filename, lineno, func, strerror(res));
 		DO_THREAD_CRASH;
 	} else {
+		if (t->track)
+			ast_store_lock_info(filename, lineno, func, mutex_name, &t->mutex);
+
 		if (t->reentrancy < AST_MAX_REENTRANCY) {
 			t->file[t->reentrancy] = filename;
 			t->lineno[t->reentrancy] = lineno;
@@ -467,11 +518,17 @@ static inline int __ast_cond_timedwait(const char *filename, int lineno, const c
 		t->thread[t->reentrancy] = 0;
 	}
 
+	if (t->track)
+		ast_remove_lock_info(&t->mutex);
+
 	if ((res = pthread_cond_timedwait(cond, &t->mutex, abstime)) && (res != ETIMEDOUT)) {
 		__ast_mutex_logger("%s line %d (%s): Error waiting on condition mutex '%s'\n", 
 				   filename, lineno, func, strerror(res));
 		DO_THREAD_CRASH;
 	} else {
+		if (t->track)
+			ast_store_lock_info(filename, lineno, func, mutex_name, &t->mutex);
+
 		if (t->reentrancy < AST_MAX_REENTRANCY) {
 			t->file[t->reentrancy] = filename;
 			t->lineno[t->reentrancy] = lineno;
@@ -574,8 +631,8 @@ static inline int ast_cond_timedwait(ast_cond_t *cond, ast_mutex_t *t, const str
 #if defined(AST_MUTEX_INIT_W_CONSTRUCTORS)
 /* If AST_MUTEX_INIT_W_CONSTRUCTORS is defined, use file scope
  constructors/destructors to create/destroy mutexes.  */
-#define __AST_MUTEX_DEFINE(scope, mutex) \
-	scope ast_mutex_t mutex = AST_MUTEX_INIT_VALUE; \
+#define __AST_MUTEX_DEFINE(scope, mutex, init_val) \
+	scope ast_mutex_t mutex = init_val; \
 static void  __attribute__ ((constructor)) init_##mutex(void) \
 { \
 	ast_mutex_init(&mutex); \
@@ -586,8 +643,8 @@ static void  __attribute__ ((destructor)) fini_##mutex(void) \
 }
 #else /* !AST_MUTEX_INIT_W_CONSTRUCTORS */
 /* By default, use static initialization of mutexes. */ 
-#define __AST_MUTEX_DEFINE(scope, mutex) \
-	scope ast_mutex_t mutex = AST_MUTEX_INIT_VALUE
+#define __AST_MUTEX_DEFINE(scope, mutex, init_val) \
+	scope ast_mutex_t mutex = init_val
 #endif /* AST_MUTEX_INIT_W_CONSTRUCTORS */
 
 #define pthread_mutex_t use_ast_mutex_t_instead_of_pthread_mutex_t
@@ -604,7 +661,8 @@ static void  __attribute__ ((destructor)) fini_##mutex(void) \
 #define pthread_cond_wait use_ast_cond_wait_instead_of_pthread_cond_wait
 #define pthread_cond_timedwait use_ast_cond_timedwait_instead_of_pthread_cond_timedwait
 
-#define AST_MUTEX_DEFINE_STATIC(mutex) __AST_MUTEX_DEFINE(static, mutex)
+#define AST_MUTEX_DEFINE_STATIC(mutex) __AST_MUTEX_DEFINE(static, mutex, AST_MUTEX_INIT_VALUE)
+#define AST_MUTEX_DEFINE_STATIC_NOTRACKING(mutex) __AST_MUTEX_DEFINE(static, mutex, AST_MUTEX_INIT_VALUE_NOTRACKING)
 
 #define AST_MUTEX_INITIALIZER __use_AST_MUTEX_DEFINE_STATIC_rather_than_AST_MUTEX_INITIALIZER__
 
@@ -621,11 +679,11 @@ static inline int ast_rwlock_init(ast_rwlock_t *prwlock)
 	pthread_rwlockattr_t attr;
 
 	pthread_rwlockattr_init(&attr);
-	
+
 #ifdef HAVE_PTHREAD_RWLOCK_PREFER_WRITER_NP
 	pthread_rwlockattr_setkind_np(&attr, PTHREAD_RWLOCK_PREFER_WRITER_NP);
 #endif
-	
+
 	return pthread_rwlock_init(prwlock, &attr);
 }
 
diff --git a/main/astmm.c b/main/astmm.c
index 948d26e6a..b29502542 100644
--- a/main/astmm.c
+++ b/main/astmm.c
@@ -81,7 +81,7 @@ static struct ast_region {
 #define HASH(a) \
 	(((unsigned long)(a)) % SOME_PRIME)
 	
-AST_MUTEX_DEFINE_STATIC(reglock);
+AST_MUTEX_DEFINE_STATIC_NOTRACKING(reglock);
 AST_MUTEX_DEFINE_STATIC(showmemorylock);
 
 #define astmm_log(...)                               \
diff --git a/main/utils.c b/main/utils.c
index 9a54622a9..8b2b86694 100644
--- a/main/utils.c
+++ b/main/utils.c
@@ -46,6 +46,8 @@ ASTERISK_FILE_VERSION(__FILE__, "$Revision$")
 #include "asterisk/md5.h"
 #include "asterisk/sha1.h"
 #include "asterisk/options.h"
+#include "asterisk/cli.h"
+#include "asterisk/linkedlists.h"
 
 #define AST_API_MODULE		/* ensure that inlinable API functions will be built in this module if required */
 #include "asterisk/strings.h"
@@ -500,17 +502,228 @@ const char *ast_inet_ntoa(struct in_addr ia)
 	return inet_ntop(AF_INET, &ia, buf, INET_ADDRSTRLEN);
 }
 
-int ast_utils_init(void)
-{
-	base64_init();
-	return 0;
-}
-
 #ifndef __linux__
 #undef pthread_create /* For ast_pthread_create function only */
 #endif /* !__linux__ */
 
 #if !defined(LOW_MEMORY)
+
+#ifdef DEBUG_THREADS
+
+/*! \brief A reasonable maximum number of locks a thread would be holding ... */
+#define AST_MAX_LOCKS 16
+
+/* Allow direct use of pthread_mutex_t and friends */
+#undef pthread_mutex_t
+#undef pthread_mutex_lock
+#undef pthread_mutex_unlock
+#undef pthread_mutex_init
+#undef pthread_mutex_destroy
+
+/*! 
+ * \brief Keep track of which locks a thread holds 
+ *
+ * There is an instance of this struct for every active thread
+ */
+struct thr_lock_info {
+	/*! The thread's ID */
+	pthread_t thread_id;
+	/*! The thread name which includes where the thread was started */
+	const char *thread_name;
+	/*! This is the actual container of info for what locks this thread holds */
+	struct {
+		const char *file;
+		int line_num;
+		const char *func;
+		const char *lock_name;
+		void *lock_addr;
+		int times_locked;
+		/*! This thread is waiting on this lock */
+		unsigned int pending:1;
+	} locks[AST_MAX_LOCKS];
+	/*! This is the number of locks currently held by this thread.
+	 *  The index (num_locks - 1) has the info on the last one in the
+	 *  locks member */
+	unsigned int num_locks;
+	/*! Protects the contents of the locks member 
+	 * Intentionally not ast_mutex_t */
+	pthread_mutex_t lock;
+	AST_LIST_ENTRY(thr_lock_info) entry;
+};
+
+/*! 
+ * \brief Locked when accessing the lock_infos list 
+ */
+AST_MUTEX_DEFINE_STATIC(lock_infos_lock);
+/*!
+ * \brief A list of each thread's lock info 
+ */
+static AST_LIST_HEAD_NOLOCK_STATIC(lock_infos, thr_lock_info);
+
+/*!
+ * \brief Destroy a thread's lock info
+ *
+ * This gets called automatically when the thread stops
+ */
+static void lock_info_destroy(void *data)
+{
+	struct thr_lock_info *lock_info = data;
+
+	pthread_mutex_lock(&lock_infos_lock.mutex);
+	AST_LIST_REMOVE(&lock_infos, lock_info, entry);
+	pthread_mutex_unlock(&lock_infos_lock.mutex);
+
+	pthread_mutex_destroy(&lock_info->lock);
+	free((void *) lock_info->thread_name);
+	free(lock_info);
+}
+
+/*!
+ * \brief The thread storage key for per-thread lock info
+ */
+AST_THREADSTORAGE_CUSTOM(thread_lock_info, thread_lock_info_init, lock_info_destroy);
+
+void ast_store_lock_info(const char *filename, int line_num, 
+	const char *func, const char *lock_name, void *lock_addr)
+{
+	struct thr_lock_info *lock_info;
+	int i;
+
+	if (!(lock_info = ast_threadstorage_get(&thread_lock_info, sizeof(*lock_info))))
+		return;
+
+	pthread_mutex_lock(&lock_info->lock);
+
+	for (i = 0; i < lock_info->num_locks; i++) {
+		if (lock_info->locks[i].lock_addr == lock_addr) {
+			lock_info->locks[i].times_locked++;
+			pthread_mutex_unlock(&lock_info->lock);
+			return;
+		}
+	}
+
+	if (lock_info->num_locks == AST_MAX_LOCKS) {
+		/* Can't use ast_log here, because it will cause infinite recursion */
+		fprintf(stderr, "XXX ERROR XXX A thread holds more locks than '%d'."
+			"  Increase AST_MAX_LOCKS!\n", AST_MAX_LOCKS);
+		pthread_mutex_unlock(&lock_info->lock);
+		return;
+	}
+	
+	lock_info->locks[i].file = filename;
+	lock_info->locks[i].line_num = line_num;
+	lock_info->locks[i].func = func;
+	lock_info->locks[i].lock_name = lock_name;
+	lock_info->locks[i].lock_addr = lock_addr;
+	lock_info->locks[i].times_locked = 1;
+	lock_info->locks[i].pending = 1;
+	lock_info->num_locks++;
+
+	pthread_mutex_unlock(&lock_info->lock);
+}
+
+void ast_mark_lock_acquired(void)
+{
+	struct thr_lock_info *lock_info;
+
+	if (!(lock_info = ast_threadstorage_get(&thread_lock_info, sizeof(*lock_info))))
+		return;
+
+	pthread_mutex_lock(&lock_info->lock);
+	lock_info->locks[lock_info->num_locks - 1].pending = 0;
+	pthread_mutex_unlock(&lock_info->lock);
+}
+
+void ast_remove_lock_info(void *lock_addr)
+{
+	struct thr_lock_info *lock_info;
+	int i = 0;
+
+	if (!(lock_info = ast_threadstorage_get(&thread_lock_info, sizeof(*lock_info))))
+		return;
+
+	pthread_mutex_lock(&lock_info->lock);
+
+	for (i = lock_info->num_locks - 1; i >= 0; i--) {
+		if (lock_info->locks[i].lock_addr == lock_addr)
+			break;
+	}
+
+	if (i == -1) {
+		/* Lock not found :( */
+		pthread_mutex_unlock(&lock_info->lock);
+		return;
+	}
+
+	if (lock_info->locks[i].times_locked > 1) {
+		lock_info->locks[i].times_locked--;
+		pthread_mutex_unlock(&lock_info->lock);
+		return;
+	}
+
+	if (i < lock_info->num_locks - 1) {
+		/* Not the last one ... *should* be rare! */
+		memmove(&lock_info->locks[i], &lock_info->locks[i + 1], 
+			(lock_info->num_locks - (i + 1)) * sizeof(lock_info->locks[0]));
+	}
+
+	lock_info->num_locks--;
+
+	pthread_mutex_unlock(&lock_info->lock);
+}
+
+static int handle_show_locks(int fd, int argc, char *argv[])
+{
+	struct thr_lock_info *lock_info;
+
+	ast_cli(fd, "\n" 
+	            "=======================================================================\n"
+	            "=== Currently Held Locks ==============================================\n"
+	            "=======================================================================\n"
+	            "===\n"
+				"=== <file> <line num> <function> <lock name> <lock addr> (times locked)\n"
+				"===\n");
+
+	pthread_mutex_lock(&lock_infos_lock.mutex);
+	AST_LIST_TRAVERSE(&lock_infos, lock_info, entry) {
+		int i;
+		ast_cli(fd, "=== Thread ID: %d (%s)\n", (int) lock_info->thread_id,
+			lock_info->thread_name);
+		pthread_mutex_lock(&lock_info->lock);
+		for (i = 0; i < lock_info->num_locks; i++) {
+			ast_cli(fd, "=== ---> %sLock #%d: %s %d %s %s %p (%d)\n", 
+				lock_info->locks[i].pending ? "Waiting for " : "", i,
+				lock_info->locks[i].file, lock_info->locks[i].line_num,
+				lock_info->locks[i].func, lock_info->locks[i].lock_name,
+				lock_info->locks[i].lock_addr, 
+				lock_info->locks[i].times_locked);
+		}
+		pthread_mutex_unlock(&lock_info->lock);
+		ast_cli(fd, "=== -------------------------------------------------------------------\n"
+		            "===\n");
+	}
+	pthread_mutex_unlock(&lock_infos_lock.mutex);
+
+	ast_cli(fd, "=======================================================================\n"
+	            "\n");
+
+	return 0;
+}
+
+static char show_locks_help[] =
+"Usage: core show locks\n"
+"       This command is for lock debugging.  It prints out which locks\n"
+"are owned by each active thread.\n";
+
+static struct ast_cli_entry utils_cli[] = {
+	{ { "core", "show", "locks", NULL }, handle_show_locks,
+	  "Show which locks are locked by which thread", show_locks_help },
+};
+
+#endif /* DEBUG_THREADS */
+
+
+
 /*
  * support for 'show threads'. The start routine is wrapped by
  * dummy_start(), so that ast_register_thread() and
@@ -533,6 +746,9 @@ static void *dummy_start(void *data)
 {
 	void *ret;
 	struct thr_arg a = *((struct thr_arg *) data);	/* make a local copy */
+#ifdef DEBUG_THREADS
+	struct thr_lock_info *lock_info;
+#endif
 
 	/* note that even though data->name is a pointer to allocated memory,
 	   we are not freeing it here because ast_register_thread is going to
@@ -542,7 +758,22 @@ static void *dummy_start(void *data)
 	free(data);
 	ast_register_thread(a.name);
 	pthread_cleanup_push(ast_unregister_thread, (void *) pthread_self());
+
+#ifdef DEBUG_THREADS
+	if (!(lock_info = ast_threadstorage_get(&thread_lock_info, sizeof(*lock_info))))
+		return NULL;
+
+	lock_info->thread_id = pthread_self();
+	lock_info->thread_name = strdup(a.name);
+	pthread_mutex_init(&lock_info->lock, NULL);
+
+	pthread_mutex_lock(&lock_infos_lock.mutex); /* Intentionally not the wrapper */
+	AST_LIST_INSERT_TAIL(&lock_infos, lock_info, entry);
+	pthread_mutex_unlock(&lock_infos_lock.mutex); /* Intentionally not the wrapper */
+#endif /* DEBUG_THREADS */
+
 	ret = a.start_routine(a.data);
+
 	pthread_cleanup_pop(1);
 
 	return ret;
@@ -1011,3 +1242,14 @@ void ast_enable_packet_fragmentation(int sock)
 		ast_log(LOG_WARNING, "Unable to disable PMTU discovery. Large UDP packets may fail to be delivered when sent from this socket.\n");
 #endif /* HAVE_IP_MTU_DISCOVER */
 }
+
+int ast_utils_init(void)
+{
+	base64_init();
+#ifdef DEBUG_THREADS
+	ast_cli_register_multiple(utils_cli, sizeof(utils_cli) / sizeof(utils_cli[0]));
+#endif
+	return 0;
+}
+
+