diff --git a/rai/node/node.cpp b/rai/node/node.cpp index 03374d26..3ae5b037 100644 --- a/rai/node/node.cpp +++ b/rai/node/node.cpp @@ -783,6 +783,12 @@ thread ([this]() { void rai::vote_processor::process_loop () { + std::chrono::steady_clock::time_point start_time, end_time; + std::chrono::steady_clock::duration elapsed_time; + std::chrono::milliseconds elapsed_time_ms; + uint64_t elapsed_time_ms_int; + bool log_this_iteration; + std::unique_lock lock (mutex); started = true; condition.notify_all (); @@ -792,6 +798,17 @@ void rai::vote_processor::process_loop () { std::deque, rai::endpoint>> votes_l; votes_l.swap (votes); + + log_this_iteration = false; + if (node.config.logging.network_logging () && votes_l.size () > 50) + { + /* + * Only log the timing information for this iteration if + * there are a sufficient number of items for it to be relevant + */ + log_this_iteration = true; + start_time = std::chrono::steady_clock::now (); + } active = true; lock.unlock (); { @@ -804,6 +821,24 @@ void rai::vote_processor::process_loop () lock.lock (); active = false; condition.notify_all (); + + if (log_this_iteration) + { + end_time = std::chrono::steady_clock::now (); + elapsed_time = end_time - start_time; + elapsed_time_ms = std::chrono::duration_cast (elapsed_time); + elapsed_time_ms_int = elapsed_time_ms.count (); + + if (elapsed_time_ms_int < 100) + { + /* + * If the time spent was less than 100ms then + * the results are probably not useful as well, + * so don't spam the logs. + */ + BOOST_LOG (node.log) << boost::str (boost::format ("Processed %1% votes in %2% milliseconds (rate of %3% votes per second)") % votes_l.size () % elapsed_time_ms_int % ((votes_l.size () * 1000ULL) / elapsed_time_ms_int)); + } + } } else {