From 3a0173f8265e61fa3a2fe6b37c6896bdd926a73d Mon Sep 17 00:00:00 2001 From: Wesley Shillingford Date: Tue, 14 May 2019 08:54:13 +0100 Subject: [PATCH] Ignore block processor batched writes from lmdb tracker (#1978) --- nano/core_test/node.cpp | 4 ++++ nano/node/diagnosticsconfig.cpp | 3 +++ nano/node/diagnosticsconfig.hpp | 1 + nano/node/lmdb.cpp | 4 ++-- nano/node/lmdb.hpp | 2 +- nano/node/lmdb_txn_tracker.cpp | 17 ++++++++++++++--- nano/node/lmdb_txn_tracker.hpp | 3 ++- nano/node/node.cpp | 2 +- 8 files changed, 28 insertions(+), 8 deletions(-) diff --git a/nano/core_test/node.cpp b/nano/core_test/node.cpp index f51f283bc..1a9a0ba6e 100644 --- a/nano/core_test/node.cpp +++ b/nano/core_test/node.cpp @@ -741,6 +741,7 @@ TEST (node_config, v17_values) txn_tracking_l.put ("enable", false); txn_tracking_l.put ("min_read_txn_time", 0); txn_tracking_l.put ("min_write_txn_time", 0); + txn_tracking_l.put ("ignore_writes_below_block_processor_max_time", true); nano::jsonconfig diagnostics_l; diagnostics_l.put_child ("txn_tracking", txn_tracking_l); tree.put_child ("diagnostics", diagnostics_l); @@ -756,6 +757,7 @@ TEST (node_config, v17_values) ASSERT_FALSE (config.diagnostics_config.txn_tracking.enable); ASSERT_EQ (config.diagnostics_config.txn_tracking.min_read_txn_time.count (), 0); ASSERT_EQ (config.diagnostics_config.txn_tracking.min_write_txn_time.count (), 0); + ASSERT_TRUE (config.diagnostics_config.txn_tracking.ignore_writes_below_block_processor_max_time); // Check config is correct with other values tree.put ("tcp_client_timeout", std::numeric_limits::max () - 100); @@ -767,6 +769,7 @@ TEST (node_config, v17_values) txn_tracking_l.put ("enable", true); txn_tracking_l.put ("min_read_txn_time", 1234); txn_tracking_l.put ("min_write_txn_time", std::numeric_limits::max ()); + txn_tracking_l.put ("ignore_writes_below_block_processor_max_time", false); nano::jsonconfig diagnostics_l; diagnostics_l.replace_child ("txn_tracking", txn_tracking_l); tree.replace_child ("diagnostics", diagnostics_l); @@ -782,6 +785,7 @@ TEST (node_config, v17_values) ASSERT_TRUE (config.diagnostics_config.txn_tracking.enable); ASSERT_EQ (config.diagnostics_config.txn_tracking.min_read_txn_time.count (), 1234); ASSERT_EQ (config.diagnostics_config.txn_tracking.min_write_txn_time.count (), std::numeric_limits::max ()); + ASSERT_FALSE (config.diagnostics_config.txn_tracking.ignore_writes_below_block_processor_max_time); } // Regression test to ensure that deserializing includes changes node via get_required_child diff --git a/nano/node/diagnosticsconfig.cpp b/nano/node/diagnosticsconfig.cpp index 28585a44a..64f319516 100644 --- a/nano/node/diagnosticsconfig.cpp +++ b/nano/node/diagnosticsconfig.cpp @@ -8,6 +8,7 @@ nano::error nano::diagnostics_config::serialize_json (nano::jsonconfig & json) c txn_tracking_l.put ("enable", txn_tracking.enable); txn_tracking_l.put ("min_read_txn_time", txn_tracking.min_read_txn_time.count ()); txn_tracking_l.put ("min_write_txn_time", txn_tracking.min_write_txn_time.count ()); + txn_tracking_l.put ("ignore_writes_below_block_processor_max_time", txn_tracking.ignore_writes_below_block_processor_max_time); json.put_child ("txn_tracking", txn_tracking_l); return json.get_error (); } @@ -25,6 +26,8 @@ nano::error nano::diagnostics_config::deserialize_json (nano::jsonconfig & json) auto min_write_txn_time_l = static_cast (txn_tracking.min_write_txn_time.count ()); txn_tracking_l->get_optional ("min_write_txn_time", min_write_txn_time_l); txn_tracking.min_write_txn_time = std::chrono::milliseconds (min_write_txn_time_l); + + txn_tracking_l->get_optional ("ignore_writes_below_block_processor_max_time", txn_tracking.ignore_writes_below_block_processor_max_time); } return json.get_error (); } diff --git a/nano/node/diagnosticsconfig.hpp b/nano/node/diagnosticsconfig.hpp index d510eb6db..afbe7902b 100644 --- a/nano/node/diagnosticsconfig.hpp +++ b/nano/node/diagnosticsconfig.hpp @@ -14,6 +14,7 @@ public: bool enable{ false }; std::chrono::milliseconds min_read_txn_time{ 5000 }; std::chrono::milliseconds min_write_txn_time{ 500 }; + bool ignore_writes_below_block_processor_max_time{ true }; }; /** Configuration options for diagnostics information */ diff --git a/nano/node/lmdb.cpp b/nano/node/lmdb.cpp index 642fe040f..b7ae9f68b 100644 --- a/nano/node/lmdb.cpp +++ b/nano/node/lmdb.cpp @@ -823,10 +823,10 @@ nano::store_iterator> nano::mdb_store return nano::store_iterator> (nullptr); } -nano::mdb_store::mdb_store (bool & error_a, nano::logger_mt & logger_a, boost::filesystem::path const & path_a, nano::txn_tracking_config const & txn_tracking_config_a, int lmdb_max_dbs, bool drop_unchecked, size_t const batch_size) : +nano::mdb_store::mdb_store (bool & error_a, nano::logger_mt & logger_a, boost::filesystem::path const & path_a, nano::txn_tracking_config const & txn_tracking_config_a, std::chrono::milliseconds block_processor_batch_max_time_a, int lmdb_max_dbs, bool drop_unchecked, size_t const batch_size) : logger (logger_a), env (error_a, path_a, lmdb_max_dbs), -mdb_txn_tracker (logger_a, txn_tracking_config_a), +mdb_txn_tracker (logger_a, txn_tracking_config_a, block_processor_batch_max_time_a), txn_tracking_enabled (txn_tracking_config_a.enable) { if (!error_a) diff --git a/nano/node/lmdb.hpp b/nano/node/lmdb.hpp index 50b69be5b..73ccda458 100644 --- a/nano/node/lmdb.hpp +++ b/nano/node/lmdb.hpp @@ -181,7 +181,7 @@ class mdb_store : public block_store friend class nano::block_predecessor_set; public: - mdb_store (bool &, nano::logger_mt &, boost::filesystem::path const &, nano::txn_tracking_config const & txn_tracking_config_a = nano::txn_tracking_config{}, int lmdb_max_dbs = 128, bool drop_unchecked = false, size_t batch_size = 512); + mdb_store (bool &, nano::logger_mt &, boost::filesystem::path const &, nano::txn_tracking_config const & txn_tracking_config_a = nano::txn_tracking_config{}, std::chrono::milliseconds block_processor_batch_max_time_a = std::chrono::milliseconds (5000), int lmdb_max_dbs = 128, bool drop_unchecked = false, size_t batch_size = 512); nano::write_transaction tx_begin_write () override; nano::read_transaction tx_begin_read () override; diff --git a/nano/node/lmdb_txn_tracker.cpp b/nano/node/lmdb_txn_tracker.cpp index 4fba843b6..e3ff94ca8 100644 --- a/nano/node/lmdb_txn_tracker.cpp +++ b/nano/node/lmdb_txn_tracker.cpp @@ -44,9 +44,10 @@ private: }; } -nano::mdb_txn_tracker::mdb_txn_tracker (nano::logger_mt & logger_a, nano::txn_tracking_config const & txn_tracking_config_a) : +nano::mdb_txn_tracker::mdb_txn_tracker (nano::logger_mt & logger_a, nano::txn_tracking_config const & txn_tracking_config_a, std::chrono::milliseconds block_processor_batch_max_time_a) : logger (logger_a), -txn_tracking_config (txn_tracking_config_a) +txn_tracking_config (txn_tracking_config_a), +block_processor_batch_max_time (block_processor_batch_max_time_a) { } @@ -105,7 +106,17 @@ void nano::mdb_txn_tracker::output_finished (nano::mdb_txn_stats const & mdb_txn // Only output them if transactions were held for longer than a certain period of time auto is_write = mdb_txn_stats.is_write (); auto time_open = mdb_txn_stats.timer.since_start (); - if ((is_write && time_open >= txn_tracking_config.min_write_txn_time) || (!is_write && time_open >= txn_tracking_config.min_read_txn_time)) + + auto should_ignore = false; + // Reduce noise in log files by removing any entries from the block processor (if enabled) which are less than the max batch time (+ a few second buffer) because these are expected writes during bootstrapping. + auto is_below_max_time = time_open <= (block_processor_batch_max_time + std::chrono::seconds (3)); + bool is_blk_processing_thread = mdb_txn_stats.thread_name == nano::thread_role::get_string (nano::thread_role::name::block_processing); + if (txn_tracking_config.ignore_writes_below_block_processor_max_time && is_blk_processing_thread && is_write && is_below_max_time) + { + should_ignore = true; + } + + if (!should_ignore && ((is_write && time_open >= txn_tracking_config.min_write_txn_time) || (!is_write && time_open >= txn_tracking_config.min_read_txn_time))) { assert (mdb_txn_stats.stacktrace); logger.always_log (boost::str (boost::format ("%1%ms %2% held on thread %3%\n%4%") % mdb_txn_stats.timer.since_start ().count () % (is_write ? "write lock" : "read") % mdb_txn_stats.thread_name % *mdb_txn_stats.stacktrace)); diff --git a/nano/node/lmdb_txn_tracker.hpp b/nano/node/lmdb_txn_tracker.hpp index fdf4093ae..4a9279540 100644 --- a/nano/node/lmdb_txn_tracker.hpp +++ b/nano/node/lmdb_txn_tracker.hpp @@ -27,7 +27,7 @@ public: class mdb_txn_tracker { public: - mdb_txn_tracker (nano::logger_mt & logger_a, nano::txn_tracking_config const & txn_tracking_config_a); + mdb_txn_tracker (nano::logger_mt & logger_a, nano::txn_tracking_config const & txn_tracking_config_a, std::chrono::milliseconds block_processor_batch_max_time_a); void serialize_json (boost::property_tree::ptree & json, std::chrono::milliseconds min_read_time, std::chrono::milliseconds min_write_time); void add (const nano::transaction_impl * transaction_impl); void erase (const nano::transaction_impl * transaction_impl); @@ -37,6 +37,7 @@ private: std::vector stats; nano::logger_mt & logger; nano::txn_tracking_config txn_tracking_config; + std::chrono::milliseconds block_processor_batch_max_time; void output_finished (nano::mdb_txn_stats const & mdb_txn_stats) const; }; diff --git a/nano/node/node.cpp b/nano/node/node.cpp index 9e62e62c3..edb464184 100644 --- a/nano/node/node.cpp +++ b/nano/node/node.cpp @@ -1026,7 +1026,7 @@ flags (flags_a), alarm (alarm_a), work (work_a), logger (config_a.logging.min_time_between_log_output), -store_impl (std::make_unique (init_a.block_store_init, logger, application_path_a / "data.ldb", config.diagnostics_config.txn_tracking, config_a.lmdb_max_dbs, !flags.disable_unchecked_drop, flags.sideband_batch_size)), +store_impl (std::make_unique (init_a.block_store_init, logger, application_path_a / "data.ldb", config_a.diagnostics_config.txn_tracking, config_a.block_processor_batch_max_time, config_a.lmdb_max_dbs, !flags.disable_unchecked_drop, flags.sideband_batch_size)), store (*store_impl), wallets_store_impl (std::make_unique (init_a.wallets_store_init, application_path_a / "wallets.ldb", config_a.lmdb_max_dbs)), wallets_store (*wallets_store_impl),