Ignore block processor batched writes from lmdb tracker (#1978)

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<unsigned long>::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<unsigned>::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<unsigned>::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

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<unsigned long> (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<bool> ("ignore_writes_below_block_processor_max_time", txn_tracking.ignore_writes_below_block_processor_max_time);
 	}
 	return json.get_error ();
 }

nano/node/diagnosticsconfig.hpp

@@ -14,6 +14,7 @@ class txn_tracking_config final
 	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 */

nano/node/lmdb.cpp

@@ -823,10 +823,10 @@ nano::store_iterator<nano::account, std::shared_ptr<nano::vote>> nano::mdb_store
 	return nano::store_iterator<nano::account, std::shared_ptr<nano::vote>> (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)

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;
 

nano/node/lmdb_txn_tracker.cpp

@@ -44,9 +44,10 @@ class matches_txn
 };
 }
 
-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));

nano/node/lmdb_txn_tracker.hpp

@@ -27,7 +27,7 @@ class mdb_txn_stats
 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 @@ class mdb_txn_tracker
 	std::vector<mdb_txn_stats> 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;
 };

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<nano::mdb_store> (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<nano::mdb_store> (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<nano::mdb_wallets_store> (init_a.wallets_store_init, application_path_a / "wallets.ldb", config_a.lmdb_max_dbs)),
 wallets_store (*wallets_store_impl),