Commit a805c89e authored by Marco Clemencic's avatar Marco Clemencic
Browse files

Counter-based timers (!787)

parents 2da5f327 9be9bb98
...@@ -3,6 +3,8 @@ ...@@ -3,6 +3,8 @@
// ============================================================================ // ============================================================================
// GaudiKernel // GaudiKernel
// ============================================================================ // ============================================================================
#include "Gaudi/Timers.h"
#include "GaudiKernel/RndmGenerators.h" #include "GaudiKernel/RndmGenerators.h"
// ============================================================================ // ============================================================================
// GaudiAlg // GaudiAlg
...@@ -54,15 +56,16 @@ public: ...@@ -54,15 +56,16 @@ public:
private: private:
// counters // counters
mutable StatEntity m_assign_counter{this, "assign"}; mutable StatEntity m_assign_counter{this, "assign"};
mutable StatEntity m_eff_counter{this, "eff"}; mutable StatEntity m_eff_counter{this, "eff"};
mutable StatEntity m_executed_counter{this, "executed"}; mutable StatEntity m_executed_counter{this, "executed"};
mutable StatEntity m_G_counter{this, "G"}; mutable StatEntity m_G_counter{this, "G"};
mutable StatEntity m_g2_counter{this, "g2"}; mutable StatEntity m_g2_counter{this, "g2"};
mutable StatEntity m_gauss_counter{this, "gauss"}; mutable StatEntity m_gauss_counter{this, "gauss"};
mutable StatEntity m_Gneg_counter{this, "Gneg"}; mutable StatEntity m_Gneg_counter{this, "Gneg"};
mutable StatEntity m_Gpos_counter{this, "Gpos"}; mutable StatEntity m_Gpos_counter{this, "Gpos"};
mutable StatEntity m_NG_counter{this, "NG"}; mutable StatEntity m_NG_counter{this, "NG"};
mutable Gaudi::Timer m_timer{this, "time"};
}; };
// ============================================================================ // ============================================================================
...@@ -73,6 +76,7 @@ DECLARE_COMPONENT( CounterNewAlg ) ...@@ -73,6 +76,7 @@ DECLARE_COMPONENT( CounterNewAlg )
// ============================================================================ // ============================================================================
int CounterNewAlg::operator()() const { int CounterNewAlg::operator()() const {
auto timeit = m_timer();
// count overall number of executions: // count overall number of executions:
++m_executed_counter; ++m_executed_counter;
......
...@@ -25,7 +25,7 @@ HistogramPersis...WARNING Histograms saving not required. ...@@ -25,7 +25,7 @@ HistogramPersis...WARNING Histograms saving not required.
ApplicationMgr INFO Application Manager Initialized successfully ApplicationMgr INFO Application Manager Initialized successfully
ApplicationMgr INFO Application Manager Started successfully ApplicationMgr INFO Application Manager Started successfully
Counter INFO Event number 1000 Counter INFO Event number 1000
Counter SUCCESS Number of counters : 9 Counter SUCCESS Number of counters : 10
| Counter | # | sum | mean/eff^* | rms/err^* | min | max | | Counter | # | sum | mean/eff^* | rms/err^* | min | max |
| "G" | 4887 | -82.31362 | -0.016843 | 0.97934 | -3.8263 | 3.4606 | | "G" | 4887 | -82.31362 | -0.016843 | 0.97934 | -3.8263 | 3.4606 |
| "Gneg" | 502 | 502 | 1.0000 | 0.0000 | 1.0000 | 1.0000 | | "Gneg" | 502 | 502 | 1.0000 | 0.0000 | 1.0000 | 1.0000 |
...@@ -38,7 +38,7 @@ Counter SUCCESS Number of counters : 9 ...@@ -38,7 +38,7 @@ Counter SUCCESS Number of counters : 9
| "gauss" | 1000 | -24.66952 | -0.024670 | 0.99675 | -3.1296 | 3.5079 | | "gauss" | 1000 | -24.66952 | -0.024670 | 0.99675 | -3.1296 | 3.5079 |
Counter INFO Efficiency (binomial counter: "eff"): (49.8 +- 1.58113)% Counter INFO Efficiency (binomial counter: "eff"): (49.8 +- 1.58113)%
Counter INFO Event number 2000 Counter INFO Event number 2000
Counter SUCCESS Number of counters : 9 Counter SUCCESS Number of counters : 10
| Counter | # | sum | mean/eff^* | rms/err^* | min | max | | Counter | # | sum | mean/eff^* | rms/err^* | min | max |
| "G" | 9802 | -137.399 | -0.014017 | 0.99570 | -3.8836 | 3.7179 | | "G" | 9802 | -137.399 | -0.014017 | 0.99570 | -3.8836 | 3.7179 |
| "Gneg" | 998 | 998 | 1.0000 | 0.0000 | 1.0000 | 1.0000 | | "Gneg" | 998 | 998 | 1.0000 | 0.0000 | 1.0000 | 1.0000 |
...@@ -51,7 +51,7 @@ Counter SUCCESS Number of counters : 9 ...@@ -51,7 +51,7 @@ Counter SUCCESS Number of counters : 9
| "gauss" | 2000 | 17.20366 | 0.0086018 | 0.97854 | -3.1296 | 3.5079 | | "gauss" | 2000 | 17.20366 | 0.0086018 | 0.97854 | -3.1296 | 3.5079 |
Counter INFO Efficiency (binomial counter: "eff"): (50.1 +- 1.11803)% Counter INFO Efficiency (binomial counter: "eff"): (50.1 +- 1.11803)%
Counter INFO Event number 3000 Counter INFO Event number 3000
Counter SUCCESS Number of counters : 9 Counter SUCCESS Number of counters : 10
| Counter | # | sum | mean/eff^* | rms/err^* | min | max | | Counter | # | sum | mean/eff^* | rms/err^* | min | max |
| "G" | 14691 | -162.8489 | -0.011085 | 0.99656 | -3.8836 | 3.7179 | | "G" | 14691 | -162.8489 | -0.011085 | 0.99656 | -3.8836 | 3.7179 |
| "Gneg" | 1487 | 1487 | 1.0000 | 0.0000 | 1.0000 | 1.0000 | | "Gneg" | 1487 | 1487 | 1.0000 | 0.0000 | 1.0000 | 1.0000 |
...@@ -64,7 +64,7 @@ Counter SUCCESS Number of counters : 9 ...@@ -64,7 +64,7 @@ Counter SUCCESS Number of counters : 9
| "gauss" | 3000 | 28.98501 | 0.0096617 | 0.98310 | -3.1296 | 3.5079 | | "gauss" | 3000 | 28.98501 | 0.0096617 | 0.98310 | -3.1296 | 3.5079 |
Counter INFO Efficiency (binomial counter: "eff"): (50.4333 +- 0.912837)% Counter INFO Efficiency (binomial counter: "eff"): (50.4333 +- 0.912837)%
Counter INFO Event number 4000 Counter INFO Event number 4000
Counter SUCCESS Number of counters : 9 Counter SUCCESS Number of counters : 10
| Counter | # | sum | mean/eff^* | rms/err^* | min | max | | Counter | # | sum | mean/eff^* | rms/err^* | min | max |
| "G" | 19545 | -200.3068 | -0.010248 | 0.99889 | -3.8836 | 3.7179 | | "G" | 19545 | -200.3068 | -0.010248 | 0.99889 | -3.8836 | 3.7179 |
| "Gneg" | 2003 | 2003 | 1.0000 | 0.0000 | 1.0000 | 1.0000 | | "Gneg" | 2003 | 2003 | 1.0000 | 0.0000 | 1.0000 | 1.0000 |
...@@ -77,7 +77,7 @@ Counter SUCCESS Number of counters : 9 ...@@ -77,7 +77,7 @@ Counter SUCCESS Number of counters : 9
| "gauss" | 4000 | -11.09144 | -0.0027729 | 0.99335 | -3.1296 | 3.5079 | | "gauss" | 4000 | -11.09144 | -0.0027729 | 0.99335 | -3.1296 | 3.5079 |
Counter INFO Efficiency (binomial counter: "eff"): (49.925 +- 0.790569)% Counter INFO Efficiency (binomial counter: "eff"): (49.925 +- 0.790569)%
Counter INFO Event number 5000 Counter INFO Event number 5000
Counter SUCCESS Number of counters : 9 Counter SUCCESS Number of counters : 10
| Counter | # | sum | mean/eff^* | rms/err^* | min | max | | Counter | # | sum | mean/eff^* | rms/err^* | min | max |
| "G" | 24446 | -236.0763 | -0.0096571 | 0.99432 | -3.8836 | 3.8273 | | "G" | 24446 | -236.0763 | -0.0096571 | 0.99432 | -3.8836 | 3.8273 |
| "Gneg" | 2506 | 2506 | 1.0000 | 0.0000 | 1.0000 | 1.0000 | | "Gneg" | 2506 | 2506 | 1.0000 | 0.0000 | 1.0000 | 1.0000 |
...@@ -90,7 +90,7 @@ Counter SUCCESS Number of counters : 9 ...@@ -90,7 +90,7 @@ Counter SUCCESS Number of counters : 9
| "gauss" | 5000 | -4.027803 |-0.00080556 | 0.99622 | -3.6235 | 3.5079 | | "gauss" | 5000 | -4.027803 |-0.00080556 | 0.99622 | -3.6235 | 3.5079 |
Counter INFO Efficiency (binomial counter: "eff"): (49.88 +- 0.707105)% Counter INFO Efficiency (binomial counter: "eff"): (49.88 +- 0.707105)%
ApplicationMgr INFO Application Manager Stopped successfully ApplicationMgr INFO Application Manager Stopped successfully
Counter SUCCESS Number of counters : 9 Counter SUCCESS Number of counters : 10
| Counter | # | sum | mean/eff^* | rms/err^* | min | max | | Counter | # | sum | mean/eff^* | rms/err^* | min | max |
| "G" | 26490 | -326.309 | -0.012318 | 0.99484 | -3.8836 | 3.8273 | | "G" | 26490 | -326.309 | -0.012318 | 0.99484 | -3.8836 | 3.8273 |
| "Gneg" | 2712 | 2712 | 1.0000 | 0.0000 | 1.0000 | 1.0000 | | "Gneg" | 2712 | 2712 | 1.0000 | 0.0000 | 1.0000 | 1.0000 |
......
...@@ -168,6 +168,9 @@ gaudi_add_unit_test(test_compose tests/src/test_compose.cpp ...@@ -168,6 +168,9 @@ gaudi_add_unit_test(test_compose tests/src/test_compose.cpp
gaudi_add_unit_test(test_reverse tests/src/test_reverse.cpp gaudi_add_unit_test(test_reverse tests/src/test_reverse.cpp
LINK_LIBRARIES GaudiKernel LINK_LIBRARIES GaudiKernel
TYPE Boost) TYPE Boost)
gaudi_add_unit_test(test_GaudiTimer tests/src/test_GaudiTimer.cpp
LINK_LIBRARIES GaudiKernel
TYPE Boost)
gaudi_add_compile_test(test_StatusCodeFail tests/src/test_StatusCode_fail.cxx gaudi_add_compile_test(test_StatusCodeFail tests/src/test_StatusCode_fail.cxx
ERRORS "FAIL01;FAIL02;FAIL03;FAIL04") ERRORS "FAIL01;FAIL02;FAIL03;FAIL04")
......
#pragma once
#include "Gaudi/Timers/GenericTimer.h"
#include "Gaudi/Timers/RdtscClock.h"
#include <chrono>
namespace Gaudi {
/**
* Default timer using a standard clock with microsecond precision
*
* \see Gaudi::Timers::GenericTimer
*/
using Timer = Timers::GenericTimer<std::chrono::high_resolution_clock, std::chrono::microseconds>;
/**
* Fast RDTSC-based timer with microsecond precision
*
* \see Gaudi::Timers::GenericTimer
* \see Gaudi::Timers::RdtscClock
*/
using FastTimer = Timers::GenericTimer<Timers::RdtscClock<std::chrono::microseconds>, std::chrono::microseconds>;
} // namespace Gaudi
#pragma once
#include "Gaudi/Chrono/Counters.h"
#include <atomic>
#include <chrono>
namespace Gaudi {
namespace Timers {
/**
* A generic timer based on std::chrono and Gaudi::Accumulators
*
* The timer is templated with a std::chrono compatible clock and the Unit
* of precision (ms, us, ...). It accumulates all time measurements in a
* Gaudi::Accumulators::StatCounter. A time measurement is done via the RAII helper
* class created by calling operator().
*
* Usually one would use one of the predefined Timer types from Gaudi/Timers.h:
*
* @code
* // .h
* Gaudi::Timer m_timer;
*
* // .cpp
* {
* auto timeit = m_timer();
* // code to be timed
* }
* info() << m_timer.stats() << endmsg;
* @endcode
*/
template <typename Clock, typename Unit>
class GenericTimer {
public:
/// Type of Counter used for accumulating time measurements
typedef Gaudi::Accumulators::StatCounter<Unit> Stats_t;
/**
* A scoped timer that starts/stops on con/de-struction
*/
class ScopeTimer {
public:
/// Start Scoped timer accumulating into stat
ScopeTimer( Stats_t& stat ) : m_stats( stat ), m_t0( Clock::now() ) {}
/// Destructor stopping timer
~ScopeTimer() { stop(); }
/// Return the elapsed time without stopping the timer
/// @return std::chrono::duration<Unit>
auto elapsed() const {
// Fenced according to https://codereview.stackexchange.com/q/196245
std::atomic_thread_fence( std::memory_order_relaxed );
auto dt = Clock::now() - m_t0;
std::atomic_thread_fence( std::memory_order_relaxed );
return std::chrono::duration_cast<Unit>( dt );
}
private:
/// Stop the timer, accumulate elapsed time and return current measurement
void stop() const { m_stats += elapsed(); }
Stats_t& m_stats; ///< reference to statistics counter
typename Clock::time_point m_t0; ///< start time of timer
};
/// Default constructor
GenericTimer() = default;
/// Constructor attaching the statistics counter to an owner
template <class OWNER>
GenericTimer( OWNER* o, const std::string& name ) {
o->declareCounter( name, m_stats );
}
/// No copy
GenericTimer( const GenericTimer& ) = delete;
/// Create (and start) a ScopeTimer
[[nodiscard]] auto operator()() const { return ScopeTimer( m_stats ); }
/// Return accumulated timing statistics
const Stats_t& stats() const { return m_stats; }
private:
mutable Stats_t m_stats; ///< statistics counter
};
} // namespace Timers
} // namespace Gaudi
#pragma once
#include <chrono>
#include <functional>
#include <ratio>
#include <thread>
#include <x86intrin.h>
namespace Gaudi {
namespace Timers {
/**
* @brief A std::chrono compatible Clock using rdtsc as its timing source
*
* This clock is not directly related to wall time but meant as a low-overhead
* time interval measurement. The Precision template parameter determines the
* internal precision of the clock (e.g. `std::milli`, `std::micro`). On first
* invocation of `now()` the timer is calibrated against a wall-time clock,
* which will have an overhead of several milliseconds. This can be avoided by
* calling `calibrate()` explicitly before the first measurement.
*
*/
template <typename Precision = std::chrono::microseconds>
class RdtscClock {
public:
// to meet requirements of TrivialClock:
typedef typename Precision::rep rep;
typedef typename Precision::period period;
typedef std::chrono::duration<rep, period> duration;
typedef std::chrono::time_point<RdtscClock> time_point;
static constexpr bool is_steady{true};
// some sanity checks:
static_assert( period::num == 1, "The Precision of RdtscClock must be reducible to 1/N" );
static_assert( std::ratio_less_equal<period, std::milli>(),
"The Precision of RdtscClock must be at least std::chrono::milliseconds" );
/// Calibrate the RDTSC clock against wall time
static rep calibrate() noexcept { return ticks_per_unit(); }
static time_point now() noexcept { return time_point{duration( __rdtsc() / ticks_per_unit() )}; }
private:
static rep ticks_per_unit() noexcept {
static rep ticks_per_unit = do_calibrate(); // local static guarantees thread-safety
return ticks_per_unit;
}
static rep do_calibrate() noexcept {
// Calibration time and conversion factor to unit of Precision
static constexpr auto calibTime = std::chrono::milliseconds( 100 );
static constexpr auto toPrec = std::ratio_divide<std::milli, period>::num;
// Calibrate against wall clock
auto t1_ref = std::chrono::high_resolution_clock::now();
auto t1 = __rdtsc();
std::this_thread::sleep_for( calibTime );
auto t2 = __rdtsc();
auto t2_ref = std::chrono::high_resolution_clock::now();
// Calculate ticks per unit of Precision
auto dt_ref = std::chrono::duration_cast<std::chrono::milliseconds>( t2_ref - t1_ref ).count();
rep ticks_per_unit = ( t2 - t1 ) / ( dt_ref * toPrec );
return ticks_per_unit;
}
};
} // namespace Timers
} // namespace Gaudi
#define BOOST_TEST_DYN_LINK
#define BOOST_TEST_MODULE test_GaudiTimer
#include <boost/test/unit_test.hpp>
#include <chrono>
#include <string>
#include <thread>
#include "Gaudi/Timers.h"
// Measure same time interval with different clocks
BOOST_AUTO_TEST_CASE( timer ) {
Gaudi::Timer timerA;
Gaudi::FastTimer timerB;
{
auto t1 = timerA();
auto t2 = timerB();
std::this_thread::sleep_for( std::chrono::milliseconds( 10 ) );
}
{
auto t1 = timerA();
auto t2 = timerB();
std::this_thread::sleep_for( std::chrono::milliseconds( 20 ) );
}
std::cout << "timerA: " << timerA.stats() << std::endl;
std::cout << "timerB: " << timerB.stats() << std::endl;
}
// Measure timer overhead
template <typename T>
void perfTimer( const std::string& label, int N ) {
T timerA;
Gaudi::Timer timeit;
{
auto twall = timeit();
for ( int i = 0; i < N; ++i ) { auto t = timerA(); }
}
std::cout << std::left << std::setw( 20 ) << label << timeit.stats().mean() << " us per " << N << " calls"
<< std::endl;
}
BOOST_AUTO_TEST_CASE( timer_overhead ) {
const int N = 10000;
perfTimer<Gaudi::Timer>( "Gaudi::Timer", N );
perfTimer<Gaudi::FastTimer>( "Gaudi::FastTimer", N );
}
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment