Boost C++ Libraries: Ticket #9856: [windows] condition_variable::wait_for returns wrong cv_status on timeout.

pi88el@… — Tue, 08 Apr 2014 19:06:54 GMT

This is also happening with wait_until.

owner, status changed

viboes — Sat, 19 Apr 2014 07:13:02 GMT

owner changed from Anthony Williams to viboes
status new → assigned

summary changed

viboes — Sat, 19 Apr 2014 11:09:36 GMT

summary condition_variable::wait_for returns wrong cv_status on timeout. → [windows] condition_variable::wait_for returns wrong cv_status on timeout.

sclark@… — Tue, 16 Sep 2014 14:43:55 GMT

This bug seems closely related to, or the same as, something I found on Linux in Boost 1.54, 1.48, and 1.46. When passed a deadline represented as a system_time, condition_variable::timed_wait() returns false (i.e. timed out) after a little under a millisecond. For more info and a test program, see the boost-users mailing list archive, thread subject "[Thread] thousands of spurious wakeups from timed_wait() per second" around Sept. 11, 2014.

(Sorry, I can't get a link to it past trac's spam filter. The spam filter says "Please respond to the following" and nothing follows.)

milestone changed

viboes — Tue, 23 Sep 2014 00:17:26 GMT

milestone To Be Determined → Boost 1.57.0

Niall Douglas — Sat, 04 Oct 2014 19:41:50 GMT

I am unable to replicate this issue with trunk 1.57 on VS2013 x86 on Win8.1.

viboes — Wed, 08 Oct 2014 05:27:30 GMT

@pi88el,@sclark please, could you check on trunk?

status changed; resolution set; milestone deleted

viboes — Sat, 11 Oct 2014 05:28:23 GMT

status assigned → closed
resolution → worksforme
milestone Boost 1.57.0

yinon — Wed, 24 Dec 2014 13:55:40 GMT

It reproduces on 1.57. Windows 8.1 Visual Studio 2013 Ultimate

Using the function

boost::condition_variable condition; condition.wait_until(lock, _waitUntil)

status, version changed; resolution deleted

yinon@… — Wed, 24 Dec 2014 13:56:42 GMT

status closed → reopened
version Boost 1.55.0 → Boost 1.57.0
resolution worksforme

Niall Douglas — Sun, 04 Jan 2015 05:58:40 GMT

I had a look for the testcase I wrote for #9856 but it looks like I deleted it last time I reset my Boost installation.

However, if I am to be blunt here, this must be a behaviour which differs between people's machines. Perhaps an AMD vs Intel difference, or maybe a HPET difference? On Windows it also matters hugely if any multimedia program is running because then the Windows context switch granularity goes from ~43ms to ~1ms. A multimedia program famous for this is the Chrome web browser.

Obviously whether a multimedia program is running should make no difference to Boost code. But I am trying to think of a repeatable demonstration, as otherwise finding and fixing any problem is very hard.

yinon@… — Sun, 04 Jan 2015 06:14:20 GMT

I have reproduced the problem on a Parallels Desktop 10 Virtual Machine, running on a MacBook Pro, Processor: Intel Core i5.

Niall Douglas — Sat, 10 Jan 2015 13:13:59 GMT

I've put together the following test case test_9856.cpp:

#include "boost/thread.hpp"
#include <iostream>
using namespace boost;
int main() {
    mutex mtx;
    condition_variable cond;
    unique_lock<mutex> lk(mtx);
    std::cout << BOOST_VERSION << "\n";
    for(int i=0; i<10; i++) {
        //std::cout << i << " : " << chrono::steady_clock::now().count() << "\n";
        if (cv_status::timeout != cond.wait_for(lk, chrono::seconds(1)))
        {
            std::cout << "ERROR: Wrong return code!\n";
            return 1;
        }
    }
    return 0;
}

I'll test it on Windows when I reboot out of Linux later today. I've also lined up a KVM virtualised Windows to test upon.

Niall

owner, status changed

viboes — Sat, 10 Jan 2015 15:07:55 GMT

owner changed from viboes to Niall Douglas
status reopened → new

Niall Douglas — Sat, 10 Jan 2015 20:38:35 GMT

I've successfully replicated this bug! You have to loop running the test case a few times, but it'll eventually appear. This was on Windows 8.1 x64.

I'll see if I can fix it next Saturday.

Niall

Niall Douglas — Thu, 22 Jan 2015 18:38:11 GMT

I have an update on this issue. Firstly, I have committed a testcase for this to Boost.Thread trunk, so it is now being tested as part of regular unit testing.

I have some quite scary news though. Boost.Thread decides whether the wait has timed out by comparing steady_clock (really QueryPerformanceCounter) from before and after, and if the wait took the timeout or longer it assumes that timeout occurred. Unfortunately, WaitForMultipleObjectsEx() provides no guarantees that it actually waits for the timeout requested - you might request 50ms, but might actually get 10ms. Here is an example program:

