Log vote processing time (#1344)

This commit is contained in:
Roy Keene 2018-11-14 11:35:35 -06:00 committed by GitHub
commit 65fa07d015
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23

View file

@ -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<std::mutex> lock (mutex);
started = true;
condition.notify_all ();
@ -792,6 +798,17 @@ void rai::vote_processor::process_loop ()
{
std::deque<std::pair<std::shared_ptr<rai::vote>, 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<std::chrono::milliseconds> (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
{