diff --git a/rai/node/logging.cpp b/rai/node/logging.cpp index 15e6bc71..ecca95b3 100644 --- a/rai/node/logging.cpp +++ b/rai/node/logging.cpp @@ -20,6 +20,7 @@ log_rpc_value (true), bulk_pull_logging_value (false), work_generation_time_value (true), upnp_details_logging_value (false), +timing_logging_value (false), log_to_cerr_value (false), flush (true), max_size (16 * 1024 * 1024), @@ -59,6 +60,7 @@ void rai::logging::serialize_json (boost::property_tree::ptree & tree_a) const tree_a.put ("bulk_pull", bulk_pull_logging_value); tree_a.put ("work_generation_time", work_generation_time_value); tree_a.put ("upnp_details", upnp_details_logging_value); + tree_a.put ("timing", timing_logging_value); tree_a.put ("log_to_cerr", log_to_cerr_value); tree_a.put ("max_size", max_size); tree_a.put ("rotation_size", rotation_size); @@ -83,6 +85,7 @@ bool rai::logging::upgrade_json (unsigned version_a, boost::property_tree::ptree result = true; case 4: tree_a.put ("upnp_details", "false"); + tree_a.put ("timing", "false"); result = true; case 5: break; @@ -126,6 +129,7 @@ bool rai::logging::deserialize_json (bool & upgraded_a, boost::property_tree::pt bulk_pull_logging_value = tree_a.get ("bulk_pull"); work_generation_time_value = tree_a.get ("work_generation_time"); upnp_details_logging_value = tree_a.get ("upnp_details"); + timing_logging_value = tree_a.get ("timing"); log_to_cerr_value = tree_a.get ("log_to_cerr"); max_size = tree_a.get ("max_size"); rotation_size = tree_a.get ("rotation_size", 4194304); @@ -218,6 +222,11 @@ bool rai::logging::upnp_details_logging () const return upnp_details_logging_value; } +bool rai::logging::timing_logging () const +{ + return timing_logging_value; +} + bool rai::logging::log_to_cerr () const { return log_to_cerr_value; diff --git a/rai/node/logging.hpp b/rai/node/logging.hpp index aa1cae08..6bdb632d 100644 --- a/rai/node/logging.hpp +++ b/rai/node/logging.hpp @@ -29,6 +29,7 @@ public: bool node_lifetime_tracing () const; bool insufficient_work_logging () const; bool upnp_details_logging () const; + bool timing_logging () const; bool log_rpc () const; bool bulk_pull_logging () const; bool callback_logging () const; @@ -51,6 +52,7 @@ public: bool bulk_pull_logging_value; bool work_generation_time_value; bool upnp_details_logging_value; + bool timing_logging_value; bool log_to_cerr_value; bool flush; uintmax_t max_size; diff --git a/rai/node/node.cpp b/rai/node/node.cpp index f3a0886d..1ffd2897 100644 --- a/rai/node/node.cpp +++ b/rai/node/node.cpp @@ -1280,11 +1280,11 @@ void rai::block_processor::process_blocks () } } -bool rai::block_processor::should_log () +bool rai::block_processor::should_log (bool first_time) { auto result (false); auto now (std::chrono::steady_clock::now ()); - if (next_log < now) + if (first_time || next_log < now) { next_log = now + std::chrono::seconds (15); result = true; @@ -1301,6 +1301,7 @@ bool rai::block_processor::have_blocks () void rai::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 ()); std::deque, std::chrono::steady_clock::time_point>> items; if (max_count == std::numeric_limits::max () || max_count >= state_blocks.size ()) { @@ -1351,6 +1352,14 @@ void rai::block_processor::verify_state_blocks (std::unique_lock & l } items.pop_front (); } + 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); + } } void rai::block_processor::process_receive_many (std::unique_lock & lock_a) @@ -1367,11 +1376,30 @@ void rai::block_processor::process_receive_many (std::unique_lock & start_time = std::chrono::steady_clock::now (); 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) { - if ((blocks.size () + state_blocks.size ()) > 64 && should_log ()) + auto log_this_record (false); + if (node.config.logging.timing_logging ()) { - BOOST_LOG (node.log) << boost::str (boost::format ("%1% blocks in processing queue") % (blocks.size () + state_blocks.size ())); + if (should_log (first_time)) + { + log_this_record = true; + } + } + else + { + if (((blocks.size () + state_blocks.size () + forced.size ()) > 64 && should_log (false))) + { + log_this_record = true; + } + } + + if (log_this_record) + { + first_time = false; + BOOST_LOG (node.log) << boost::str (boost::format ("%1% blocks (+ %2% state blocks) (+ %3% forced) in processing queue") % blocks.size () % state_blocks.size () % forced.size ()); } std::pair, std::chrono::steady_clock::time_point> block; bool force (false); @@ -1386,6 +1414,7 @@ void rai::block_processor::process_receive_many (std::unique_lock & block = std::make_pair (forced.front (), std::chrono::steady_clock::now ()); forced.pop_front (); force = true; + number_of_forced_processed++; } lock_a.unlock (); auto hash (block.first->hash ()); @@ -1403,6 +1432,7 @@ void rai::block_processor::process_receive_many (std::unique_lock & Because of that we should set set validated_state_block as "false" for forced state blocks (!force) */ bool validated_state_block (!force && block.first->type () == rai::block_type::state); auto process_result (process_receive_one (transaction, block.first, block.second, validated_state_block)); + number_of_blocks_processed++; (void)process_result; lock_a.lock (); /* Verify more state blocks if blocks deque is empty @@ -1413,6 +1443,15 @@ void rai::block_processor::process_receive_many (std::unique_lock & } } lock_a.unlock (); + + 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); + } } rai::process_return rai::block_processor::process_receive_one (rai::transaction const & transaction_a, std::shared_ptr block_a, std::chrono::steady_clock::time_point origination, bool validated_state_block) diff --git a/rai/node/node.hpp b/rai/node/node.hpp index f92b5411..ead199eb 100644 --- a/rai/node/node.hpp +++ b/rai/node/node.hpp @@ -422,7 +422,7 @@ public: bool full (); void add (std::shared_ptr, std::chrono::steady_clock::time_point); void force (std::shared_ptr); - bool should_log (); + bool should_log (bool); bool have_blocks (); void process_blocks (); rai::process_return process_receive_one (rai::transaction const &, std::shared_ptr, std::chrono::steady_clock::time_point = std::chrono::steady_clock::now (), bool = false);