better thread debugging

panda/src/pipeline/conditionVarDebug.cxx

@@ -74,9 +74,11 @@ void ConditionVarDebug::
 wait() {
   _mutex._global_lock->lock();
 
+  Thread *this_thread = Thread::get_current_thread();
+
   if (!_mutex.do_debug_is_locked()) {
     ostringstream ostr;
-    ostr << *Thread::get_current_thread() << " attempted to wait on "
+    ostr << *this_thread << " attempted to wait on "
          << *this << " without holding " << _mutex;
     nassert_raise(ostr.str());
     _mutex._global_lock->release();
@@ -85,16 +87,25 @@ wait() {
 
   if (thread_cat->is_spam()) {
     thread_cat.spam()
-      << *Thread::get_current_thread() << " waiting on " << *this << "\n";
+      << *this_thread << " waiting on " << *this << "\n";
+  }
+
+  nassertd(this_thread->_waiting_on_cvar == NULL &&
+           this_thread->_waiting_on_cvar_full == NULL) {
   }
+  this_thread->_waiting_on_cvar = this;
   
   _mutex.do_release();
-  _impl.wait();
+  _impl.wait();  // temporarily releases _global_lock
   _mutex.do_lock();
 
+  nassertd(this_thread->_waiting_on_cvar == this) {
+  }
+  this_thread->_waiting_on_cvar = NULL;
+
   if (thread_cat.is_spam()) {
     thread_cat.spam()
-      << *Thread::get_current_thread() << " awake on " << *this << "\n";
+      << *this_thread << " awake on " << *this << "\n";
   }
 
   _mutex._global_lock->release();
@@ -115,9 +126,11 @@ void ConditionVarDebug::
 wait(double timeout) {
   _mutex._global_lock->lock();
 
+  Thread *this_thread = Thread::get_current_thread();
+
   if (!_mutex.do_debug_is_locked()) {
     ostringstream ostr;
-    ostr << *Thread::get_current_thread() << " attempted to wait on "
+    ostr << *this_thread << " attempted to wait on "
          << *this << " without holding " << _mutex;
     nassert_raise(ostr.str());
     _mutex._global_lock->release();
@@ -126,17 +139,26 @@ wait(double timeout) {
 
   if (thread_cat.is_spam()) {
     thread_cat.spam()
-      << *Thread::get_current_thread() << " waiting on " << *this 
+      << *this_thread << " waiting on " << *this 
       << ", with timeout " << timeout << "\n";
   }
+
+  nassertd(this_thread->_waiting_on_cvar == NULL &&
+           this_thread->_waiting_on_cvar_full == NULL) {
+  }
+  this_thread->_waiting_on_cvar = this;
   
   _mutex.do_release();
-  _impl.wait(timeout);
+  _impl.wait(timeout);  // temporarily releases _global_lock
   _mutex.do_lock();
 
+  nassertd(this_thread->_waiting_on_cvar == this) {
+  }
+  this_thread->_waiting_on_cvar = NULL;
+
   if (thread_cat.is_spam()) {
     thread_cat.spam()
-      << *Thread::get_current_thread() << " awake on " << *this << "\n";
+      << *this_thread << " awake on " << *this << "\n";
   }
 
   _mutex._global_lock->release();
@@ -162,9 +184,12 @@ wait(double timeout) {
 void ConditionVarDebug::
 signal() {
   _mutex._global_lock->lock();
+
+  Thread *this_thread = Thread::get_current_thread();
+
   if (!_mutex.do_debug_is_locked()) {
     ostringstream ostr;
-    ostr << *Thread::get_current_thread() << " attempted to signal "
+    ostr << *this_thread << " attempted to signal "
          << *this << " without holding " << _mutex;
     nassert_raise(ostr.str());
     _mutex._global_lock->release();
@@ -173,7 +198,7 @@ signal() {
 
   if (thread_cat->is_spam()) {
     thread_cat.spam()
-      << *Thread::get_current_thread() << " signalling " << *this << "\n";
+      << *this_thread << " signalling " << *this << "\n";
   }
 
   _impl.signal();

panda/src/pipeline/conditionVarFullDebug.cxx

@@ -74,9 +74,11 @@ void ConditionVarFullDebug::
 wait() {
   _mutex._global_lock->lock();
 
+  Thread *this_thread = Thread::get_current_thread();
+
   if (!_mutex.do_debug_is_locked()) {
     ostringstream ostr;
-    ostr << *Thread::get_current_thread() << " attempted to wait on "
+    ostr << *this_thread << " attempted to wait on "
          << *this << " without holding " << _mutex;
     nassert_raise(ostr.str());
     _mutex._global_lock->release();
@@ -85,16 +87,25 @@ wait() {
 
   if (thread_cat->is_spam()) {
     thread_cat.spam()
-      << *Thread::get_current_thread() << " waiting on " << *this << "\n";
+      << *this_thread << " waiting on " << *this << "\n";
+  }
+
+  nassertd(this_thread->_waiting_on_cvar == NULL &&
+           this_thread->_waiting_on_cvar_full == NULL) {
   }
+  this_thread->_waiting_on_cvar_full = this;
   
   _mutex.do_release();
-  _impl.wait();
+  _impl.wait();  // temporarily releases _global_lock
   _mutex.do_lock();
 
+  nassertd(this_thread->_waiting_on_cvar_full == this) {
+  }
+  this_thread->_waiting_on_cvar_full = NULL;
+
   if (thread_cat.is_spam()) {
     thread_cat.spam()
-      << *Thread::get_current_thread() << " awake on " << *this << "\n";
+      << *this_thread << " awake on " << *this << "\n";
   }
 
   _mutex._global_lock->release();
@@ -115,9 +126,11 @@ void ConditionVarFullDebug::
 wait(double timeout) {
   _mutex._global_lock->lock();
 
+  Thread *this_thread = Thread::get_current_thread();
+
   if (!_mutex.do_debug_is_locked()) {
     ostringstream ostr;
-    ostr << *Thread::get_current_thread() << " attempted to wait on "
+    ostr << *this_thread << " attempted to wait on "
          << *this << " without holding " << _mutex;
     nassert_raise(ostr.str());
     _mutex._global_lock->release();
@@ -126,17 +139,26 @@ wait(double timeout) {
 
   if (thread_cat.is_spam()) {
     thread_cat.spam()
-      << *Thread::get_current_thread() << " waiting on " << *this 
+      << *this_thread << " waiting on " << *this 
       << ", with timeout " << timeout << "\n";
   }
+
+  nassertd(this_thread->_waiting_on_cvar == NULL &&
+           this_thread->_waiting_on_cvar_full == NULL) {
+  }
+  this_thread->_waiting_on_cvar_full = this;
   
   _mutex.do_release();
-  _impl.wait(timeout);
+  _impl.wait(timeout);  // temporarily releases _global_lock
   _mutex.do_lock();
 
+  nassertd(this_thread->_waiting_on_cvar_full == this) {
+  }
+  this_thread->_waiting_on_cvar_full = NULL;
+
   if (thread_cat.is_spam()) {
     thread_cat.spam()
-      << *Thread::get_current_thread() << " awake on " << *this << "\n";
+      << *this_thread << " awake on " << *this << "\n";
   }
 
   _mutex._global_lock->release();
@@ -162,9 +184,12 @@ wait(double timeout) {
 void ConditionVarFullDebug::
 signal() {
   _mutex._global_lock->lock();
+
+  Thread *this_thread = Thread::get_current_thread();
+
   if (!_mutex.do_debug_is_locked()) {
     ostringstream ostr;
-    ostr << *Thread::get_current_thread() << " attempted to signal "
+    ostr << *this_thread << " attempted to signal "
          << *this << " without holding " << _mutex;
     nassert_raise(ostr.str());
     _mutex._global_lock->release();
@@ -173,7 +198,7 @@ signal() {
 
   if (thread_cat->is_spam()) {
     thread_cat.spam()
-      << *Thread::get_current_thread() << " signalling " << *this << "\n";
+      << *this_thread << " signalling " << *this << "\n";
   }
 
   _impl.signal();
@@ -197,9 +222,12 @@ signal() {
 void ConditionVarFullDebug::
 signal_all() {
   _mutex._global_lock->lock();
+
+  Thread *this_thread = Thread::get_current_thread();
+
   if (!_mutex.do_debug_is_locked()) {
     ostringstream ostr;
-    ostr << *Thread::get_current_thread() << " attempted to signal "
+    ostr << *this_thread << " attempted to signal "
          << *this << " without holding " << _mutex;
     nassert_raise(ostr.str());
     _mutex._global_lock->release();
@@ -208,7 +236,7 @@ signal_all() {
 
   if (thread_cat->is_spam()) {
     thread_cat.spam()
-      << *Thread::get_current_thread() << " signalling all " << *this << "\n";
+      << *this_thread << " signalling all " << *this << "\n";
   }
 
   _impl.signal_all();

panda/src/pipeline/thread.cxx

@@ -16,6 +16,9 @@
 #include "mainThread.h"
 #include "externalThread.h"
 #include "config_pipeline.h"
+#include "mutexDebug.h"
+#include "conditionVarDebug.h"
+#include "conditionVarFullDebug.h"
 
 Thread *Thread::_main_thread;
 Thread *Thread::_external_thread;
@@ -52,6 +55,8 @@ Thread(const string &name, const string &sync_name) :
 
 #ifdef DEBUG_THREADS
   _blocked_on_mutex = NULL;
+  _waiting_on_cvar = NULL;
+  _waiting_on_cvar_full = NULL;
 #endif
 
 #if defined(HAVE_PYTHON) && !defined(SIMPLE_THREADS)
@@ -69,7 +74,9 @@ Thread(const string &name, const string &sync_name) :
 Thread::
 ~Thread() {
 #ifdef DEBUG_THREADS
-  nassertv(_blocked_on_mutex == NULL);
+  nassertv(_blocked_on_mutex == NULL &&
+           _waiting_on_cvar == NULL &&
+           _waiting_on_cvar_full == NULL);
 #endif
 }
 
@@ -153,6 +160,27 @@ output(ostream &out) const {
   out << get_type() << " " << get_name();
 }
 
+////////////////////////////////////////////////////////////////////
+//     Function: Thread::output_blocker
+//       Access: Published
+//  Description: Writes a description of the mutex or condition
+//               variable that this thread is blocked on.  Writes
+//               nothing if there is no blocker, or if we are not in
+//               DEBUG_THREADS mode.
+////////////////////////////////////////////////////////////////////
+void Thread::
+output_blocker(ostream &out) const {
+#ifdef DEBUG_THREADS
+  if (_blocked_on_mutex != (MutexDebug *)NULL) {
+    out << *_blocked_on_mutex;
+  } else if (_waiting_on_cvar != (ConditionVarDebug *)NULL) {
+    out << *_waiting_on_cvar;
+  } else if (_waiting_on_cvar_full != (ConditionVarFullDebug *)NULL) {
+    out << *_waiting_on_cvar_full;
+  }
+#endif  // DEBUG_THREADS
+}
+
 ////////////////////////////////////////////////////////////////////
 //     Function: Thread::write_status
 //       Access: Published, Static

panda/src/pipeline/thread.h

@@ -31,6 +31,8 @@
 class Mutex;
 class ReMutex;
 class MutexDebug;
+class ConditionVarDebug;
+class ConditionVarFullDebug;
 
 ////////////////////////////////////////////////////////////////////
 //       Class : Thread
@@ -83,6 +85,7 @@ PUBLISHED:
   BLOCKING INLINE static void consider_yield();
 
   virtual void output(ostream &out) const;
+  void output_blocker(ostream &out) const;
   static void write_status(ostream &out);
 
   INLINE bool is_started() const;
@@ -130,7 +133,9 @@ private:
 
 #ifdef DEBUG_THREADS
   MutexDebug *_blocked_on_mutex;
-#endif
+  ConditionVarDebug *_waiting_on_cvar;
+  ConditionVarFullDebug *_waiting_on_cvar_full;
+#endif  // DEBUG_THREADS
 
 private:
   static Thread *_main_thread;
@@ -154,6 +159,8 @@ private:
   static TypeHandle _type_handle;
 
   friend class MutexDebug;
+  friend class ConditionVarDebug;
+  friend class ConditionVarFullDebug;
 
   friend class ThreadDummyImpl;
   friend class ThreadWin32Impl;

panda/src/pipeline/threadSimpleManager.cxx

@@ -334,6 +334,9 @@ write_status(ostream &out) const {
   for (ti = _ready.begin(); ti != _ready.end(); ++ti) {
     out << " " << *(*ti)->_parent_obj;
   }
+  for (ti = _next_ready.begin(); ti != _next_ready.end(); ++ti) {
+    out << " " << *(*ti)->_parent_obj;
+  }
   out << "\n";
 
   double now = get_current_time();
@@ -357,6 +360,11 @@ write_status(ostream &out) const {
     for (ti = threads.begin(); ti != threads.end(); ++ti) {
       ThreadSimpleImpl *thread = (*ti);
       out << " " << *thread->_parent_obj;
+#ifdef DEBUG_THREADS
+      out << " (";
+      thread->_parent_obj->output_blocker(out);
+      out << ")";
+#endif  // DEBUG_THREADS
     }
     out << "\n";
   }
@@ -527,17 +535,23 @@ wake_sleepers(double now) {
 ////////////////////////////////////////////////////////////////////
 void ThreadSimpleManager::
 report_deadlock() {
-  Blocked::iterator bi;
+  Blocked::const_iterator bi;
   for (bi = _blocked.begin(); bi != _blocked.end(); ++bi) {
     BlockerSimple *blocker = (*bi).first;
-    FifoThreads &threads = (*bi).second;
+    const FifoThreads &threads = (*bi).second;
     thread_cat.info()
       << "On blocker " << blocker << ":\n";
-    FifoThreads::iterator ti;
+    FifoThreads::const_iterator ti;
     for (ti = threads.begin(); ti != threads.end(); ++ti) {
       ThreadSimpleImpl *thread = (*ti);
       thread_cat.info()
-        << "  " << *thread->_parent_obj << "\n";
+        << "  " << *thread->_parent_obj;
+#ifdef DEBUG_THREADS
+      thread_cat.info(false) << " (";
+      thread->_parent_obj->output_blocker(thread_cat.info(false));
+      thread_cat.info(false) << ")";
+#endif  // DEBUG_THREADS
+      thread_cat.info(false) << "\n";
     }
   }
 }