Improve mutex handling when generating stacktraces with NANO_TIMED_LOCKS/txn tracker (#2685)

* Improve NANO_TIMED_LOCKS on Windows

* Missed CMakeLists.txt change

CMakeLists.txt

@@ -63,6 +63,7 @@ set (NANO_ROCKSDB OFF CACHE BOOL "")
 set (NANO_POW_SERVER OFF CACHE BOOL "")
 set (NANO_WARN_TO_ERR OFF CACHE BOOL "")
 set (NANO_TIMED_LOCKS 0 CACHE STRING "")
+set (NANO_TIMED_LOCKS_IGNORE_BLOCKED OFF CACHE BOOL "")
 set (NANO_FUZZER_TEST OFF CACHE BOOL "")
 
 option (NANO_STACKTRACE_BACKTRACE "Use BOOST_STACKTRACE_USE_BACKTRACE in stacktraces, for POSIX" OFF)
@@ -75,6 +76,9 @@ endif ()
 
 if (${NANO_TIMED_LOCKS} GREATER 0)
 	add_definitions (-DNANO_TIMED_LOCKS=${NANO_TIMED_LOCKS})
+	if (NANO_TIMED_LOCKS_IGNORE_BLOCKED)
+		add_definitions(-DNANO_TIMED_LOCKS_IGNORE_BLOCKED)
+	endif ()
 endif ()
 
 add_definitions (-DNANO_ROCKSDB=$<STREQUAL:${NANO_ROCKSDB},ON>)

nano/lib/locks.cpp

@@ -28,6 +28,7 @@ void output_if_held_long_enough (nano::timer<std::chrono::milliseconds> & timer,
 	timer.stop ();
 }
 
+#ifndef NANO_TIMED_LOCKS_IGNORE_BLOCKED
 template <typename Mutex>
 void output_if_blocked_long_enough (nano::timer<std::chrono::milliseconds> & timer, Mutex & mutex)
 {
@@ -37,6 +38,7 @@ void output_if_blocked_long_enough (nano::timer<std::chrono::milliseconds> & tim
 		output ("blocked", time_blocked, mutex);
 	}
 }
+#endif
 }
 
 namespace nano
@@ -47,7 +49,9 @@ mut (mutex)
 	timer.start ();
 
 	mut.lock ();
+#ifndef NANO_TIMED_LOCKS_IGNORE_BLOCKED
 	output_if_blocked_long_enough (timer, mut);
+#endif
 }
 
 lock_guard<std::mutex>::~lock_guard () noexcept
@@ -73,8 +77,9 @@ void unique_lock<Mutex, U>::lock_impl ()
 
 	mut->lock ();
 	owns = true;
-
+#ifndef NANO_TIMED_LOCKS_IGNORE_BLOCKED
 	output_if_blocked_long_enough (timer, *mut);
+#endif
 }
 
 template <typename Mutex, typename U>

nano/node/lmdb/lmdb_txn.cpp

@@ -180,9 +180,9 @@ void nano::mdb_txn_tracker::serialize_json (boost::property_tree::ptree & json,
 	}
 }
 
-void nano::mdb_txn_tracker::output_finished (nano::mdb_txn_stats const & mdb_txn_stats) const
+void nano::mdb_txn_tracker::log_if_held_long_enough (nano::mdb_txn_stats const & mdb_txn_stats) const
 {
-	// Only output them if transactions were held for longer than a certain period of time
+	// Only log these transactions if they were held for longer than the min_read_txn_time/min_write_txn_time config values
 	auto is_write = mdb_txn_stats.is_write ();
 	auto time_open = mdb_txn_stats.timer.since_start ();
 
@@ -212,13 +212,14 @@ void nano::mdb_txn_tracker::add (const nano::transaction_impl * transaction_impl
 /** Can be called without error if transaction does not exist */
 void nano::mdb_txn_tracker::erase (const nano::transaction_impl * transaction_impl)
 {
-	nano::lock_guard<std::mutex> guard (mutex);
+	nano::unique_lock<std::mutex> lk (mutex);
 	auto it = std::find_if (stats.begin (), stats.end (), matches_txn (transaction_impl));
 	if (it != stats.end ())
 	{
-		output_finished (*it);
-		it->timer.stop ();
+		auto tracker_stats_copy = *it;
 		stats.erase (it);
+		lk.unlock ();
+		log_if_held_long_enough (tracker_stats_copy);
 	}
 }
 

nano/node/lmdb/lmdb_txn.hpp

@@ -78,6 +78,6 @@ private:
 	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;
+	void log_if_held_long_enough (nano::mdb_txn_stats const & mdb_txn_stats) const;
 };
 }

nano/rpc_test/rpc.cpp

@@ -6761,7 +6761,7 @@ TEST (rpc, block_confirmed)
 
 TEST (rpc, database_txn_tracker)
 {
-	// Don't test this in rocksdb mode
+	// Don't test this with the rocksdb backend
 	auto use_rocksdb_str = std::getenv ("TEST_USE_ROCKSDB");
 	if (use_rocksdb_str && boost::lexical_cast<int> (use_rocksdb_str) == 1)
 	{