From aa10e79825960387f5d7d44f9796a88db8c31ae4 Mon Sep 17 00:00:00 2001
From: Wesley Shillingford <wezrule@hotmail.com>
Date: Thu, 16 Jul 2020 12:42:18 +0100
Subject: [PATCH] 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              |  4 ++++
 nano/lib/locks.cpp          |  7 ++++++-
 nano/node/lmdb/lmdb_txn.cpp | 11 ++++++-----
 nano/node/lmdb/lmdb_txn.hpp |  2 +-
 nano/rpc_test/rpc.cpp       |  2 +-
 5 files changed, 18 insertions(+), 8 deletions(-)

diff --git a/CMakeLists.txt b/CMakeLists.txt
index 0c893171a2..4e80cc0132 100644
--- a/CMakeLists.txt
+++ b/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>)
diff --git a/nano/lib/locks.cpp b/nano/lib/locks.cpp
index e38a4e174a..8c784379dd 100644
--- a/nano/lib/locks.cpp
+++ b/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>
diff --git a/nano/node/lmdb/lmdb_txn.cpp b/nano/node/lmdb/lmdb_txn.cpp
index 405fd84e26..5e059ee1af 100644
--- a/nano/node/lmdb/lmdb_txn.cpp
+++ b/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);
 	}
 }
 
diff --git a/nano/node/lmdb/lmdb_txn.hpp b/nano/node/lmdb/lmdb_txn.hpp
index 0ec1767c26..63030a0347 100644
--- a/nano/node/lmdb/lmdb_txn.hpp
+++ b/nano/node/lmdb/lmdb_txn.hpp
@@ -78,6 +78,6 @@ class mdb_txn_tracker
 	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;
 };
 }
diff --git a/nano/rpc_test/rpc.cpp b/nano/rpc_test/rpc.cpp
index 067ebee769..73cdf97fd8 100644
--- a/nano/rpc_test/rpc.cpp
+++ b/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)
 	{