<condition_variable>: condition_variable_any::wait_for returns cv_status::timeout when the elapsed time is shorter than requested

[cpplearner]

Describe the bug

Revealed by libc++ test test/std/thread/thread.condition/thread.condition.condvarany/wait_for.pass.cpp.

[thread.condvarany.wait]/13:

Returns: cv_status​::​timeout if the relative timeout ([thread.req.timing]) specified by rel_time expired, otherwise cv_status​::​no_timeout.

But MSVC STL's condition_variable_any::wait_for sometimes returns cv_status​::​timeout even though the elapsed time (measured by high_resolution_clock) is shorter than the requested timeout.

Command-line test case

D:\test>type test-condvarany.cpp
#include <condition_variable>
#include <atomic>
#include <cassert>
#include <chrono>
#include <mutex>
#include <thread>
#include <print>

template <class Mutex>
struct MyLock : std::unique_lock<Mutex> {
  using std::unique_lock<Mutex>::unique_lock;
};

template <class Function>
std::chrono::microseconds measure(Function f) {
  std::chrono::high_resolution_clock::time_point start = std::chrono::high_resolution_clock::now();
  f();
  std::chrono::high_resolution_clock::time_point end = std::chrono::high_resolution_clock::now();
  return std::chrono::duration_cast<std::chrono::microseconds>(end - start);
}

template <class Lock>
void test() {
  using Mutex = typename Lock::mutex_type;

  // Test unblocking via a timeout.
  //
  // To test this, we create a thread that waits on a condition variable
  // with a certain timeout, and we never awaken it. To guard against
  // spurious wakeups, we wait again whenever we are awoken for a reason
  // other than a timeout.
  {
    auto timeout = std::chrono::milliseconds(250);
    std::condition_variable_any cv;
    Mutex mutex;

    std::thread t1([&] {
      Lock lock(mutex);
      std::cv_status result;
      do {
        auto elapsed = measure([&] { result = cv.wait_for(lock, timeout); });
        if (result == std::cv_status::timeout)
          if (elapsed < timeout) {
            std::println("elapsed: {}", elapsed);
            std::println("timeout: {}", timeout);
          }

      } while (result != std::cv_status::timeout);
    });

    t1.join();
  }
}

int main(int, char**) {
  test<std::unique_lock<std::mutex>>();
  test<std::unique_lock<std::timed_mutex>>();
  test<MyLock<std::mutex>>();
  test<MyLock<std::timed_mutex>>();
  return 0;
}

D:\test>cl /EHs /std:c++latest test-condvarany.cpp
Microsoft (R) C/C++ Optimizing Compiler Version 19.41.33901 for x64
Copyright (C) Microsoft Corporation.  All rights reserved.

/std:c++latest is provided as a preview of language features from the latest C++
working draft, and we're eager to hear about bugs and suggestions for improvements.
However, note that these features are provided as-is without support, and subject
to changes or removal as the working draft evolves. See
https://go.microsoft.com/fwlink/?linkid=2045807 for details.

test-condvarany.cpp
Microsoft (R) Incremental Linker Version 14.41.33901.0
Copyright (C) Microsoft Corporation.  All rights reserved.

/out:test-condvarany.exe
test-condvarany.obj

D:\test>.\test-condvarany.exe
elapsed: 249758us
timeout: 250ms

(You might need to execute the program several times to see the output.)

Expected behavior

.\test-condvarany.exe should consistently produce no output

STL version

v17.11.0-pre.1.0

[frederick-vs-ja]