#include <windows.h>
#include <stdio.h>
#include <chrono>
int main(void)
{
  ULONG ulDelay_ms = 20;
  HANDLE hSemaphoreDelay = CreateSemaphore(NULL, 0, 1, NULL);
  for (size_t n = 0; n < 50; n++)
  {
    while (1) {
      auto begin = std::chrono::high_resolution_clock::now();
      ULONG hr = WaitForSingleObject(hSemaphoreDelay, ulDelay_ms);
      auto end = std::chrono::high_resolution_clock::now();
      auto diff = end - begin;
      if (hr == WAIT_ABANDONED)
        printf("Wait Abandoned ");
      else if (hr == WAIT_TIMEOUT)
        printf("Timed out ");
      else
        printf("Signaled ");
      DWORD lTDelta = std::chrono::duration_cast<std::chrono::milliseconds>(diff).count();
      printf("Target Wait Interval: %u Real Wait Interval: %u (%u)\n", ulDelay_ms, lTDelta, diff.count());
      if (lTDelta >= ulDelay_ms) break;
    }
    printf("\n");
  }
  CloseHandle(hSemaphoreDelay);
  return 0;
}

... and indeed very occasionally it is returning after 16-18ms instead of the requested 20ms at the same frequency that Boost.Thread is not returning timeout.

This is scary because I believe every single wait routine in Windows in Boost.Thread, and possibly other Boost libraries, will need to be audited and potentially refactored. I'll raise it on boost-dev tomorrow morning. I believe this new early timeout feature was probably introduced when Microsoft added timer coalescing to Windows to save battery on mobile devices, and so only appeared in Windows 7 and later. The fact it hasn't presented sooner is worrying.

Niall

Niall Douglas — Fri, 23 Jan 2015 17:15:43 GMT

FYI the current consensus in the discussion on boost-dev is that this should be a wontfix. See http://comments.gmane.org/gmane.comp.lib.boost.devel/257246.

Personally speaking I'd prefer to adjust the code to produce fewer spurious wakeups, but not completely prevent them. We'll see if Microsoft come back to us to say what their STL does.

Niall Douglas — Thu, 29 Jan 2015 17:57:38 GMT

Did some testing of the performance of passing a timeout to WaitForMultipleObjects versus using SetWaitableTimerEx:

Where underlying object is not signalled, 1ms timeout:

WaitForMultipleObjects alone: 1293.457580 microsecs

CreateWaitableTimer + SetWaitableTimer + WaitForMultipleObjects + CloseHandle: 1000.870380 microsecs

Where underlying object is signalled:

WaitForMultipleObjects alone: 0.246493 microsecs

SetWaitableTimer + WaitForMultipleObjects: 1.062579 microsecs

CreateWaitableTimer + SetWaitableTimer + WaitForMultipleObjects + CloseHandle: 2.055087 microsecs

Moving the creation of the waitable timer outside of interruptible_wait() will be a pain - every interruptible_wait() user will need to cache a copy, or else we keep a copy in thread local storage. Given that the number of occasions where the underlying semaphore goes signalled in between the check before starting the wait and the wait beginning will be few, I reckon the 8x slowdown for timeouts < 20ms will be worth the ease of implementation. So this is what I will do.

Niall

viboes — Sat, 31 Jan 2015 10:03:52 GMT

It seems this is related to #10967 and #9720.

Niall Douglas — Sun, 01 Feb 2015 01:41:22 GMT

Replying to viboes:

It seems this is related to #10967 and #9720.

It does appear that Windows respects the timeout you pass to a waitable timer, whilst it fuzzes any timeout given to WaitForMultipleObjects to be either too short or too long (on average 30% too long).

BTW I have more empirical findings. It turns out Windows ignores all TolerableDelay values <= 26 ms. I have no idea why. But 27 ms is definitely the minimum for it to have any effect at all.

Windows usually ticks at 15.6 ms, so a tolerable delay of 27 ms is about 1.75 context switches. Do I have permission to set that minimum for all timers i.e.

27 ms <= tolerable delay <= 5% of duration between now and timeout.

Do we need an upper bound on tolerable delay? I can't see Windows running for ten seconds without at least one interrupt firing though ...

Niall

viboes — Sun, 01 Feb 2015 07:42:39 GMT

Niall, are these data dependent on the windows version?

Niall Douglas — Sun, 01 Feb 2015 15:44:18 GMT

@viboes I only have access to Windows 8.1 nowadays. They added coalesced timer support in Vista and a tickless kernel in Windows 8, so I would assume each Windows will be a little bit different.

The code I have written should compile and work on Win XP however. As with GetTickCount64(), it emulates the SetWaitableTimerEx() function on XP and earlier.

Niall

viboes — Mon, 02 Feb 2015 05:54:49 GMT

I let you take the best decision.

Niall Douglas — Wed, 04 Feb 2015 14:31:03 GMT

Addition of coalesced timers is in https://github.com/boostorg/thread/pull/44.

The fact that Thread doesn't return timeout up to 10% of the time on Windows is wontfix.

status changed; resolution set

Niall Douglas — Wed, 04 Feb 2015 14:32:01 GMT

status new → closed
resolution → wontfix