With this patch, there is new ./configure option '--enable-lock-debug' which controls whether we want to turn on debugging locks. This feature is exposed as a ./configure option due to its huge overhead in speed/log size and is only meant to be used with this in mind. It is designed in a way that even log from deadlocked daemon should provide enough info to find the deadlock itself. Every matching Lock() call can be matched with its Unlock() call and with every Lock() called it is visible whether it failed or not. Unlock() call follows the same output, even though unnecessary (the call cannot block). Lock logging is disabled while logging because that would either recurse or deadlock. Signed-off-by: Martin Kletzander <mkletzan(a)redhat.com&gt; --- configure.ac | 19 +++++++++++++++ src/Makefile.am | 3 ++- src/libvirt_private.syms | 1 + src/util/virlog.c | 8 +++++++ src/util/virthread.h | 4 ++++ src/util/virthreadpthread.c | 58 ++++++++++++++++++++++++++++++++++++++++++++- src/util/virutil.c | 40 +++++++++++++++++++++++++++++++ src/util/virutil.h | 2 ++ 8 files changed, 133 insertions(+), 2 deletions(-) diff --git a/configure.ac b/configure.ac index b5af0d3..c63ffe7 100644 --- a/configure.ac +++ b/configure.ac @@ -478,6 +478,24 @@ if test x"$enable_debug" = x"yes"; then AC_DEFINE([ENABLE_DEBUG], [], [whether debugging is enabled]) fi +dnl --enable-lock-debug=(yes|no) +AC_ARG_ENABLE([lock-debug], + [AC_HELP_STRING([--enable-lock-debug=@<:@no|yes@:>@], + [enable lock debugging (beware of huge overhead) @<:@default=no@:>@])], + [],[enable_lock_debug=no]) +AM_CONDITIONAL([ENABLE_LOCK_DEBUG], test x"$enable_lock_debug" = x"yes") +if test x"$enable_lock_debug" = x"yes"; then + if test "$ac_cv_header_pthread_h" != "yes" ; then + AC_MSG_ERROR([POSIX threads are needed to properly debug locking]) + fi + if test x"$enable_debug" != x"yes" ; then + AC_MSG_ERROR([Cannot debug locking without enabling debugging itself]) + fi + + AC_DEFINE([ENABLE_LOCK_DEBUG], [], [whether lock debugging is enabled]) + LOCK_DEBUG_LDFLAGS="-rdynamic" +fi +AC_SUBST([LOCK_DEBUG_LDFLAGS]) dnl @@ -2601,6 +2619,7 @@ AC_MSG_NOTICE([]) AC_MSG_NOTICE([Miscellaneous]) AC_MSG_NOTICE([]) AC_MSG_NOTICE([ Debug: $enable_debug]) +AC_MSG_NOTICE([ Lock debug: $enable_lock_debug]) AC_MSG_NOTICE([ Use -Werror: $set_werror]) AC_MSG_NOTICE([ Warning Flags: $WARN_CFLAGS]) AC_MSG_NOTICE([ Readline: $lv_use_readline]) diff --git a/src/Makefile.am b/src/Makefile.am index 8fa8680..ef6aaa3 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -33,7 +33,8 @@ AM_CFLAGS = $(LIBXML_CFLAGS) \ $(WIN32_EXTRA_CFLAGS) \ $(COVERAGE_CFLAGS) AM_LDFLAGS = $(DRIVER_MODULE_LDFLAGS) \ - $(COVERAGE_LDFLAGS) + $(COVERAGE_LDFLAGS) \ + $(LOCK_DEBUG_LDFLAGS) EXTRA_DIST = $(conf_DATA) util/keymaps.csv diff --git a/src/libvirt_private.syms b/src/libvirt_private.syms index 7790ede..44b4a60 100644 --- a/src/libvirt_private.syms +++ b/src/libvirt_private.syms @@ -2022,6 +2022,7 @@ virGetGroupID; virGetGroupList; virGetGroupName; virGetHostname; +virGetLockFunc; virGetUnprivSGIOSysfsPath; virGetUserCacheDirectory; virGetUserConfigDirectory; diff --git a/src/util/virlog.c b/src/util/virlog.c index d1fb0b3..8d1e943 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -150,14 +150,22 @@ virMutex virLogMutex; void virLogLock(void) { +#ifdef ENABLE_LOCK_DEBUG + virMutexLockNoLog(&virLogMutex); +#else virMutexLock(&virLogMutex); +#endif } void virLogUnlock(void) { +#ifdef ENABLE_LOCK_DEBUG + virMutexUnlockNoLog(&virLogMutex); +#else virMutexUnlock(&virLogMutex); +#endif } diff --git a/src/util/virthread.h b/src/util/virthread.h index 84d3bdc..6d86227 100644 --- a/src/util/virthread.h +++ b/src/util/virthread.h @@ -88,6 +88,10 @@ void virMutexDestroy(virMutexPtr m); void virMutexLock(virMutexPtr m); void virMutexUnlock(virMutexPtr m); +# ifdef ENABLE_LOCK_DEBUG +void virMutexLockNoLog(virMutexPtr m); +void virMutexUnlockNoLog(virMutexPtr m); +# endif int virCondInit(virCondPtr c) ATTRIBUTE_RETURN_CHECK; diff --git a/src/util/virthreadpthread.c b/src/util/virthreadpthread.c index ca841e4..95e20b5 100644 --- a/src/util/virthreadpthread.c +++ b/src/util/virthreadpthread.c @@ -29,6 +29,11 @@ #include "viralloc.h" +#ifdef ENABLE_LOCK_DEBUG +# include "virutil.h" +# include "virlog.h" +#endif + /* Nothing special required for pthreads */ int virThreadInitialize(void) @@ -81,7 +86,57 @@ void virMutexDestroy(virMutexPtr m) pthread_mutex_destroy(&m->lock); } -void virMutexLock(virMutexPtr m){ +#ifdef ENABLE_LOCK_DEBUG + +# define PRE_LOCK_PROC(mutex) \ + char *frame = virGetLockFrame(); \ + do { \ + if (frame) \ + VIR_DEBUG("lock=%p, frame=%s, state=request", \ + &mutex->lock, NULLSTR(frame)); \ + else \ + VIR_DEBUG("lock=%p, state=request", &mutex->lock); \ + } while (0) + +# define POST_LOCK_PROC(mutex) \ + do { \ + if (frame) { \ + VIR_DEBUG("lock=%p, frame=%s, state=done", \ + &mutex->lock, NULLSTR(frame)); \ + VIR_FREE(frame); \ + } else { \ + VIR_DEBUG("lock=%p, state=done", &mutex->lock); \ + } \ + } while (0) + +void virMutexLock(virMutexPtr m) +{ + PRE_LOCK_PROC(m); + virMutexLockNoLog(m); + POST_LOCK_PROC(m); +} + +void virMutexUnlock(virMutexPtr m) +{ + PRE_LOCK_PROC(m); + virMutexUnlockNoLog(m); + POST_LOCK_PROC(m); +} + +void virMutexLockNoLog(virMutexPtr m) +{ + pthread_mutex_lock(&m->lock); +} + +void virMutexUnlockNoLog(virMutexPtr m) +{ + pthread_mutex_unlock(&m->lock); +} + +#else /* ENABLE_LOCK_DEBUG */ + +void virMutexLock(virMutexPtr m) +{ pthread_mutex_lock(&m->lock); } @@ -90,6 +145,7 @@ void virMutexUnlock(virMutexPtr m) pthread_mutex_unlock(&m->lock); } +#endif /* ENABLE_LOCK_DEBUG */ int virCondInit(virCondPtr c) { diff --git a/src/util/virutil.c b/src/util/virutil.c index 0b54ef7..88b7984 100644 --- a/src/util/virutil.c +++ b/src/util/virutil.c @@ -40,6 +40,7 @@ #include <string.h> #include <termios.h> #include <locale.h> +#include <execinfo.h> #if HAVE_LIBDEVMAPPER_H # include <libdevmapper.h> @@ -2017,3 +2018,42 @@ virCompareLimitUlong(unsigned long long a, unsigned long b) return -1; } + + +/** + * virGetLockFrame: + * + * This function returns possibly the most relevant frame information + * from where a lock function was called. This info is obtained from + * a backtrace while going through the functions and filtering those + * which end with 'Lock'. + * + * We don't want to log anything from this method, not even an OOM + * Error, in case of any problems, just cleanup and return NULL. + */ +char * +virGetLockFrame(void) +{ + char **fnames = NULL; + char *out = NULL; + int i = 0; + int nframes = 0; + void *frames[100] = {0}; + + if (!(nframes = backtrace(frames, ARRAY_CARDINALITY(frames))) || + !(fnames = backtrace_symbols(frames, nframes))) + goto cleanup; + + for (i = 0; i < nframes; i++) { + if (!strstr(fnames[i], "Lock") && + !strstr(fnames[i], "Unlock") && + !strstr(fnames[i], "(+")) { + ignore_value(VIR_STRDUP_QUIET(out, fnames[i])); + break; + } + } + + cleanup: + VIR_FREE(fnames); + return out; +} diff --git a/src/util/virutil.h b/src/util/virutil.h index 0083c88..e385ae6 100644 --- a/src/util/virutil.h +++ b/src/util/virutil.h @@ -169,4 +169,6 @@ char *virFindFCHostCapableVport(const char *sysfs_prefix); int virCompareLimitUlong(unsigned long long a, unsigned long b); +char *virGetLockFrame(void); + #endif /* __VIR_UTIL_H__ */ -- 1.8.3.2