[Boost-commit] svn:boost r85206 - in trunk/libs/log: doc src

Subject: [Boost-commit] svn:boost r85206 - in trunk/libs/log: doc src
From: andrey.semashev_at_[hidden]
Date: 2013-08-04 09:48:23

Author: andysem
Date: 2013-08-04 09:48:22 EDT (Sun, 04 Aug 2013)
New Revision: 85206
URL: http://svn.boost.org/trac/boost/changeset/85206

Log:
Fixed timer attribute generating incorrect time readings on Windows on heavy thread contention when QueryPerformanceCounter API was used.

Text files modified: 
   trunk/libs/log/doc/changelog.qbk |     5 +++                                     
   trunk/libs/log/doc/log.qbk       |     2 +                                       
   trunk/libs/log/src/timer.cpp     |    52 ++++++++++++--------------------------- 
   3 files changed, 23 insertions(+), 36 deletions(-)

Modified: trunk/libs/log/doc/changelog.qbk
==============================================================================
--- trunk/libs/log/doc/changelog.qbk	Sun Aug  4 04:19:13 2013	(r85205)
+++ trunk/libs/log/doc/changelog.qbk	2013-08-04 09:48:22 EDT (Sun, 04 Aug 2013)	(r85206)
@@ -16,6 +16,11 @@
 * Added a new configuration macro `BOOST_LOG_WITHOUT_DEFAULT_FACTORIES`. By defining this macro the user can disable compilation of the default filter and formatter factories used by settings parsers. This can substantially reduce binary sizes while still retaining support for settings parsers. Note that when this macro is defined the user will have to register _all_ attributes in the library.
 * Rewritten some of the parsers to reduce the compiled binary size.
 
+[*Bug fixes:]
+
+* Fixed [link log.detailed.attributes.timer `timer`] attribute generating incorrect time readings on Windows on heavy thread contention when `QueryPerformanceCounter` API was used.
+* Closed tickets: [ticket 8815], [ticket 8819], [ticket 8915], [ticket 8917].
+
 [heading 2.1, Boost 1.54]
 
 [*Breaking changes:]

Modified: trunk/libs/log/doc/log.qbk
==============================================================================
--- trunk/libs/log/doc/log.qbk	Sun Aug  4 04:19:13 2013	(r85205)
+++ trunk/libs/log/doc/log.qbk	2013-08-04 09:48:22 EDT (Sun, 04 Aug 2013)	(r85206)
@@ -48,6 +48,8 @@
 [def __boost_locale__ [@http://www.boost.org/doc/libs/release/libs/locale/doc/html/index.html Boost.Locale]]
 [def __boost_quickbook__ [@http://www.boost.org/doc/libs/release/doc/html/quickbook.html Boost.Quickbook]]
 
+[template ticket[key] '''<ulink url="https://svn.boost.org/trac/boost/ticket/'''[key]'''">#'''[key]'''</ulink>''']
+
 [/ Auto-generated macros that refer to Reference sections /]
 [include top_level_reference.qbk]
 [include core_reference.qbk]

Modified: trunk/libs/log/src/timer.cpp
==============================================================================
--- trunk/libs/log/src/timer.cpp	Sun Aug  4 04:19:13 2013	(r85205)
+++ trunk/libs/log/src/timer.cpp	2013-08-04 09:48:22 EDT (Sun, 04 Aug 2013)	(r85206)
@@ -24,8 +24,11 @@
 #include <boost/assert.hpp>
 #include <boost/cstdint.hpp>
 #include <boost/detail/interlocked.hpp>
+#include <boost/log/detail/config.hpp>
+#if !defined(BOOST_LOG_NO_THREADS)
 #include <boost/log/detail/locks.hpp>
-#include <boost/log/detail/spin_mutex.hpp>
+#include <boost/thread/mutex.hpp>
+#endif
 #include <windows.h>
 #include <boost/log/detail/header.hpp>
 
@@ -42,12 +45,12 @@
 private:
 #if !defined(BOOST_LOG_NO_THREADS)
     //! Synchronization mutex type
-    typedef log::aux::spin_mutex mutex_type;
+    typedef boost::mutex mutex_type;
     //! Synchronization mutex
     mutex_type m_Mutex;
 #endif
     //! Frequency factor for calculating duration
-    uint64_t m_FrequencyFactor;
+    double m_FrequencyFactor;
     //! Last value of the performance counter
     uint64_t m_LastCounter;
     //! Elapsed time duration, in microseconds
@@ -60,7 +63,7 @@
         LARGE_INTEGER li;
         QueryPerformanceFrequency(&li);
         BOOST_ASSERT(li.QuadPart != 0LL);
-        m_FrequencyFactor = static_cast< uint64_t >(li.QuadPart) / 1000000ULL;
+        m_FrequencyFactor = 1000000.0 / static_cast< double >(li.QuadPart);
 
         QueryPerformanceCounter(&li);
         m_LastCounter = static_cast< uint64_t >(li.QuadPart);
@@ -69,43 +72,20 @@
     //! The method returns the actual attribute value. It must not return NULL.
     attribute_value get_value()
     {
-        LARGE_INTEGER li;
-        QueryPerformanceCounter(&li);
-
         uint64_t duration;
         {
-            BOOST_LOG_EXPR_IF_MT(log::aux::exclusive_lock_guard< mutex_type > _(m_Mutex);)
+            BOOST_LOG_EXPR_IF_MT(log::aux::exclusive_lock_guard< mutex_type > lock(m_Mutex);)
 
-            const uint64_t counts = static_cast< uint64_t >(li.QuadPart) - m_LastCounter;
-            m_LastCounter = static_cast< uint64_t >(li.QuadPart);
-            m_Duration += counts / m_FrequencyFactor;
-            duration = m_Duration;
-        }
-
-        // All these dances are needed simply to construct Boost.DateTime duration without truncating the value
-        value_type res;
-        if (duration < static_cast< uint64_t >((std::numeric_limits< value_type::fractional_seconds_type >::max)()))
-        {
-            res = value_type(0, 0, 0, static_cast< value_type::fractional_seconds_type >(
-                duration * (1000000 / value_type::traits_type::ticks_per_second)));
-        }
-        else
-        {
-            uint64_t total_seconds = duration / 1000000ULL;
-            value_type::fractional_seconds_type usec = static_cast< value_type::fractional_seconds_type >(duration % 1000000ULL);
-            if (total_seconds < static_cast< uint64_t >((std::numeric_limits< value_type::sec_type >::max)()))
-            {
-                res = value_type(0, 0, static_cast< value_type::sec_type >(total_seconds), usec);
-            }
-            else
-            {
-                uint64_t total_hours = total_seconds / 3600ULL;
-                value_type::sec_type seconds = static_cast< value_type::sec_type >(total_seconds % 3600ULL);
-                res = value_type(static_cast< value_type::hour_type >(total_hours), 0, seconds, usec);
-            }
+            LARGE_INTEGER li;
+            QueryPerformanceCounter(&li);
+            const uint64_t counter = static_cast< uint64_t >(li.QuadPart);
+            const uint64_t counts = counter - m_LastCounter;
+            m_LastCounter = counter;
+            duration = m_Duration + static_cast< uint64_t >(counts * m_FrequencyFactor);
+            m_Duration = duration;
         }
 
-        return attribute_value(new attribute_value_impl< value_type >(res));
+        return attribute_value(new attribute_value_impl< value_type >(boost::posix_time::microseconds(duration)));
     }
 };