Opened 6 years ago

Closed 16 months ago

#8006 closed Support Requests (fixed)

Boost::Chrono Assertion at startup - steady_clock::now() - Windows

Reported by: meckschlager@… Owned by: viboes
Milestone: Component: chrono
Version: Boost 1.50.0 Severity: Problem
Keywords: Cc:

Description (last modified by viboes)

steady_clock::time_point now = steady_clock::now(); sometimes causes

Assertion failed: 0 && "Boost::Chrono - Internal Error", file C:\Projects\Librari
es\src\boost\boost_1_48_0\boost/chrono/detail/inlined/win/chrono.hpp, line 44
on Windows XP, boost 1.48

Change History (34)

comment:1 Changed 6 years ago by meckschlager@…

Now I see, boost::chrono is all thread unsafe and I was reading the time from 2 threads simultaneously (I guess that's so not uncommon) Is that really good? Locking the time reading method seems a bit weird to me...

comment:2 in reply to:  1 Changed 6 years ago by viboes

Replying to meckschlager@…:

Now I see, boost::chrono is all thread unsafe and I was reading the time from 2 threads simultaneously (I guess that's so not uncommon)

Why do you think that the code is thread unsafe?

Is that really good? Locking the time reading method seems a bit weird to me...

What is weird for you?

comment:3 in reply to:  description Changed 6 years ago by viboes

Replying to meckschlager@…:

steady_clock::time_point now = steady_clock::now(); sometimes causes Assertion failed: 0 && "Boost::Chrono - Internal Error", file C:\Projects\Librari es\src\boost\boost_1_48_0\boost/chrono/detail/inlined/win/chrono.hpp, line 44 on Windows XP, boost 1.48

The code in question is

    if ( (nanosecs_per_tic <= 0.0L) ||
            (!boost::detail::win32::QueryPerformanceCounter( &pcount )) )
    {
      BOOST_ASSERT(0 && "Boost::Chrono - Internal Error");
      return steady_clock::time_point();
    }

could you check which condition is true?

comment:4 Changed 6 years ago by meckschlager@…

Hi, thanks embracing that issue up!

Why do you think that the code is thread unsafe?

It states so in the chrono users guide "All functions in the library are thread-unsafe except when noted explicitly." (http://www.boost.org/doc/libs/1_52_0/doc/html/chrono/users_guide.html) thats why I came to the working solution

lock steady_clock::time_point now = steady_clock::now(); unlock

Now, it just seems unnecessary that multiple threads might have to wait to get the current time, which many os methods would return without requiring a lock.

cheers m.

comment:5 in reply to:  4 Changed 6 years ago by viboes

Replying to meckschlager@…:

Hi, thanks embracing that issue up!

Why do you think that the code is thread unsafe?

It states so in the chrono users guide "All functions in the library are thread-unsafe except when noted explicitly." (http://www.boost.org/doc/libs/1_52_0/doc/html/chrono/users_guide.html) thats why I came to the working solution

lock steady_clock::time_point now = steady_clock::now(); unlock

Now, it just seems unnecessary that multiple threads might have to wait to get the current time, which many os methods would return without requiring a lock.

Hrr! I would fix this on the documentation, call to Clock::now() should be thread safe.

Thanks for the report.

comment:6 Changed 6 years ago by viboes

Status: newassigned

I have fixed the documentation in revision [83511]. have you analyzed which condition was failing?

comment:7 in reply to:  6 Changed 6 years ago by viboes

Replying to viboes:

I have fixed the documentation in revision [83511]. have you analyzed which condition was failing?

Could you tell me which is the result of

boost::detail::win32::QueryPerformanceCounter( &pcount ) 

when the program asserts?

comment:8 Changed 6 years ago by viboes

Description: modified (diff)
Resolution: worksforme
Status: assignedclosed

I can not reproduce this error. Without your help I'm unable to help you? Reopen it if you have some insight.

comment:9 Changed 6 years ago by anonymous

Resolution: worksforme
Status: closedreopened
Version: Boost 1.48.0Boost 1.50.0

The same assertion happen in my application. Application running 4 threads constructed by thread_group.

pcount = {0x063ff1c300000000}
nanosecs_per_tic = 488.71054212171725


call stack
----------
boost::chrono::steady_clock::now()          Line 44 + 0x16 bytes	C++
boost::condition_variable_any::wait_for<... Line 508 + 0x23 bytes	C++
... (call from my application)


BOOST v1.50
MSVC 9
 - WIN32;_DEBUG;_WIN32_WINNT=0x0501
 - /Od (disabled optimization)

Running at: Windows 7, intel i7

Hope this information can help.

kt.

comment:10 Changed 6 years ago by viboes

I don't know how to explain that QueryPerformanceCounter? fails. Maybe the following remark could explain it

"Remarks

On a multiprocessor computer, it should not matter which processor is called. However, you can get different results on different processors due to bugs in the basic input/output system (BIOS) or the hardware abstraction layer (HAL)."

Anyway. it is surprising that Microsoft doesn't provides stead_clocks on their C++11 library implementation (See some post on SO).

I addition neither gcc nor libC++ provide them on windows as

      clock_gettime(CLOCK_MONOTONIC, &tp);

is not available.

What about not providing steady_clock on Windows?

comment:11 Changed 6 years ago by viboes

Status: reopenednew

comment:12 Changed 6 years ago by viboes

Status: newassigned

comment:13 Changed 6 years ago by viboes

Summary: Boost::Chrono Assertion at startupBoost::Chrono Assertion at startup - steady_clock::now() - Windows

comment:14 Changed 5 years ago by dmitry@…

I'm getting this assertion from time to time when use asio::steady_timer which in turns uses steady_clock::now(). I've checked under debugger: nanosecs_per_tic is positive number (311.0 in my case), so QueryPerformanceCounter? returns FALSE. GetLastError?() in debugger returns 0, but I'm not sure this is the value set after QueryPerformanceCounter?. Some googling reveals that the argument to this function must be aligned to 64 bit boundary. I've also checked address of the argument - and it looks aligned properly.

No more guesses from me :/

comment:15 Changed 5 years ago by viboes

Thanks for looking on this. Do you think that retrying the call to QueryPerformanceCounter? when fails could help?

comment:16 Changed 5 years ago by andreas.weis@…

We get this problem as well. I can reproduce everything dmitry described on a Windows 7 x64 installation: QueryPerformanceCounter? returns FALSE from time to time, but GetLastError? reports ERROR_SUCCESS. The argument to QueryPerformanceCounter? is aligned properly, and from what the MSDN docs say the function call should not fail, but it does anyway.

It really looks like the assert is too strict in this case. Maybe just retrying the call to QueryPerformanceCounter? will help. As an alternative, I noticed that the chrono implementation shipping with the VC10 standard library uses the GetSystemTimeAsFileTime? API instead of the high performance counters. Maybe those functions are more reliable?

comment:17 Changed 5 years ago by dmitry@…

Andreas, actually using GetSystemTimeAsFileTime? in MSVC STL is a bug. See bug with ID 719443 on Microsoft Connect website (I can't post link here).

Maybe it makes sense to wait until it's implemented and tested by Microsoft, then it can be "backported" to boost::chrono.

Regarding timers on Windows, this article claims that we can't rely on QueryPerformanceCounter? API and should fall back to something different on some motherboard models and versions of Windows

comment:18 Changed 5 years ago by dmitry@…

"This article" in my last post is the article on gamedev.net site called "Timer pitfalls and solutions"

comment:19 Changed 5 years ago by viboes

Please, could you try this patch

diff --git a/include/boost/chrono/detail/inlined/win/chrono.hpp b/include/boost/chrono/detail/inlined/win/chrono.hpp
index 84cac01..e2128d6 100644
--- a/include/boost/chrono/detail/inlined/win/chrono.hpp
+++ b/include/boost/chrono/detail/inlined/win/chrono.hpp
@@ -38,12 +38,19 @@ namespace chrono_detail
     static double nanosecs_per_tic = chrono_detail::get_nanosecs_per_tic();
 
     boost::detail::winapi::LARGE_INTEGER_ pcount;
-    if ( (nanosecs_per_tic <= 0.0L) ||
-            (!boost::detail::winapi::QueryPerformanceCounter( &pcount )) )
+    if ( nanosecs_per_tic <= 0.0L )
     {
-      BOOST_ASSERT(0 && "Boost::Chrono - Internal Error");
+      BOOST_ASSERT(0 && "Boost::Chrono - get_nanosecs_per_tic Internal Error");
       return steady_clock::time_point();
     }
+    unsigned times=0;
+    while ( ! boost::detail::winapi::QueryPerformanceCounter( &pcount ) )
+    {
+      if ( ++times > 3 ) {
+        BOOST_ASSERT(0 && "Boost::Chrono - QueryPerformanceCounter Internal Error");
+        return steady_clock::time_point();
+      }
+    }
 
     return steady_clock::time_point(steady_clock::duration(
       static_cast<steady_clock::rep>((nanosecs_per_tic) * pcount.QuadPart)));

Giving as result

  steady_clock::time_point steady_clock::now() BOOST_NOEXCEPT
  {
    static double nanosecs_per_tic = chrono_detail::get_nanosecs_per_tic();

    boost::detail::winapi::LARGE_INTEGER_ pcount;
    if ( nanosecs_per_tic <= 0.0L )
    {
      BOOST_ASSERT(0 && "Boost::Chrono - get_nanosecs_per_tic Internal Error");
      return steady_clock::time_point();
    }
    unsigned times=0;
    while ( ! boost::detail::winapi::QueryPerformanceCounter( &pcount ) )
    {
      if ( ++times > 3 ) {
        BOOST_ASSERT(0 && "Boost::Chrono - QueryPerformanceCounter Internal Error");
        return steady_clock::time_point();
      }
    }

    return steady_clock::time_point(steady_clock::duration(
      static_cast<steady_clock::rep>((nanosecs_per_tic) * pcount.QuadPart)));
  }

comment:21 Changed 5 years ago by viboes

Milestone: To Be DeterminedBoost 1.56.0

comment:22 Changed 5 years ago by viboes

Resolution: fixed
Status: assignedclosed

comment:23 Changed 4 years ago by dsp@…

I have just downloaded the current boost 1.56.0 beta and I notice that the bug-fix applied to

steady_clock::now()

has not been correspondingly applied to the overload

steady_clock::now(system::error_code&)

which is available when BOOST_CHRONO_DONT_PROVIDE_HYBRID_ERROR_HANDLING is not defined.

I would strongly recommend to apply that patch to this function as well, otherwise the discrimination between error and non-error would be different when using either the first or the second overload

comment:24 Changed 4 years ago by CharlesSavoie

I too hit this assertion on first use once in a while. It seems unlikely that QueryPerformanceCounter? is failing on any modern hardware, or especially that calling it again would solve the problem.

However, the "static double nanosecs_per_tic" is definitely a problem in a multithreaded environment since the return value could be used by one thread before another thread has finished calling the chrono_detail::get_nanosecs_per_tic() function and assigning the value. Static local variables are never to be used in a multithreaded environment, which an MSDN blog post explains. I can't post a link here, so please search for "C++ scoped static initialization is not thread-safe, on purpose!".

I would recommend rethinking this method and all methods that use static local variables.

comment:24 Changed 4 years ago by CharlesSavoie

I too hit this assertion on first use once in a while. It seems unlikely that QueryPerformanceCounter? is failing on any modern hardware, or especially that calling it again would solve the problem.

However, the "static double nanosecs_per_tic" is definitely a problem in a multithreaded environment since the return value could be used by one thread before another thread has finished calling the chrono_detail::get_nanosecs_per_tic() function and assigning the value. Static local variables are never to be used in a multithreaded environment, which an MSDN blog post explains. I can't post a link here, so please search for "C++ scoped static initialization is not thread-safe, on purpose!".

I would recommend rethinking this method and all methods that use static local variables.

comment:25 in reply to:  24 Changed 4 years ago by CharlesSavoie

Apologies for skipping some of the comments before replying; you did say QueryPerformanceCounter? was sometimes returning false on your system. I'll attempt the patch and see if it helps my issue. Again, sorry for assuming otherwise, and for the double post.

comment:26 Changed 4 years ago by viboes

Resolution: fixed
Status: closedreopened

Please, reopen a ticket when you want something to be done :)

comment:27 Changed 4 years ago by viboes

Milestone: Boost 1.56.0To Be Determined

comment:28 Changed 3 years ago by viboes

I don't remember when

static double nanosecs_per_tic

has been removed, but there are no more static in the develop branch.

Please, could you check it?

comment:30 Changed 3 years ago by viboes

Type: BugsSupport Requests

Moved to support until someone respond.

comment:31 Changed 2 years ago by anonymous

I've hit this assertion as well (Boost 1.55, VS 2013, Windows 10 64-bit) by trying to acquire a shared mutex for a limited period of time (1 ms). Here was the callstack:

  1. steady_clock::now()
  2. shared_mutex::try_lock_shared_for()
  3. shared_lock::try_lock_for()

Although obviously not thread-safe, it didn't look to me that the assignment of the return value of chrono_detail::get_nanosecs_per_tic() to the static variable nanosecs_per_tic was the cause of the problem since nanosecs_per_tic had a positive value (about 311) at the time of the assertion.

This implies that the problem must have been with the return value of winapi::QueryPerformanceCounter?() to which I didn't have access.

comment:32 Changed 2 years ago by franz@…

I've hit this assertion as well (Boost 1.55, VS 2013, Windows 10 64-bit) by trying to acquire a shared mutex for a limited period of time (1 ms). Here was the callstack:

  1. steady_clock::now()
  2. shared_mutex::try_lock_shared_for()
  3. shared_lock::try_lock_for()

Although obviously not thread-safe, it didn't look to me that the assignment of the return value of chrono_detail::get_nanosecs_per_tic() to the static variable nanosecs_per_tic was the cause of the problem since nanosecs_per_tic had a positive value (about 311) at the time of the assertion.

This implies that the problem must have been with the return value of winapi::QueryPerformanceCounter?() to which I didn't have access.

comment:33 Changed 16 months ago by viboes

Milestone: To Be Determined
Resolution: fixed
Status: reopenedclosed

This should be fixed since boost 1.56.

Please, reopen it it is still there.

Note: See TracTickets for help on using tickets.