Boost Threads Producer/Consumer unexpected behavior

Question

I am currently writing an application(using boost) that will have one producer grabbing frames and one consumer reading frames.I added a sleep statement in the producer to simulate the time to grab a frame. I expected the consumer to wait on a condition variable and on the first notify from the producer be awakened to read the frame. However, what I am seeing in the log file is the consumer(main thread) waiting on the condition variable, however the producer goes through several notifys before the consumer comes out of the wait to read the frame.

Here is my Worker.h

class Worker {
static log4cxx::LoggerPtr m_log;

public:
    Worker();
    virtual ~Worker();

    void start();
    void stop();
    void getCurrentFrame(/*cv::Mat& frame*/);

private:
    void processFrames();

    volatile bool m_stopRequested;

    bool m_bFrameReady;
    boost::mutex m_mutex;
    boost::condition_variable condF;

    boost::shared_ptr<boost::thread> m_thread;
};

Worker.cpp

LoggerPtr Worker::m_log(Logger::getLogger("fdx.Worker"));

Worker::Worker() {
    m_bFrameReady = false;

    LOG4CXX_INFO(m_log, "Worker() c-tor");

    m_stopRequested = false;

}

Worker::~Worker() {
    LOG4CXX_INFO(m_log, "Worker() d-tor");
}

void Worker::start()
{
    LOG4CXX_INFO(m_log, "Worker()::start()");
    assert(!m_thread);

    m_thread = boost::shared_ptr<boost::thread>(new boost::thread(&Worker::processFrames, this));

    LOG4CXX_WARN(m_log, "Worker()::start() thread[" << m_thread->get_id() << "] started!");
}

void Worker::stop()
{
    LOG4CXX_INFO(m_log, "Worker()::stop()");

    if(m_thread != NULL)
    {
        LOG4CXX_INFO(m_log, "Worker()::stop() ThrId [" << m_thread->get_id() << "]");
        m_stopRequested = true;
        m_thread->join();
    }
    else
    {
        LOG4CXX_WARN(m_log, "Worker()::stop() The thread for this camera was never started.");
    }

LOG4CXX_INFO(m_log, "Worker()::stop() thread stopped!");
}

void Worker::processFrames()
{
    LOG4CXX_WARN(m_log, "Worker()::processFrames() Thread[" << boost::this_thread::get_id() << "] starting...");

    int rc = 0;
    std::stringstream ss;

    while(!this->m_stopRequested)
    {
        boost::mutex::scoped_lock lock(m_mutex);
        LOG4CXX_WARN(m_log, "Worker()::processFrames() Got a Write lock");

        m_bFrameReady = true;
        LOG4CXX_WARN(m_log, "Worker()::processFrames() Frame ready set to true");

        boost::this_thread::sleep(boost::posix_time::milliseconds(200));

        LOG4CXX_WARN(m_log, "Worker()::processFrames() Write Un-lock");

        lock.unlock();

        LOG4CXX_WARN(m_log, "Worker()::processFrames() Notify");

        condF.notify_one();
    }
}

void Worker::getCurrentFrame()
{
    boost::mutex::scoped_lock lock(m_mutex);

    while(!this->m_bFrameReady)
    {
        LOG4CXX_WARN(m_log, "Worker::getCurrentFrame() wait for Read lock");
        condF.wait(lock);
    }

    LOG4CXX_WARN(m_log, "Worker::getCurrentFrame() Frame ready; Got a Read lock");

    m_bFrameReady = false;

    LOG4CXX_WARN(m_log, "Worker::getCurrentFrame() Frame ready set to false");

    LOG4CXX_WARN(m_log, "Worker::getCurrentFrame() Read Un-lock");
    lock.unlock();

}

main.cpp

LoggerPtr logger(Logger::getLogger("TCamApp"));

int main(int argc, char** argv)
{
int rc = 0;

char cwDir[FILENAME_MAX];

Worker* pWorker = NULL;

memset(cwDir, 0, sizeof(cwDir));
getcwd(cwDir, FILENAME_MAX);

std::cout << "Current Working Dir[" << cwDir << "]" << endl;

std::stringstream ss;
ss << "" << cwDir << "/logs.properties";
std::cout << "logs.properties file[" << ss.str() << "]" << endl;

struct stat st;
if(!stat(ss.str().c_str(), &st))
{
    PropertyConfigurator::configure(ss.str());
}
else
{
    BasicConfigurator::configure();
}

LOG4CXX_INFO(logger, "Application [" << argv[0] << "] starting...");

pWorker = new Worker();
assert(pWorker);

pWorker->start();

for(int i = 0; i < 100; i++)
{
    pWorker->getCurrentFrame();

    LOG4CXX_INFO(logger, "Iteration [" << i << "]");


    //boost::this_thread::sleep(boost::posix_time::milliseconds(20));
}

pWorker->stop();

LOG4CXX_INFO(logger, "Application [" << argv[0] << "] stopping...");

return rc;
}

Below is an excerpt from my log file:

