From 6736141d845b4385dec005285ddd5bbc3c220ca1 Mon Sep 17 00:00:00 2001 From: cryptocode <34946442+cryptocode@users.noreply.github.com> Date: Tue, 8 Jan 2019 00:46:58 +0100 Subject: [PATCH] Timer utilities (#1526) * Timer utilities * Add tests, fix enum class and better enable_if usage --- nano/core_test/CMakeLists.txt | 1 + nano/core_test/timer.cpp | 70 +++++++++ nano/lib/CMakeLists.txt | 1 + nano/lib/timer.hpp | 257 ++++++++++++++++++++++++++++++++++ nano/node/node.cpp | 24 ++-- 5 files changed, 338 insertions(+), 15 deletions(-) create mode 100644 nano/core_test/timer.cpp create mode 100644 nano/lib/timer.hpp diff --git a/nano/core_test/CMakeLists.txt b/nano/core_test/CMakeLists.txt index c5ad3a487..33c49ce40 100644 --- a/nano/core_test/CMakeLists.txt +++ b/nano/core_test/CMakeLists.txt @@ -16,6 +16,7 @@ add_executable (core_test peer_container.cpp rpc.cpp signing.cpp + timer.cpp uint256_union.cpp versioning.cpp wallet.cpp diff --git a/nano/core_test/timer.cpp b/nano/core_test/timer.cpp new file mode 100644 index 000000000..400e2f837 --- /dev/null +++ b/nano/core_test/timer.cpp @@ -0,0 +1,70 @@ +#include +#include +#include +#include +#include + +/* Tests for the timer utility. Note that we use sleep_for in the tests, which + sleeps for *at least* the given amount. We thus allow for some leeway in the + upper bound checks (also because CI is often very slow) */ + +TEST (timer, states) +{ + nano::timer t1; + ASSERT_EQ (t1.current_state (), nano::timer_state::stopped); + t1.start (); + ASSERT_EQ (t1.current_state (), nano::timer_state::started); + t1.restart (); + ASSERT_EQ (t1.current_state (), nano::timer_state::started); + t1.pause (); + ASSERT_EQ (t1.current_state (), nano::timer_state::stopped); + t1.start (); + ASSERT_EQ (t1.current_state (), nano::timer_state::started); + t1.stop (); + ASSERT_EQ (t1.current_state (), nano::timer_state::stopped); + + nano::timer t2 (nano::timer_state::started); + ASSERT_EQ (t2.current_state (), nano::timer_state::started); + t2.stop (); + ASSERT_EQ (t2.current_state (), nano::timer_state::stopped); +} + +TEST (timer, measure_and_compare) +{ + using namespace std::chrono_literals; + nano::timer t1 (nano::timer_state::started); + ASSERT_EQ (t1.current_state (), nano::timer_state::started); + std::this_thread::sleep_for (50ms); + ASSERT_TRUE (t1.after_deadline (30ms)); + ASSERT_TRUE (t1.before_deadline (500ms)); + ASSERT_LT (t1.since_start (), 200ms); + ASSERT_GT (t1.since_start (), 10ms); + ASSERT_GE (t1.stop (), 50ms); +} + +TEST (timer, cummulative_child) +{ + using namespace std::chrono_literals; + nano::timer t1 (nano::timer_state::started); + auto & child1 = t1.child (); + for (int i = 0; i < 10; i++) + { + child1.start (); + std::this_thread::sleep_for (5ms); + child1.pause (); + } + ASSERT_GE (child1.value (), 50ms); + ASSERT_LT (child1.value (), 500ms); + + auto & child2 = t1.child (); + for (int i = 0; i < 10; i++) + { + child2.start (); + std::this_thread::sleep_for (5ms); + child2.pause (); + } + ASSERT_GE (child2.value (), 50ms); + ASSERT_LT (child2.value (), 500ms); + + ASSERT_GT (t1.stop (), 100ms); +} diff --git a/nano/lib/CMakeLists.txt b/nano/lib/CMakeLists.txt index bbaa87884..5723c9649 100644 --- a/nano/lib/CMakeLists.txt +++ b/nano/lib/CMakeLists.txt @@ -24,6 +24,7 @@ add_library (nano_lib interface.h numbers.cpp numbers.hpp + timer.hpp utility.cpp utility.hpp work.hpp diff --git a/nano/lib/timer.hpp b/nano/lib/timer.hpp new file mode 100644 index 000000000..c5ddf9a2e --- /dev/null +++ b/nano/lib/timer.hpp @@ -0,0 +1,257 @@ +#pragma once + +namespace nano +{ +enum class timer_state +{ + started, + stopped +}; + +/** Timer utility with nesting support */ +template +class timer +{ +public: + timer () = default; + + timer (nano::timer_state state_a, std::string description_a = "timer") : + desc (description_a) + { + if (state_a == nano::timer_state::started) + { + start (); + } + } + + timer (std::string description_a) : + desc (description_a) + { + } + + timer (std::string description_a, timer * parent_a) : + desc (description_a), parent (parent_a) + { + } + + /** Do not output if measured time is below the time units threshold in \p minimum_a */ + timer & set_minimum (UNIT minimum_a) + { + minimum = minimum_a; + return *this; + } + + /** + * Create a child timer without starting it. + * Since the timing API needs to have low overhead, this function + * does not check if a timer with the same name already exists. + */ + timer & child (std::string description_a = "child timer") + { + children.emplace_back (description_a, this); + return children.back (); + } + + /** Create and start a child timer */ + timer & start_child (std::string description_a = "child timer") + { + auto & child_timer = child (description_a); + child_timer.start (); + return child_timer; + } + + /** Start the timer. This will assert if the timer is already started. */ + void start () + { + assert (state == nano::timer_state::stopped); + state = nano::timer_state::started; + begin = std::chrono::high_resolution_clock::now (); + } + + /** Restarts the timer */ + void restart () + { + state = nano::timer_state::started; + begin = std::chrono::high_resolution_clock::now (); + ticks = UNIT::zero (); + measurements = 0; + } + + /** + * Stops the timer and increases the measurement count. A timer can be started and paused + * multiple times (e.g. in a loop). + * @return duration + */ + UNIT pause () + { + ++measurements; + return stop (); + } + + /** + * Stop timer + * @return duration + */ + UNIT stop () + { + assert (state == nano::timer_state::started); + state = nano::timer_state::stopped; + + auto end = std::chrono::high_resolution_clock::now (); + ticks += std::chrono::duration_cast (end - begin); + return ticks; + } + + /** + * Return current units. + */ + UNIT value () + { + return ticks; + } + + /** Returns the duration in UNIT since the timer was last started. */ + UNIT since_start () + { + auto end = std::chrono::high_resolution_clock::now (); + return std::chrono::duration_cast (end - begin); + } + + /** Returns true if the timer was last started longer than \p duration_a units ago*/ + bool after_deadline (UNIT duration_a) + { + auto end = std::chrono::high_resolution_clock::now (); + return std::chrono::duration_cast (end - begin) > duration_a; + } + + /** Returns true if the timer was last started shorter than \p duration_a units ago*/ + bool before_deadline (UNIT duration_a) + { + auto end = std::chrono::high_resolution_clock::now (); + return std::chrono::duration_cast (end - begin) < duration_a; + } + + /** Stop timer and write measurements to \p output_a */ + void stop (std::string & output_a) + { + std::ostringstream stream; + stop (stream); + output_a = stream.str (); + } + + /** Stop timer and write measurements to \p stream_a */ + void stop (std::ostream & stream_a) + { + stop (); + print (stream_a); + } + + /** Print measurements to the \p stream_a */ + void print (std::ostream & stream_a) + { + if (ticks >= minimum) + { + // Print cumulative children first. Non-cumulative children prints directly. + for (auto & child : children) + { + if (child.measurements > 0) + { + child.print (stream_a); + } + } + + auto current_parent = parent; + while (current_parent) + { + stream_a << parent->desc << "."; + current_parent = current_parent->parent; + } + + stream_a << desc << ": " << ticks.count () << ' ' << unit (); + if (measurements > 0) + { + stream_a << " (" << measurements << " measurements, " << std::setprecision (2) << std::fixed << static_cast (ticks.count ()) / static_cast (measurements) << ' ' << unit () << " avg)"; + } + stream_a << std::endl; + } + } + + /** Returns the SI unit string */ + std::string unit () const + { + return typed_unit (); + } + + nano::timer_state current_state () const + { + return state; + } + +private: + timer * parent{ nullptr }; + std::vector children; + nano::timer_state state{ nano::timer_state::stopped }; + std::string desc; + std::chrono::time_point begin; + UNIT ticks{ 0 }; + UNIT minimum{ UNIT::zero () }; + unsigned measurements{ 0 }; + + template ::value> * = nullptr> + std::string typed_unit () const + { + return "nanoseconds"; + } + + template ::value> * = nullptr> + std::string typed_unit () const + { + return "microseconds"; + } + + template ::value> * = nullptr> + std::string typed_unit () const + { + return "milliseconds"; + } + + template ::value> * = nullptr> + std::string typed_unit () const + { + return "seconds"; + } + + template ::value> * = nullptr> + std::string typed_unit () const + { + return "minutes"; + } + + template ::value> * = nullptr> + std::string typed_unit () const + { + return "hours"; + } +}; + +/** + * The autotimer starts on construction, and stops and prints on destruction. + */ +template +class autotimer : public nano::timer +{ +public: + autotimer (std::string description_a, std::ostream & stream_a = std::cout) : + nano::timer (description_a), stream (stream_a) + { + nano::timer::start (); + } + ~autotimer () + { + nano::timer::stop (stream); + } + +private: + std::ostream & stream; +}; +} diff --git a/nano/node/node.cpp b/nano/node/node.cpp index 465d3c36a..2420bcfe3 100644 --- a/nano/node/node.cpp +++ b/nano/node/node.cpp @@ -1,6 +1,7 @@ #include #include +#include #include #include #include @@ -1301,7 +1302,7 @@ bool nano::block_processor::have_blocks () void nano::block_processor::verify_state_blocks (std::unique_lock & lock_a, size_t max_count) { assert (!mutex.try_lock ()); - auto start_time (std::chrono::steady_clock::now ()); + nano::timer timer_l (nano::timer_state::started); std::deque, std::chrono::steady_clock::time_point>> items; if (max_count == std::numeric_limits::max () || max_count >= state_blocks.size ()) { @@ -1354,31 +1355,28 @@ void nano::block_processor::verify_state_blocks (std::unique_lock & } if (node.config.logging.timing_logging ()) { - auto end_time (std::chrono::steady_clock::now ()); - auto elapsed_time_ms (std::chrono::duration_cast (end_time - start_time)); - auto elapsed_time_ms_int (elapsed_time_ms.count ()); - - BOOST_LOG (node.log) << boost::str (boost::format ("Batch verified %1% state blocks in %2% milliseconds") % size % elapsed_time_ms_int); + BOOST_LOG (node.log) << boost::str (boost::format ("Batch verified %1% state blocks in %2% %3%") % size % timer_l.stop ().count () % timer_l.unit ()); } } void nano::block_processor::process_batch (std::unique_lock & lock_a) { + nano::timer timer_l; lock_a.lock (); - auto start_time (std::chrono::steady_clock::now ()); + timer_l.start (); // Limit state blocks verification time - while (!state_blocks.empty () && std::chrono::steady_clock::now () - start_time < std::chrono::seconds (2)) + while (!state_blocks.empty () && timer_l.before_deadline (std::chrono::seconds (2))) { verify_state_blocks (lock_a, 2048); } lock_a.unlock (); auto transaction (node.store.tx_begin_write ()); - start_time = std::chrono::steady_clock::now (); + timer_l.restart (); lock_a.lock (); // Processing blocks auto first_time (true); unsigned number_of_blocks_processed (0), number_of_forced_processed (0); - while ((!blocks.empty () || !forced.empty ()) && std::chrono::steady_clock::now () - start_time < node.config.block_processor_batch_max_time) + while ((!blocks.empty () || !forced.empty ()) && timer_l.before_deadline (node.config.block_processor_batch_max_time)) { auto log_this_record (false); if (node.config.logging.timing_logging ()) @@ -1446,11 +1444,7 @@ void nano::block_processor::process_batch (std::unique_lock & lock_a if (node.config.logging.timing_logging ()) { - auto end_time (std::chrono::steady_clock::now ()); - auto elapsed_time_ms (std::chrono::duration_cast (end_time - start_time)); - auto elapsed_time_ms_int (elapsed_time_ms.count ()); - - BOOST_LOG (node.log) << boost::str (boost::format ("Processed %1% blocks (%2% blocks were forced) in %3% milliseconds") % number_of_blocks_processed % number_of_forced_processed % elapsed_time_ms_int); + BOOST_LOG (node.log) << boost::str (boost::format ("Processed %1% blocks (%2% blocks were forced) in %3% %4%") % number_of_blocks_processed % number_of_forced_processed % timer_l.stop ().count () % timer_l.unit ()); } }