dn724/dncurrency
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages 1 Wiki Activity Actions

Timer utilities (#1526)

Browse source 
* Timer utilities

* Add tests, fix enum class and better enable_if usage
This commit is contained in:
cryptocode 2019-01-08 00:46:58 +01:00 • committed by Zach Hyatt
commit 6736141d84
5 changed files with 338 additions and 15 deletions
Download patch file Download diff file Expand all files Collapse all files

1
nano/core_test/CMakeLists.txt
View file

@ -16,6 +16,7 @@ add_executable (core_test
peer_container.cpp
rpc.cpp
signing.cpp
timer.cpp
uint256_union.cpp
versioning.cpp
wallet.cpp

70
nano/core_test/timer.cpp Normal file
View file

@ -0,0 +1,70 @@
#include <chrono>
#include <gtest/gtest.h>
#include <nano/core_test/testutil.hpp>
#include <nano/lib/timer.hpp>
#include <thread>
/* 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<std::chrono::milliseconds> 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<std::chrono::milliseconds> 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<std::chrono::milliseconds> 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<std::chrono::milliseconds> 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);
}

1
nano/lib/CMakeLists.txt
View file

@ -24,6 +24,7 @@ add_library (nano_lib
interface.h
numbers.cpp
numbers.hpp
timer.hpp
utility.cpp
utility.hpp
work.hpp

257
nano/lib/timer.hpp Normal file
View file

@ -0,0 +1,257 @@
#pragma once
namespace nano
{
enum class timer_state
{
started,
stopped
};
/** Timer utility with nesting support */
template <typename UNIT = std::chrono::milliseconds>
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<UNIT> (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<UNIT> (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<UNIT> (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<UNIT> (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<double> (ticks.count ()) / static_cast<double> (measurements) << ' ' << unit () << " avg)";
}
stream_a << std::endl;
}
}
/** Returns the SI unit string */
std::string unit () const
{
return typed_unit<UNIT> ();
}
nano::timer_state current_state () const
{
return state;
}
private:
timer * parent{ nullptr };
std::vector<timer> children;
nano::timer_state state{ nano::timer_state::stopped };
std::string desc;
std::chrono::time_point<std::chrono::high_resolution_clock> begin;
UNIT ticks{ 0 };
UNIT minimum{ UNIT::zero () };
unsigned measurements{ 0 };
template <typename U, std::enable_if_t<std::is_same<U, std::chrono::nanoseconds>::value> * = nullptr>
std::string typed_unit () const
{
return "nanoseconds";
}
template <typename U, std::enable_if_t<std::is_same<U, std::chrono::microseconds>::value> * = nullptr>
std::string typed_unit () const
{
return "microseconds";
}
template <typename U, std::enable_if_t<std::is_same<U, std::chrono::milliseconds>::value> * = nullptr>
std::string typed_unit () const
{
return "milliseconds";
}
template <typename U, std::enable_if_t<std::is_same<U, std::chrono::seconds>::value> * = nullptr>
std::string typed_unit () const
{
return "seconds";
}
template <typename U, std::enable_if_t<std::is_same<U, std::chrono::minutes>::value> * = nullptr>
std::string typed_unit () const
{
return "minutes";
}
template <typename U, std::enable_if_t<std::is_same<U, std::chrono::hours>::value> * = nullptr>
std::string typed_unit () const
{
return "hours";
}
};
/**
* The autotimer starts on construction, and stops and prints on destruction.
*/
template <typename UNIT = std::chrono::milliseconds>
class autotimer : public nano::timer<UNIT>
{
public:
autotimer (std::string description_a, std::ostream & stream_a = std::cout) :
nano::timer<UNIT> (description_a), stream (stream_a)
{
nano::timer<UNIT>::start ();
}
~autotimer ()
{
nano::timer<UNIT>::stop (stream);
}
private:
std::ostream & stream;
};
}

24
nano/node/node.cpp
View file

@ -1,6 +1,7 @@
#include <nano/node/node.hpp>
#include <nano/lib/interface.h>
#include <nano/lib/timer.hpp>
#include <nano/lib/utility.hpp>
#include <nano/node/common.hpp>
#include <nano/node/rpc.hpp>
@ -1301,7 +1302,7 @@ bool nano::block_processor::have_blocks ()
void nano::block_processor::verify_state_blocks (std::unique_lock<std::mutex> & lock_a, size_t max_count)
{
assert (!mutex.try_lock ());
auto start_time (std::chrono::steady_clock::now ());
nano::timer<std::chrono::milliseconds> timer_l (nano::timer_state::started);
std::deque<std::pair<std::shared_ptr<nano::block>, std::chrono::steady_clock::time_point>> items;
if (max_count == std::numeric_limits<size_t>::max () || max_count >= state_blocks.size ())
{
@ -1354,31 +1355,28 @@ void nano::block_processor::verify_state_blocks (std::unique_lock<std::mutex> &
}
if (node.config.logging.timing_logging ())
{
auto end_time (std::chrono::steady_clock::now ());
auto elapsed_time_ms (std::chrono::duration_cast<std::chrono::milliseconds> (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<std::mutex> & lock_a)
{
nano::timer<std::chrono::milliseconds> 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<std::mutex> & lock_a
if (node.config.logging.timing_logging ())
{
auto end_time (std::chrono::steady_clock::now ());
auto elapsed_time_ms (std::chrono::duration_cast<std::chrono::milliseconds> (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 ());
}
}