2012-07-11 15:33:53,943 [0x7f5707bcf780] INFO  TCamApp - Application [/home/op/workspace/TestThreads/Debug/TestThreads] starting...
2012-07-11 15:33:53,944 [0x7f5707bcf780] WARN  fdx.Worker - Worker()::start() thread[0x15e4c50] started!
2012-07-11 15:33:53,944 [0x7f5707bcf780] WARN  fdx.Worker - Worker::getCurrentFrame() wait for Read lock
2012-07-11 15:33:53,944 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Thread[0x15e4c50] starting...
2012-07-11 15:33:53,944 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Got a Write lock
2012-07-11 15:33:53,944 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Frame ready set to true
2012-07-11 15:33:54,145 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Write Un-lock
2012-07-11 15:33:54,145 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Notify
2012-07-11 15:33:54,145 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Got a Write lock
2012-07-11 15:33:54,145 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Frame ready set to true
2012-07-11 15:33:54,345 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Write Un-lock
2012-07-11 15:33:54,345 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Notify
2012-07-11 15:33:54,345 [0x7f5707bcf780] WARN  fdx.Worker - Worker::getCurrentFrame() Frame ready; Got a Read lock
2012-07-11 15:33:54,345 [0x7f5707bcf780] WARN  fdx.Worker - Worker::getCurrentFrame() Frame ready set to false
2012-07-11 15:33:54,345 [0x7f5707bcf780] WARN  fdx.Worker - Worker::getCurrentFrame() Read Un-lock
2012-07-11 15:33:54,346 [0x7f5707bcf780] INFO  TCamApp - Iteration [0]
2012-07-11 15:33:54,346 [0x7f5707bcf780] WARN  fdx.Worker - Worker::getCurrentFrame() wait for Read lock
2012-07-11 15:33:54,346 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Got a Write lock
2012-07-11 15:33:54,346 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Frame ready set to true
2012-07-11 15:33:54,546 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Write Un-lock
2012-07-11 15:33:54,547 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Notify
2012-07-11 15:33:54,547 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Got a Write lock
2012-07-11 15:33:54,547 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Frame ready set to true
2012-07-11 15:33:54,747 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Write Un-lock
2012-07-11 15:33:54,747 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Notify
2012-07-11 15:33:54,747 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Got a Write lock
2012-07-11 15:33:54,747 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Frame ready set to true
2012-07-11 15:33:54,948 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Write Un-lock
2012-07-11 15:33:54,948 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Notify
2012-07-11 15:33:54,948 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Got a Write lock
2012-07-11 15:33:54,948 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Frame ready set to true
2012-07-11 15:33:55,148 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Write Un-lock
2012-07-11 15:33:55,149 [0x7f57059c1700] WARN  fdx.Worker - Worker()::processFrames() Notify
2012-07-11 15:33:55,149 [0x7f5707bcf780] WARN  fdx.Worker - Worker::getCurrentFrame() Frame ready; Got a Read lock
2012-07-11 15:33:55,149 [0x7f5707bcf780] WARN  fdx.Worker - Worker::getCurrentFrame() Frame ready set to false
2012-07-11 15:33:55,149 [0x7f5707bcf780] WARN  fdx.Worker - Worker::getCurrentFrame() Read Un-lock
2012-07-11 15:33:55,149 [0x7f5707bcf780] INFO  TCamApp - Iteration [1]

As you can see from the log the main thread waits to read, yet the other thread will produce multiple notifys before the main thread will get out of it's wait().

I have researched some and thought I had coded it correctly, but it is not behaving as I expected. I would appreciate any advice on a solution. Thanks.

Unless you're working on a very specific platform, like x86, and want to limit yourself to such a platform, [`volatile` is not useful for multithreaded programming](http://stackoverflow.com/a/4558031/87234). — GManNickG, Jul 11 '12 at 21:53
Well, and replace it with something else. :) Like `atomic` (or atomic flag). — GManNickG, Jul 11 '12 at 22:12

score 2 · Accepted Answer · edited Jul 13 '12 at 04:08

That's expected, as the producer thread is sleeping with the mutex locked. As soon as it wakes up, it notifies the consumer and locks it again. There's no guarantee of "fairness" on who will get to lock the mutex.

What you appear to be trying to implement is an asynchronous queue. It usually contains 2 condition variables: one to hold down producers when the queue is full, another to hold down consumers when the queue is empty. No matter how long it takes to produce or consume the item in the queue, the mutex gets locked only for the duration of the push/pop operations - which is supposed to be really fast.

Your sleep statement is probably just biasing the scheduler of your OS to give more priority to the producer thread. Move the sleep out of the critical section, to simulate the processing outside the push operation, and you should see the consumer thread being more responsive.

On a related note, instead polling an atomic variable for termination, you could push a sentinel object (that is, a special value, like a null pointer on a queue of pointers) onto the queue to let the consumer threads know they have to stop.

Great info. Moved the sleep out of the critical section and everything behaved as expected. That got me thinking about the code retrieving frames from the video device and there is a select() call on the file handle with a timeout. I changed the code to only lock on a buffer copy operation instead of the entire retrieval of the frame. I really your idea on using a sentinel object for termination. Thanks again!! — vagrant4ever, Jul 13 '12 at 15:30

Boost Threads Producer/Consumer unexpected behavior

1 Answers1