[Boost-users] [Thread] thousands of spurious wakeups from timed_wait() per second

Subject: [Boost-users] [Thread] thousands of spurious wakeups from timed_wait() per second
From: Steven Clark (steven.clark_at_[hidden])
Date: 2014-09-09 22:38:14

I've been trying to get useful behavior out of
condition_variable::timed_wait() with little success.  Depending on
the platform, I'm getting about 3000 or nearly 100000 spurious wakeups
per second.

I'm working on a few different Linux platforms with different versions
of Boost: 1.46, 1.48, and another in the high 40's.  The eventual target
is 1.48.  I've looked for bug reports and haven't found any, and I have
no evidence yet that suggests the different versions are significant to
this problem.

Because of the lack of problem reports, I figure I'm doing something
wrong.  That's my question:  "What am I doing wrong here?"

I have a test program that sets up a typical producer/consumer example.
The main program spawns a thread, the producer, that notifies the main
thread via a condition_variable once a second for a few seconds, then
ends.  The main thread, the consumer, waits efficiently for notifications
with a 2-second timeout.  When the producer thread finishes, the main
(consumer) thread eventually times out, joins the spawned thread,
and exits.  At least, that's what is supposed to happen.

If I don't bother with timeouts and use condition_variable::wait(), it
works perfectly - except for the timeout, join, and exit.  This is as
expected.  So far I have seen no spurious wakeups at all with this test.

There is an ominous yet ambiguous remark in the documentation
"The duration overload of timed_wait is difficult to use correctly.
The overload taking a predicate should be preferred in most cases."
Due to that remark I stopped experimenting with relative timeouts before
I got anything to work.  Using absolute timeouts, I get very high numbers
of spurious wakeups as mentioned above - 3000 and about 100000 per second
depending on the platform.  I see no difference between timed_wait with
a predicate and without a predicate.

I'm also having trouble with the return value of timed_wait().
The documentation carefully states that timed_wait() returns "false if
the call is returning because the time specified by abs_time was reached,
true otherwise".  This seems to mean that spurious wakeups return true
-- and if you think about it, the return value is useless if spurious
wakeups could return false.  You'd have to add your own check for timeout.

I was quite surprised to find that every spurious wakeup of timed_wait()
that I've ever seen returns false.  That just doesn't make sense to me.

Here is the version of my test program that uses timed_wait without a
predicate, followed by its output.

#include <boost/thread.hpp>
#include <boost/date_time.hpp>
#include <iostream>

boost::condition_variable gCond;
boost::mutex gMutex;
bool gGotData;
unsigned gValue;

void threadfn() {
    for (unsigned i = 0; i < 7; i++) {
        std::cerr << "hello from threadfn(), #" << i << std::endl;
        {
            boost::lock_guard<boost::mutex> guard(gMutex);
            gGotData = true;
            gValue = i;
        }
        gCond.notify_one();
        boost::this_thread::sleep(boost::posix_time::seconds(1));
    }
}


int main() {
    std::cerr << "******* Using timed_wait()" << std::endl;
    gGotData = false;
    gValue = 999;
    boost::thread t(threadfn);
    while (true) {
        boost::system_time deadline(
                boost::posix_time::microsec_clock::local_time());
        std::cerr << "now is " << deadline << std::endl;
        deadline += boost::posix_time::seconds(2);
        std::cerr << "deadline is " << deadline << std::endl;
        boost::unique_lock<boost::mutex> lock(gMutex);
        unsigned nWakeups = 0;
        while(!gGotData) {
            bool ret = gCond.timed_wait(lock, deadline);
            nWakeups++;
            if (ret) std::cerr << "timed_wait() returned true on wakeup #"
                    << nWakeups << std::endl;
        }
        std::cerr << "main() exited inner loop with " << nWakeups
                << " wakeups; gGotData is "
                << (gGotData ? "true" : "false") << std::endl;
        if (gGotData) {
            std::cerr << "main(), notified, gValue is " << gValue << std::endl;
            gGotData = false;
        }
    }
    // not reached in this incarnation of the code
    t.join();
    std::cerr << "main(), after joining" << std::endl;
}


******* Using timed_wait()
now is 2014-Sep-09 20:48:12.183781
deadline is 2014-Sep-09 20:48:14.183781
hello from threadfn(), #0
timed_wait() returned true on wakeup #1451
main() exited inner loop with 1451 wakeups; gGotData is true
main(), notified, gValue is 0
now is 2014-Sep-09 20:48:12.215471
deadline is 2014-Sep-09 20:48:14.215471
hello from threadfn(), #1
timed_wait() returned true on wakeup #96864
main() exited inner loop with 96864 wakeups; gGotData is true
main(), notified, gValue is 1
now is 2014-Sep-09 20:48:13.216511
deadline is 2014-Sep-09 20:48:15.216511
hello from threadfn(), #2
timed_wait() returned true on wakeup #95911
main() exited inner loop with 95911 wakeups; gGotData is true
main(), notified, gValue is 2
now is 2014-Sep-09 20:48:14.216805
deadline is 2014-Sep-09 20:48:16.216805
hello from threadfn(), #3
timed_wait() returned true on wakeup #97526
main() exited inner loop with 97526 wakeups; gGotData is true
main(), notified, gValue is 3
now is 2014-Sep-09 20:48:15.217191
deadline is 2014-Sep-09 20:48:17.217191
hello from threadfn(), #4
timed_wait() returned true on wakeup #104710
main() exited inner loop with 104710 wakeups; gGotData is true
main(), notified, gValue is 4
now is 2014-Sep-09 20:48:16.217453
deadline is 2014-Sep-09 20:48:18.217453
hello from threadfn(), #5
timed_wait() returned true on wakeup #102404
main() exited inner loop with 102404 wakeups; gGotData is true
main(), notified, gValue is 5
now is 2014-Sep-09 20:48:17.217685
deadline is 2014-Sep-09 20:48:19.217685
hello from threadfn(), #6
timed_wait() returned true on wakeup #97906
main() exited inner loop with 97906 wakeups; gGotData is true
main(), notified, gValue is 6
now is 2014-Sep-09 20:48:18.217291
deadline is 2014-Sep-09 20:48:20.217291
^C

Thank you very much,
Steven Clark