Added backtrace functions for debugging

5 files changed, 224 insertions, 85 deletions

diff --git a/CONTRIBUTORS b/CONTRIBUTORS
index a3d593f3..6e228afe 100644
--- a/CONTRIBUTORS
+++ b/CONTRIBUTORS
@@ -3429,6 +3429,8 @@ Jasmin Jessich <jasmin@anw.at>
  for help and suggestions when implementing debug output for checking the correct
  sequence of locking global lists
  for suggesting to use $(Q) to control Makefile verbosity
+ for adding handling DEBUG to the Make.config.template file, in order to control
+ code optimization
 
 Martin Schirrmacher <schirrmie@gmail.com>
  for suggesting to provide a way for skin plugins to get informed about the currently
diff --git a/HISTORY b/HISTORY
index 5b4c1a9d..95098012 100644
--- a/HISTORY
+++ b/HISTORY
@@ -9058,11 +9058,21 @@ Video Disk Recorder Revision History
 
 2017-05-31: Version 2.3.6
 
-- Added debug output for checking the correct sequence of locking global lists
-  (with help and suggestions from Jasmin Jessich). To activate this, define the
-  macro DEBUG_LOCKSEQ in thread.c. At the first occurrence of an invalid locking
-  sequence, the 20 most recent locks will be printed to stderr, followed by a
-  backtrace that led to the call in question.
+- Added backtrace functions for debugging (see cBackTrace in thread.h).
+- Added checking the correct sequence of locking global lists (with help and
+  suggestions from Jasmin Jessich). At the first occurrence of an invalid locking
+  sequence, the 20 most recent locks will be written to the log file, followed by a
+  backtrace that led to the call in question. This code can be activated by defining
+  the macro DEBUG_LOCKSEQ in thread.c (which is on by default).
+  When debugging an actual invalid locking sequence, you can additionally define
+  the macro DEBUG_LOCKCALL in thread.c, which will add information about the caller
+  of each lock. Note that this may cause some stress on the CPU, therefore it is off
+  by default.
+- The file Make.config.template now reacts on DEBUG=1 in the 'make' command line,
+  and disables code optimizations by setting -O0 (thanks to Jasmin Jessich).
+  This can be helpful when backtracing highly optimized code. You may want to
+  'make distclean' before running 'make' with a modified setting of DEBUG, to make
+  sure all object files are newly compiled.
 - Fixed the locking sequence when dumping EPG data.
 - Fixed the locking sequence when starting a recording.
 - The Makefiles now use the macro $(Q) instead of a plain '@' in front of their
diff --git a/Make.config.template b/Make.config.template
index 8768f3b9..82d55617 100644
--- a/Make.config.template
+++ b/Make.config.template
@@ -6,7 +6,7 @@
 # See the main source file 'vdr.c' for copyright information and
 # how to reach the author.
 #
-# $Id: Make.config.template 3.4 2015/02/09 09:58:45 kls Exp $
+# $Id: Make.config.template 4.1 2017/06/02 09:29:54 kls Exp $
 
 ### The C compiler and options:
 
@@ -16,6 +16,12 @@ CFLAGS   = -g -O3 -Wall
 CXX      = g++
 CXXFLAGS = -g -O3 -Wall -Werror=overloaded-virtual -Wno-parentheses
 
+# Use 'make DEBUG=1 ...' to build a debug version of VDR and plugins:
+ifdef DEBUG
+CFLAGS   += -O0
+CXXFLAGS += -O0
+endif
+
 # Use 'make M32=1 ...' to build a 32-bit version of VDR on a 64-bit machine:
 ifdef M32
 CFLAGS   += -m32
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 <cxxabi.h>
+#include <dlfcn.h>
 #include <errno.h>
+#include <execinfo.h>
 #include <linux/unistd.h>
 #include <malloc.h>
 #include <stdarg.h>
 #include <stdlib.h>
+#include <sys/prctl.h>
 #include <sys/resource.h>
 #include <sys/syscall.h>
 #include <sys/time.h>
 #include <sys/wait.h>
-#include <sys/prctl.h>
 #include <unistd.h>
 #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 <cxxabi.h>
-#include <execinfo.h>
-static cVector<tThreadId> StateLockThreadIds;
-static cVector<int> 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<void*>(addr), &dlinfo)) {
+           if ((strcmp(Module, dlinfo.dli_fname) == 0) && dlinfo.dli_fbase) {
+              unsigned long long base = reinterpret_cast<unsigned long long>(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<tThreadId> threadIds;
+  cVector<int> 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)
 {
diff --git a/thread.h b/thread.h
index 9df677d3..fe8535b7 100644
--- a/thread.h
+++ b/thread.h
@@ -4,7 +4,7 @@
  * See the main source file 'vdr.c' for copyright information and
  * how to reach the author.
  *
- * $Id: thread.h 4.2 2016/12/08 10:18:32 kls Exp $
+ * $Id: thread.h 4.3 2017/06/03 12:43:22 kls Exp $
  */
 
 #ifndef __THREAD_H
@@ -291,6 +291,37 @@ public:
   int Close(void);
   };
 
+// cBackTrace can be used for debugging.
+
+class cStringList;
+class cString;
+
+class cBackTrace {
+public:
+  static cString Demangle(char *s);
+         ///< Demangles the function name in the given string and returns the converted
+         ///< version of s. s must be one of the strings returned by a call to
+         ///< BackTrace() or GetCaller().
+         ///< Note that this function works on the given string by inserting '\0'
+         ///< characters to separate the individual parts. Therefore the string
+         ///< will be modified upon return.
+  static void BackTrace(cStringList &StringList, int Level = 0, bool Mangled = false);
+         ///< Produces a backtrace and stores it in the given StringList.
+         ///< If Level is given, only calls up to the given value are listed.
+         ///< If Mangled is true, the raw backtrace will be returned and you can use
+         ///< Demangle() to make the function names readable.
+  static void BackTrace(FILE *f = NULL, int Level = 0, bool Mangled = false);
+         ///< Produces a backtrace beginning at the given Level, and
+         ///< writes it to the given file. If no file is given, the backtrace is
+         ///< written to the logfile. If Mangled is true, the raw backtrace will
+         ///< be printed/logged.
+  static cString GetCaller(int Level = 0, bool Mangled = false);
+         ///< Returns the caller at the given Level (or the immediate caller,
+         ///< if Level is 0).
+         ///< If Mangled is true, the raw backtrace will be returned and you can use
+         ///< Demangle() to make the function name readable.
+  };
+
 // SystemExec() implements a 'system()' call that closes all unnecessary file
 // descriptors in the child process.
 // With Detached=true, calls command in background and in a separate session,