Added debug output for checking the correct sequence of locking global lists

1 files changed, 168 insertions, 7 deletions

diff --git a/thread.c b/thread.c
index 2f57f815..32ce7c3f 100644
--- a/thread.c
+++ b/thread.c
@@ -4,7 +4,7 @@
  * See the main source file 'vdr.c' for copyright information and
  * how to reach the author.
  *
- * $Id: thread.c 4.2 2016/12/08 10:18:32 kls Exp $
+ * $Id: thread.c 4.3 2017/05/28 12:41:03 kls Exp $
  */
 
 #include "thread.h"
@@ -24,6 +24,7 @@
 #define ABORT { dsyslog("ABORT!"); abort(); } // use debugger to trace back the problem
 
 //#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
 
 #ifdef DEBUG_LOCKING
 #define dbglocking(a...) fprintf(stderr, a)
@@ -431,6 +432,163 @@ bool cThreadLock::Lock(cThread *Thread)
 
 // --- cStateLock ------------------------------------------------------------
 
+#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)
+{
+  char *Module = s;
+  char *Function = NULL;
+  //char *Offset = NULL;
+  char *Address = NULL;
+  // separate the string:
+  for (char *q = Module; *q; q++) {
+      if (*q == '(') {
+         *q = 0;
+         Function = q + 1;
+         }
+      else if (*q == '+') {
+         *q = 0;
+         //Offset = q + 1;
+         }
+      else if (*q == ')')
+         *q = 0;
+      else if (*q == '[')
+         Address = q + 1;
+      else if (*q == ']') {
+         *q = 0;
+         break;
+         }
+      }
+  // 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);
+  // determine the file name and line number:
+  cString cmd = cString::sprintf("addr2line --exe=%s --functions --demangle --basename %s", Module, Address);
+  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))
+                 d = cString::sprintf("%s calling %s", *d, l);
+              }
+           else
+              d = cString::sprintf("%s at %s", *d, l);
+           n++;
+           }
+     p.Close();
+     }
+  free(r);
+  return d;
+}
+
+static void BackTrace(void)
+{
+  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]));
+     free(s);
+     }
+}
+
+static void BackTraceCaller(int Level, char *t, int l)
+{
+  void *b[BT_BUF_SIZE];
+  int n = backtrace(b, BT_BUF_SIZE);
+  if (char **s = backtrace_symbols(b, n)) {
+     strn0cpy(t, s[Level], l);
+     free(s);
+     }
+}
+
+static void DumpStateLockLog(tThreadId ThreadId, const char *Name)
+{
+  if (!DumpStateLocks)
+     return;
+  DumpStateLocks = false;
+  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 (++StateLockLogIndex >= SLL_SIZE)
+         StateLockLogIndex = 0;
+      }
+  fprintf(stderr, "%5d invalid lock sequence: %-12s\n", ThreadId, Name);
+  fprintf(stderr, "full backtrace:\n");
+  BackTrace();
+}
+
+static void CheckStateLockLevel(const char *Name, bool Lock, bool Write = false)
+{
+  if (Name) {
+     int n = *Name - '0';
+     if (1 <= n && n <= 9) {
+        int b = 1 << (n - 1);
+        cMutexLock MutexLock(&StateLockMutex);
+        tThreadId ThreadId = cThread::ThreadId();
+        int Index = StateLockThreadIds.IndexOf(ThreadId);
+        if (Index < 0) {
+           if (Lock) {
+              Index = StateLockThreadIds.Size();
+              StateLockThreadIds.Append(ThreadId);
+              StateLockFlags.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;
+        if (Lock) {
+           if ((StateLockFlags[Index] & ~b) < b)
+              StateLockFlags[Index] |= b;
+           else if ((StateLockFlags[Index] & b) == 0)
+              DumpStateLockLog(ThreadId, Name);
+           }
+        else
+           StateLockFlags[Index] &= ~b;
+        }
+     }
+}
+#define dbglockseq(n, l, w) CheckStateLockLevel(n, l, w)
+#else
+#define dbglockseq(n, l, w)
+#endif // DEBUG_LOCKSEQ
+
 cStateLock::cStateLock(const char *Name)
 :rwLock(true)
 {
@@ -442,7 +600,7 @@ cStateLock::cStateLock(const char *Name)
 
 bool cStateLock::Lock(cStateKey &StateKey, bool Write, int TimeoutMs)
 {
-  dbglocking("%5d %-10s %10p   lock state = %d/%d write = %d timeout = %d\n", cThread::ThreadId(), name, &StateKey, state, StateKey.state, Write, TimeoutMs);
+  dbglocking("%5d %-12s %10p   lock state = %d/%d write = %d timeout = %d\n", cThread::ThreadId(), name, &StateKey, state, StateKey.state, Write, TimeoutMs);
   StateKey.timedOut = false;
   if (StateKey.stateLock) {
      esyslog("ERROR: StateKey already in use in call to cStateLock::Lock() (tid=%d, lock=%s)", StateKey.stateLock->threadId, name);
@@ -450,25 +608,27 @@ bool cStateLock::Lock(cStateKey &StateKey, bool Write, int TimeoutMs)
      return false;
      }
   if (rwLock.Lock(Write, TimeoutMs)) {
+     dbglockseq(name, true, Write);
      StateKey.stateLock = this;
      if (Write) {
-        dbglocking("%5d %-10s %10p   locked write\n", cThread::ThreadId(), name, &StateKey);
+        dbglocking("%5d %-12s %10p   locked write\n", cThread::ThreadId(), name, &StateKey);
         threadId = cThread::ThreadId();
         StateKey.write = true;
         return true;
         }
      else if (state != StateKey.state) {
-        dbglocking("%5d %-10s %10p   locked read\n", cThread::ThreadId(), name, &StateKey);
+        dbglocking("%5d %-12s %10p   locked read\n", cThread::ThreadId(), name, &StateKey);
         return true;
         }
      else {
-        dbglocking("%5d %-10s %10p   state unchanged\n", cThread::ThreadId(), name, &StateKey);
+        dbglocking("%5d %-12s %10p   state unchanged\n", cThread::ThreadId(), name, &StateKey);
         StateKey.stateLock = NULL;
+        dbglockseq(name, false, false);
         rwLock.Unlock();
         }
      }
   else if (TimeoutMs) {
-     dbglocking("%5d %-10s %10p   timeout\n", cThread::ThreadId(), name, &StateKey);
+     dbglocking("%5d %-12s %10p   timeout\n", cThread::ThreadId(), name, &StateKey);
      StateKey.timedOut = true;
      }
   return false;
@@ -476,7 +636,7 @@ bool cStateLock::Lock(cStateKey &StateKey, bool Write, int TimeoutMs)
 
 void cStateLock::Unlock(cStateKey &StateKey, bool IncState)
 {
-  dbglocking("%5d %-10s %10p unlock state = %d/%d inc = %d\n", cThread::ThreadId(), name, &StateKey, state, StateKey.state, IncState);
+  dbglocking("%5d %-12s %10p unlock state = %d/%d inc = %d\n", cThread::ThreadId(), name, &StateKey, state, StateKey.state, IncState);
   if (StateKey.stateLock != this) {
      esyslog("ERROR: cStateLock::Unlock() called with an unused key (tid=%d, lock=%s)", threadId, name);
      ABORT;
@@ -495,6 +655,7 @@ void cStateLock::Unlock(cStateKey &StateKey, bool IncState)
      threadId = 0;
      explicitModify = false;
      }
+  dbglockseq(name, false, false);
   rwLock.Unlock();
 }