The round-up in _Clamped_rel_time_ms_count (introduced in #4457) looks like the reason. 249758μs would be turned into 250ms here.

STL/stl/inc/thread

Lines 187 to 198 in e36ee6c

	template <class _Duration>
	_NODISCARD _Clamped_rel_time_ms_count_result _Clamped_rel_time_ms_count(const _Duration& _Rel) {
	// _Clamp must be less than 2^32 - 1 (INFINITE) milliseconds, but is otherwise arbitrary.
	constexpr chrono::milliseconds _Clamp{chrono::hours{24}};
	if (_Rel > _Clamp) {
	return {static_cast<unsigned long>(_Clamp.count()), true};
	} else {
	const auto _Rel_ms = chrono::ceil<chrono::milliseconds>(_Rel);
	return {static_cast<unsigned long>(_Rel_ms.count()), false};
	}
	}

CC @AlexGuteniev.

[AlexGuteniev]

The round-up in _Clamped_rel_time_ms_count (introduced in #4457) looks like the reason

Why? It rounds the parameter passed to wait, so would err on the other side.

[frederick-vs-ja]

The round-up in _Clamped_rel_time_ms_count (introduced in #4457) looks like the reason

Why? It rounds the parameter passed to wait, so would err on the other side.

Oh, I see. Probably I was wrong then.

Can we reproduce the error with SleepConditionVariableSRW? If so, we may need to work around it.

[StephanTLavavej]

This looks like an STL bug that wasn't fixed by #4457 (despite how I Changelogged it, oopsy).

According to WG21-N4981 [thread.condvarany.wait]/11:

template<class Lock, class Rep, class Period>
  cv_status wait_for(Lock& lock, const chrono::duration<Rep, Period>& rel_time);

Effects: Equivalent to:

return wait_until(lock, chrono::steady_clock::now() + rel_time);

condition_variable_any::wait_for should use the steady_clock. But we don't do that:

STL/stl/inc/condition_variable

Lines 117 to 126 in e36ee6c

	template <class _Lock, class _Rep, class _Period>
	cv_status wait_for(_Lock& _Lck, const chrono::duration<_Rep, _Period>& _Rel_time) { // wait for duration
	if (_Rel_time <= chrono::duration<_Rep, _Period>::zero()) {
	_Unlock_guard<_Lock> _Unlock_outer{_Lck};
	(void) _Unlock_outer;
	return cv_status::timeout;
	}
	const auto _Rel_time_ms = _Clamped_rel_time_ms_count(_Rel_time);
	const cv_status _Result = _Wait_for_ms_count(_Lck, _Rel_time_ms._Count);

STL/stl/inc/condition_variable

Lines 227 to 233 in e36ee6c

	template <class _Lock>
	cv_status _Wait_for_ms_count(_Lock& _Lck, const unsigned int _Rel_ms_count) {
	// wait for signal with timeout
	const shared_ptr<mutex> _Ptr = _Myptr; // for immunity to *this destruction
	unique_lock<mutex> _Guard{*_Ptr};
	_Unlock_guard<_Lock> _Unlock_outer{_Lck};
	const _Thrd_result _Res = _Cnd_timedwait_for(_Mycnd(), _Ptr->_Mymtx(), _Rel_ms_count);

STL/stl/src/sharedmutex.cpp

Lines 44 to 54 in e36ee6c

	_Thrd_result __stdcall _Cnd_timedwait_for(const _Cnd_t cond, const _Mtx_t mtx, const unsigned int target_ms) noexcept {
	_Thrd_result res = _Thrd_result::_Success;
	const auto cs = &mtx->_Critical_section;
	const auto start_ms = GetTickCount64();
	// TRANSITION: replace with _Mtx_clear_owner(mtx);
	mtx->_Thread_id = -1;
	--mtx->_Count;
	if (!Concurrency::details::_Get_cond_var(cond)->wait_for(cs, target_ms)) { // report timeout
	const auto end_ms = GetTickCount64();

We're calling GetTickCount64() which is the system clock.

We need to audit this area again (both condition_variable and condition_variable_any) and make sure we Do What The Standard Says^TM.

[Arup-Chauhan]

@AlexGuteniev @frederick-vs-ja @StephanTLavavej @cpplearner I would like to collaborate on this, requested in Discord chat space too :)

[AlexGuteniev]

We're calling GetTickCount64() which is the system clock.

Actually it is not a system clock, it is a steady clock, but an imprecise steady clock not matching std::steady_clock.

[AlexGuteniev]

Adding the following:

#include <Windows.h>

#pragma comment(lib, "Winmm.lib")

...

int main(int, char**) {
	auto p = timeBeginPeriod(1);
...
	timeEndPeriod(p);
	return 0;
}

Makes the bug more reproducible