[asterisk-commits] russell: branch russell/debug_threads_trunk r77882 - in /team/russell/debug_t...
SVN commits to the Asterisk project
asterisk-commits at lists.digium.com
Wed Aug 1 15:46:29 CDT 2007
Author: russell
Date: Wed Aug 1 15:46:29 2007
New Revision: 77882
URL: http://svn.digium.com/view/asterisk?view=rev&rev=77882
Log:
Add the trunk version of this lock debugging code. 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.
Modified:
team/russell/debug_threads_trunk/include/asterisk/lock.h
team/russell/debug_threads_trunk/main/astmm.c
team/russell/debug_threads_trunk/main/utils.c
Modified: team/russell/debug_threads_trunk/include/asterisk/lock.h
URL: http://svn.digium.com/view/asterisk/team/russell/debug_threads_trunk/include/asterisk/lock.h?view=diff&rev=77882&r1=77881&r2=77882
==============================================================================
--- team/russell/debug_threads_trunk/include/asterisk/lock.h (original)
+++ team/russell/debug_threads_trunk/include/asterisk/lock.h Wed Aug 1 15:46:29 2007
@@ -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;
@@ -121,6 +125,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)
{
@@ -216,6 +244,9 @@
{
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)) {
@@ -261,6 +292,8 @@
#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 @@
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 @@
}
#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;
@@ -305,6 +345,8 @@
__ast_mutex_logger("%s line %d (%s): '%s' really deep reentrancy!\n",
filename, lineno, func, mutex_name);
}
+ } else if (t->track) {
+ ast_remove_lock_info(&t->mutex);
}
return res;
@@ -344,6 +386,9 @@
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 @@
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 @@
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 @@
#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 @@
}
#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 @@
#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__
Modified: team/russell/debug_threads_trunk/main/astmm.c
URL: http://svn.digium.com/view/asterisk/team/russell/debug_threads_trunk/main/astmm.c?view=diff&rev=77882&r1=77881&r2=77882
==============================================================================
--- team/russell/debug_threads_trunk/main/astmm.c (original)
+++ team/russell/debug_threads_trunk/main/astmm.c Wed Aug 1 15:46:29 2007
@@ -80,8 +80,10 @@
#define HASH(a) \
(((unsigned long)(a)) % SOME_PRIME)
-
-AST_MUTEX_DEFINE_STATIC(reglock);
+
+/*! Tracking this mutex will cause infinite recursion, as the mutex tracking
+ * code allocates memory */
+AST_MUTEX_DEFINE_STATIC_NOTRACKING(reglock);
AST_MUTEX_DEFINE_STATIC(showmemorylock);
#define astmm_log(...) \
Modified: team/russell/debug_threads_trunk/main/utils.c
URL: http://svn.digium.com/view/asterisk/team/russell/debug_threads_trunk/main/utils.c?view=diff&rev=77882&r1=77881&r2=77882
==============================================================================
--- team/russell/debug_threads_trunk/main/utils.c (original)
+++ team/russell/debug_threads_trunk/main/utils.c Wed Aug 1 15:46:29 2007
@@ -51,6 +51,8 @@
#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"
@@ -509,20 +511,233 @@
static int dev_urandom_fd;
#endif
-int ast_utils_init(void)
-{
-#ifdef HAVE_DEV_URANDOM
- dev_urandom_fd = open("/dev/urandom", O_RDONLY);
-#endif
- 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, NULL, 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 char *handle_show_locks(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
+{
+ struct thr_lock_info *lock_info;
+
+ switch (cmd) {
+ case CLI_INIT:
+ e->command = "core show locks";
+ e->usage =
+ "Usage: core show locks\n"
+ " This command is for lock debugging. It prints out which locks\n"
+ "are owned by each active thread.\n";
+ return NULL;
+
+ case CLI_GENERATE:
+ return NULL;
+ }
+
+ ast_cli(a->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(a->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(a->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(a->fd, "=== -------------------------------------------------------------------\n"
+ "===\n");
+ }
+ pthread_mutex_unlock(&lock_infos_lock.mutex);
+
+ ast_cli(a->fd, "=======================================================================\n"
+ "\n");
+
+ return 0;
+}
+
+static struct ast_cli_entry utils_cli[] = {
+ NEW_CLI(handle_show_locks, "Show which locks are held by which thread"),
+};
+
+#endif /* DEBUG_THREADS */
+
/*
* support for 'show threads'. The start routine is wrapped by
* dummy_start(), so that ast_register_thread() and
@@ -545,6 +760,9 @@
{
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
@@ -554,7 +772,22 @@
ast_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;
@@ -1144,3 +1377,14 @@
return 0;
}
+int ast_utils_init(void)
+{
+#ifdef HAVE_DEV_URANDOM
+ dev_urandom_fd = open("/dev/urandom", O_RDONLY);
+#endif
+ base64_init();
+#ifdef DEBUG_THREADS
+ ast_cli_register_multiple(utils_cli, sizeof(utils_cli) / sizeof(utils_cli[0]));
+#endif
+ return 0;
+}
More information about the asterisk-commits
mailing list