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

Subject: Re: [Boost-users] [Thread] thousands of spurious wakeups from timed_wait() per second
From: Vicente J. Botet Escriba (vicente.botet_at_[hidden])
Date: 2014-09-10 02:46:27

Le 10/09/14 04:38, Steven Clark a écrit :
> 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.
Which platforms are you testing?
> 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.
Could you test with the develop branch?
>
> Because of the lack of problem reports, I figure I'm doing something
> wrong.
Well, not everyone writes a report.
> 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."
I suspect that this mean that you need to check for the spurious 
wakeups, and the predicate recall you to do it. Changing the duration is 
something the users forgot to do as it is not evident.
> 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.
the function return true if there were a notify on this condition. This 
doesn't mean that another thread has not already changed the result of 
the predicate.
the function return false when there were no notify before the timeout 
was reached.
>
> 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.
Well, this is how it works. The problem is why do you receive so many 
spurious wakeup.
>
> Here is the version of my test program that uses timed_wait without a
> predicate, followed by its output.
>
<snip>

> ******* 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
>
I have not reached to reproduce it on develop branch. I will try later 
with other versions.
Here are my results on MacOs

******* Using timed_wait()
hello from threadfn(), #0
now is 2014-Sep-10 08:27:08.045253
deadline is 2014-Sep-10 08:27:10.045253
main() exited inner loop with 0 wakeups; gGotData is true
main(), notified, gValue is 0
now is 2014-Sep-10 08:27:08.046008
deadline is 2014-Sep-10 08:27:10.046008
hello from threadfn(), #1
timed_wait() returned true on wakeup #1
main() exited inner loop with 1 wakeups; gGotData is true
main(), notified, gValue is 1
now is 2014-Sep-10 08:27:09.046545
deadline is 2014-Sep-10 08:27:11.046545
hello from threadfn(), #2
timed_wait() returned true on wakeup #1
main() exited inner loop with 1 wakeups; gGotData is true
main(), notified, gValue is 2
now is 2014-Sep-10 08:27:10.047779
deadline is 2014-Sep-10 08:27:12.047779
hello from threadfn(), #3
timed_wait() returned true on wakeup #1
main() exited inner loop with 1 wakeups; gGotData is true
main(), notified, gValue is 3
now is 2014-Sep-10 08:27:11.048845
deadline is 2014-Sep-10 08:27:13.048845
hello from threadfn(), #4
timed_wait() returned true on wakeup #1
main() exited inner loop with 1 wakeups; gGotData is true
main(), notified, gValue is 4
now is 2014-Sep-10 08:27:12.049441
deadline is 2014-Sep-10 08:27:14.049441
hello from threadfn(), #5
timed_wait() returned true on wakeup #1
main() exited inner loop with 1 wakeups; gGotData is true
main(), notified, gValue is 5
now is 2014-Sep-10 08:27:13.050441
deadline is 2014-Sep-10 08:27:15.050441
hello from threadfn(), #6
timed_wait() returned true on wakeup #1
main() exited inner loop with 1 wakeups; gGotData is true
main(), notified, gValue is 6
main(), after joining

Best,
Vicente