From 2c74a31afed1a3552fb22b522039e67a3d40b188 Mon Sep 17 00:00:00 2001 From: Klaus Schmidinger Date: Sat, 3 Jun 2017 12:43:22 +0200 Subject: Added backtrace functions for debugging --- thread.c | 246 +++++++++++++++++++++++++++++++++++++++++++-------------------- 1 file changed, 168 insertions(+), 78 deletions(-) (limited to 'thread.c') diff --git a/thread.c b/thread.c index 32ce7c3f..345f2af4 100644 --- a/thread.c +++ b/thread.c @@ -4,27 +4,31 @@ * See the main source file 'vdr.c' for copyright information and * how to reach the author. * - * $Id: thread.c 4.3 2017/05/28 12:41:03 kls Exp $ + * $Id: thread.c 4.4 2017/06/03 12:43:22 kls Exp $ */ #include "thread.h" +#include +#include #include +#include #include #include #include #include +#include #include #include #include #include -#include #include #include "tools.h" -#define ABORT { dsyslog("ABORT!"); abort(); } // use debugger to trace back the problem +#define ABORT { dsyslog("ABORT!"); cBackTrace::BackTrace(); abort(); } -//#define DEBUG_LOCKING // uncomment this line to activate debug output for locking -//#define DEBUG_LOCKSEQ // uncomment this line to activate debug output for locking sequence +//#define DEBUG_LOCKING // uncomment this line to activate debug output for locking +#define DEBUG_LOCKSEQ // uncomment this line to activate debug output for invalid locking sequence +//#define DEBUG_LOCKCALL // uncomment this line to activate caller information with DEBUG_LOCKSEQ (WARNING: expensive operation, use only when actually debugging the locking sequence!) #ifdef DEBUG_LOCKING #define dbglocking(a...) fprintf(stderr, a) @@ -430,27 +434,15 @@ bool cThreadLock::Lock(cThread *Thread) return false; } -// --- cStateLock ------------------------------------------------------------ +// --- cBackTrace ------------------------------------------------------------ -#ifdef DEBUG_LOCKSEQ -#include -#include -static cVector StateLockThreadIds; -static cVector StateLockFlags; -static cMutex StateLockMutex; -#define SLL_SIZE 20 // the number of log entries -#define SLL_LENGTH 256 // the maximum length of log entries -#define SLL_DELIM '#' // delimiter for caller info -static char StateLockLog[SLL_SIZE][SLL_LENGTH] = { 0 }; -static int StateLockLogIndex = 0; -static bool DumpStateLocks = true; #define BT_BUF_SIZE 100 -static cString Demangle(char *s, char *Prefix = NULL) +cString cBackTrace::Demangle(char *s) { char *Module = s; char *Function = NULL; - //char *Offset = NULL; + char *Offset = NULL; char *Address = NULL; // separate the string: for (char *q = Module; *q; q++) { @@ -460,7 +452,7 @@ static cString Demangle(char *s, char *Prefix = NULL) } else if (*q == '+') { *q = 0; - //Offset = q + 1; + Offset = q + 1; } else if (*q == ')') *q = 0; @@ -472,20 +464,46 @@ static cString Demangle(char *s, char *Prefix = NULL) } } // demangle the function name: - int status; - char *r = abi::__cxa_demangle(Function, NULL, 0, &status); - if (r) - Function = r; - cString d = cString::sprintf("%s %s %s", Prefix ? Prefix : "", Module, Function); + char *DemangledFunction = NULL; + if (Function) { + int status; + DemangledFunction = abi::__cxa_demangle(Function, NULL, 0, &status); + if (DemangledFunction) + Function = DemangledFunction; + if (!*Function) + Function = NULL; + } + cString d = cString::sprintf("%s%s%s", Module, Function ? " " : "", Function ? Function : ""); + // convert string address to numbers: + unsigned long long addr = Address ? strtoull(Address, NULL, 0) : 0; + unsigned long long offs = Offset ? strtoull(Offset, NULL, 0) : 0; + // for shared libraries we need get the offset inside the library: + if (Function) { + // check whether the module name ends with ".so*": + char *e = Module; + char *p = NULL; + while (e = strstr(e, ".so")) + p = e++; + if (p && !strchr(p, '/')) { + Dl_info dlinfo; + if (dladdr(reinterpret_cast(addr), &dlinfo)) { + if ((strcmp(Module, dlinfo.dli_fname) == 0) && dlinfo.dli_fbase) { + unsigned long long base = reinterpret_cast(dlinfo.dli_fbase); + addr -= base; + addr &= 0x0FFFFFFFF; // to make it work on both 32 and 64 bit systems + } + } + } + } // determine the file name and line number: - cString cmd = cString::sprintf("addr2line --exe=%s --functions --demangle --basename %s", Module, Address); + cString cmd = cString::sprintf("addr2line --functions --demangle --inlines --basename --exe=%s 0x%llx", Module, Function ? addr : offs); cPipe p; if (p.Open(cmd, "r")) { int n = 0; cReadLine rl; while (char *l = rl.Read(p)) { if (n == 0) { - if (!isempty(Function) && strcmp(l, Function)) + if (Function && strcmp(l, Function)) d = cString::sprintf("%s calling %s", *d, l); } else @@ -494,101 +512,173 @@ static cString Demangle(char *s, char *Prefix = NULL) } p.Close(); } - free(r); + free(DemangledFunction); return d; } -static void BackTrace(void) +void cBackTrace::BackTrace(cStringList &StringList, int Level, bool Mangled) { void *b[BT_BUF_SIZE]; int n = backtrace(b, BT_BUF_SIZE); if (char **s = backtrace_symbols(b, n)) { - for (int i = 5; i < n; i++) - fprintf(stderr, "%s\n", *Demangle(s[i])); + for (int i = max(Level, 0) + 1; i < n; i++) // 1 is the call to this function itself + StringList.Append(strdup(Mangled ? s[i] : *Demangle(s[i]))); free(s); } } -static void BackTraceCaller(int Level, char *t, int l) +void cBackTrace::BackTrace(FILE *f, int Level, bool Mangled) { + cStringList sl; + BackTrace(sl, Level + 1, Mangled); // 1 is the call to this function itself + for (int i = 0; i < sl.Size(); i++) { + if (f) + fprintf(f, "%s\n", sl[i]); + else + dsyslog("%s", sl[i]); + } +} + +cString cBackTrace::GetCaller(int Level, bool Mangled) +{ + cString Caller; + Level = max(Level, 0) + 1; // 1 is the call to this function itself void *b[BT_BUF_SIZE]; int n = backtrace(b, BT_BUF_SIZE); if (char **s = backtrace_symbols(b, n)) { - strn0cpy(t, s[Level], l); + if (Level < n) + Caller = Mangled ? s[Level] : *Demangle(s[Level]); free(s); } + return Caller; } -static void DumpStateLockLog(tThreadId ThreadId, const char *Name) -{ - if (!DumpStateLocks) - return; - DumpStateLocks = false; +// --- cStateLockLog --------------------------------------------------------- + +#ifdef DEBUG_LOCKSEQ +#define SLL_SIZE 20 // the number of log entries +#define SLL_LENGTH 256 // the maximum length of log entries +#define SLL_MAX_LIST 9 // max. number of lists to log +#define SLL_WRITE_FLAG 0x80000000 + +class cStateLockLog { +private: + cMutex mutex; + cVector threadIds; + cVector flags; + tThreadId logThreadIds[SLL_SIZE]; + int logFlags[SLL_SIZE]; + char logCaller[SLL_SIZE][SLL_LENGTH]; + int logIndex; + bool dumped; + void Dump(const char *Name, tThreadId ThreadId); +public: + cStateLockLog(void); + void Check(const char *Name, bool Lock, bool Write = false); + }; + +cStateLockLog::cStateLockLog(void) +{ + memset(logThreadIds, 0, sizeof(logThreadIds)); + memset(logFlags, 0, sizeof(logFlags)); + memset(logCaller, 0, sizeof(logCaller)); + logIndex = 0; + dumped = false; +} + +void cStateLockLog::Dump(const char *Name, tThreadId ThreadId) +{ + dsyslog("--- begin invalid lock sequence report"); + int LastFlags = 0; for (int i = 0; i < SLL_SIZE; i++) { - char *s = StateLockLog[StateLockLogIndex]; - if (*s) { - if (char *Delim = strchr(s, SLL_DELIM)) { - *Delim = 0; - fprintf(stderr, "%s\n", *Demangle(Delim + 1, s)); + if (tThreadId tid = logThreadIds[logIndex]) { + char msg[SLL_LENGTH]; + char *q = msg; + q += sprintf(q, "%5d", tid); + int Flags = logFlags[logIndex]; + bool Write = Flags & SLL_WRITE_FLAG; + Flags &= ~SLL_WRITE_FLAG; + int Changed = LastFlags ^ Flags; + LastFlags = Flags; + bool Lock = (Flags & Changed) != 0; + for (int i = 0; i <= SLL_MAX_LIST; i++) { + char c = '-'; + int b = 1 << i; + if ((Flags & b) != 0) + c = '*'; + if ((Changed & b) != 0) + c = Lock ? Write ? 'W' : 'R' : '-'; + q += sprintf(q, " %c", c); + } + q += sprintf(q, " %c", Lock ? 'L' : 'U'); + if (*logCaller[logIndex]) { + *q++ = ' '; + strn0cpy(q, *cBackTrace::Demangle(logCaller[logIndex]), sizeof(msg) - (q - msg)); } + dsyslog("%s", msg); } - if (++StateLockLogIndex >= SLL_SIZE) - StateLockLogIndex = 0; + if (++logIndex >= SLL_SIZE) + logIndex = 0; } - fprintf(stderr, "%5d invalid lock sequence: %-12s\n", ThreadId, Name); - fprintf(stderr, "full backtrace:\n"); - BackTrace(); + dsyslog("%5d invalid lock sequence: %s", ThreadId, Name); + dsyslog("full backtrace:"); + cBackTrace::BackTrace(NULL, 2); + dsyslog("--- end invalid lock sequence report"); + fprintf(stderr, "invalid lock sequence at %s\n", *DayDateTime(time(NULL))); } -static void CheckStateLockLevel(const char *Name, bool Lock, bool Write = false) +void cStateLockLog::Check(const char *Name, bool Lock, bool Write) { - if (Name) { + if (!dumped && Name) { int n = *Name - '0'; - if (1 <= n && n <= 9) { + if (1 <= n && n <= SLL_MAX_LIST) { int b = 1 << (n - 1); - cMutexLock MutexLock(&StateLockMutex); + cMutexLock MutexLock(&mutex); tThreadId ThreadId = cThread::ThreadId(); - int Index = StateLockThreadIds.IndexOf(ThreadId); + int Index = threadIds.IndexOf(ThreadId); if (Index < 0) { if (Lock) { - Index = StateLockThreadIds.Size(); - StateLockThreadIds.Append(ThreadId); - StateLockFlags.Append(0); + Index = threadIds.Size(); + threadIds.Append(ThreadId); + flags.Append(0); } else return; } - char *p = StateLockLog[StateLockLogIndex]; - char *q = p; - q += sprintf(q, "%5d", ThreadId); - for (int i = 0; i <= 9; i++) { - char c = '-'; - if (StateLockFlags[Index] & (1 << i)) - c = '*'; - if (i == n - 1) - c = Lock ? Write ? 'W' : 'R' : '-'; - q += sprintf(q, " %c", c); - } - q += sprintf(q, " %c%c", Lock ? 'L' : 'U', SLL_DELIM); - BackTraceCaller(Lock ? 5 : 3, q, SLL_LENGTH - (q - p)); - if (++StateLockLogIndex >= SLL_SIZE) - StateLockLogIndex = 0; + bool DoDump = false; if (Lock) { - if ((StateLockFlags[Index] & ~b) < b) - StateLockFlags[Index] |= b; - else if ((StateLockFlags[Index] & b) == 0) - DumpStateLockLog(ThreadId, Name); + if ((flags[Index] & ~b) < b) // thread holds only "smaller" locks -> OK + ; + else if ((flags[Index] & b) == 0) // thread already holds "bigger" locks, so it may only re-lock one that it already has! + DoDump = true; + flags[Index] |= b; } else - StateLockFlags[Index] &= ~b; + flags[Index] &= ~b; + logThreadIds[logIndex] = ThreadId; + logFlags[logIndex] = flags[Index] | (Write ? SLL_WRITE_FLAG : 0); +#ifdef DEBUG_LOCKCALL + strn0cpy(logCaller[logIndex], cBackTrace::GetCaller(Lock ? 5 : 3, true), SLL_LENGTH); +#endif + if (++logIndex >= SLL_SIZE) + logIndex = 0; + if (DoDump) { + Dump(Name, ThreadId); + dumped = true; + } } } } -#define dbglockseq(n, l, w) CheckStateLockLevel(n, l, w) + +static cStateLockLog StateLockLog; + +#define dbglockseq(n, l, w) StateLockLog.Check(n, l, w) #else #define dbglockseq(n, l, w) #endif // DEBUG_LOCKSEQ +// --- cStateLock ------------------------------------------------------------ + cStateLock::cStateLock(const char *Name) :rwLock(true) { -- cgit v1.2.3