Skip to content
Permalink
Browse files

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

  • Loading branch information...
wezrule committed May 14, 2019
1 parent efca351 commit 3a0173f8265e61fa3a2fe6b37c6896bdd926a73d
@@ -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
@@ -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 ();
}
@@ -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 */
@@ -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)
@@ -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;

@@ -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));
@@ -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;
};
@@ -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),

0 comments on commit 3a0173f

Please sign in to comment.
You can’t perform that action at this time.