[Boost-users] [thread] Mysterious deadlock

From: David Greene (greened_at_[hidden])
Date: 2006-02-09 16:46:23

I have this simple testcase (below) which runs into deadlock (full
run trace after the testcase):

...
[Producer] Producer generated data 28
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 29
[Producer] push(): about to lock
[Producer] push(): locked
[Consumer] Signaled for data
[Consumer] empty(): about to lock
<<DEADLOCK>>

The call to empty() by Consumer is after the first time
it is woken up from full_condition.  So the deadlock
occurs right when the consumer first attempts to grab
some data.

Is there something I'm not understanding about how
mutexes and locks work in Boost.Thread?  I feel like
I'm missing something obvious.  This comes out of a
larger and more complicated program but I was able to
isolate the mysterious (to me) behavior I'm seeing.

I used to use LOG for debugging but I thought there might be
some interaction between the queue mutex locks and the print
mutex locks so I switched to the non-locking LOG_NOLCK but
observed no change in behavior.

Any help is greatly appreciated.

                       -Dave

---------------------------------
Testcase

#include <iostream>
#include <queue>
#include <map>
#include <string>

#include <boost/thread.hpp>
#include <boost/thread/recursive_mutex.hpp>
#include <boost/thread/condition.hpp>
#include <boost/bind.hpp>

#include <pthread.h>

typedef boost::recursive_mutex mutex_type;
typedef mutex_type::scoped_lock lock_type;

// Atomic prints
mutex_type print_mutex;
mutex_type print_map_mutex;

// For print/debug purposes
typedef std::map<pthread_t, std::string> thread_map_type;
thread_map_type thread_map;

template<typename T>
void register_thread_id(const T &entity)
{
   lock_type lock(print_map_mutex);
   std::cout << "Registering " << pthread_self() << " to " << entity.name()
             << std::endl;
   thread_map[pthread_self()] = entity.name();
}

#define LOG(msg)                                  \
{                                                 \
   lock_type lock(print_mutex);                   \
   std::cout << "[" << thread_map[pthread_self()] \
             << "] " << msg << std::endl;         \
}

#define LOG_NOLCK(msg)                            \
{                                                 \
   std::cout << "[" << thread_map[pthread_self()] \
             << "] " << msg << std::endl;         \
}

// Synchronize start (make sure all registered)
mutex_type go_mutex;
boost::condition go_condition;

bool ready = false;

class Consumer {
   private:
      boost::thread thread;

      std::queue<int> queue;

      typedef boost::recursive_mutex mutex_type;
      typedef mutex_type::scoped_lock lock_type;

      mutable mutex_type mutex;
      mutable mutex_type full_mutex;

      mutable boost::condition full_condition;

      void wait_until_ready(void) const {
         ::lock_type lock(go_mutex);

         while(!ready) {
            go_condition.wait(lock);
         }
         LOG_NOLCK("go!");
      };

      void wait_for_data(void) const {
         lock_type lock(full_mutex);
         while(empty()) {
            LOG_NOLCK("Waiting for data");
            full_condition.wait(lock);
            LOG_NOLCK("Signaled for data");
         }
         LOG_NOLCK("Wakeup for data");
      };

      void event_loop(void) {
         register_thread_id(*this);
         wait_until_ready();
        
         while(true) {
            wait_for_data();	
            LOG_NOLCK("Consumer received data " << top());
            pop();
         }
      };

   public:
      Consumer(void) : thread(boost::bind(&Consumer::event_loop, this)) {};

      std::string name(void) const { return("Consumer"); };

      void push(int val) {
         LOG_NOLCK("push(): about to lock");
         {
            lock_type lock(mutex);
            LOG_NOLCK("push(): locked");
            queue.push(val);
        
            lock_type full_lock(full_mutex);
            LOG_NOLCK("push(): about to unlock");
         }
         full_condition.notify_all();
      };

      int top(void) const {
         LOG_NOLCK("top(): about to lock");
         lock_type lock(mutex);
         LOG_NOLCK("top(): locked");
         int item = queue.front();
         LOG_NOLCK("top(): about to unlock");
         return(item);
      };

      void pop(void) {
         LOG_NOLCK("pop(): about to lock");
         lock_type lock(mutex);
         LOG_NOLCK("pop(): locked");
         queue.pop();
         LOG_NOLCK("pop(): about to unlock");
      };

      bool empty (void) const {
         LOG_NOLCK("empty(): about to lock");
         lock_type lock(mutex);
         LOG_NOLCK("empty(): locked");
         bool val = queue.empty();
         LOG_NOLCK("empty(): about to unlock");
         return(val);
      };
};

class Producer {
   private:
      boost::thread thread;

      void wait_until_ready(void) const {
         lock_type lock(go_mutex);

         while(!ready) {
            go_condition.wait(lock);
         }
         LOG_NOLCK("go!");
      };

      void event_loop(void) {
         int i = 0;

         register_thread_id(*this);
         wait_until_ready();

         while(true) {
            LOG_NOLCK("Producer generated data " << i);
            consumer->push(i);
            ++i;
         };
      };

      Consumer *consumer;

   public:
      Producer(Consumer *c) : consumer(c),
                              thread(boost::bind(&Producer::event_loop, this)) {};

      std::string name(void) const { return("Producer"); };
};

void go(void)
{
   // Wait until everyone arrives
   lock_type lock(go_mutex);
   ready = true;

   // Notify everyone
   go_condition.notify_all();
}

int main(void)
{
   Consumer c;
   Producer p(&c);

   go();

   while(true);

   return(0);
}

-----------------
Ouput Trace

[Consumer] empty(): about to unlock
[Consumer] Waiting for data
Registering 48958384 to Producer
[Producer] go!
[Producer] Producer generated data 0
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 1
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 2
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 3
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 4
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 5
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 6
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 7
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 8
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 9
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 10
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 11
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 12
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 13
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 14
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 15
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 16
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 17
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 18
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 19
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 20
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 21
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 22
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 23
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 24
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 25
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 26
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 27
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 28
[Producer] push(): about to lock
[Producer] push(): locked
[Producer] push(): about to unlock
[Producer] Producer generated data 29
[Producer] push(): about to lock
[Producer] push(): locked
[Consumer] Signaled for data
[Consumer] empty(): about to lock
<<DEADLOCK>>