diff --git a/include/rocksdb/perf_context.h b/include/rocksdb/perf_context.h index 1095d063b..3bb7f5c0b 100644 --- a/include/rocksdb/perf_context.h +++ b/include/rocksdb/perf_context.h @@ -131,6 +131,11 @@ struct PerfContext { // total number of SST table bloom misses uint64_t bloom_sst_miss_count; + // Time spent waiting on key locks in transaction lock manager. + uint64_t key_lock_wait_time; + // number of times acquiring a lock was blocked by another transaction. + uint64_t key_lock_wait_count; + // Total time spent in Env filesystem operations. These are only populated // when TimedEnv is used. uint64_t env_new_sequential_file_nanos; diff --git a/monitoring/perf_context.cc b/monitoring/perf_context.cc index 791f4bdbe..a80b9e470 100644 --- a/monitoring/perf_context.cc +++ b/monitoring/perf_context.cc @@ -79,6 +79,8 @@ void PerfContext::Reset() { bloom_memtable_miss_count = 0; bloom_sst_hit_count = 0; bloom_sst_miss_count = 0; + key_lock_wait_time = 0; + key_lock_wait_count = 0; env_new_sequential_file_nanos = 0; env_new_random_access_file_nanos = 0; @@ -158,6 +160,8 @@ std::string PerfContext::ToString(bool exclude_zero_counters) const { PERF_CONTEXT_OUTPUT(bloom_memtable_miss_count); PERF_CONTEXT_OUTPUT(bloom_sst_hit_count); PERF_CONTEXT_OUTPUT(bloom_sst_miss_count); + PERF_CONTEXT_OUTPUT(key_lock_wait_time); + PERF_CONTEXT_OUTPUT(key_lock_wait_count); PERF_CONTEXT_OUTPUT(env_new_sequential_file_nanos); PERF_CONTEXT_OUTPUT(env_new_random_access_file_nanos); PERF_CONTEXT_OUTPUT(env_new_writable_file_nanos); diff --git a/utilities/transactions/transaction_lock_mgr.cc b/utilities/transactions/transaction_lock_mgr.cc index a72c2a12f..9485067d5 100644 --- a/utilities/transactions/transaction_lock_mgr.cc +++ b/utilities/transactions/transaction_lock_mgr.cc @@ -20,6 +20,7 @@ #include #include +#include "monitoring/perf_context_imp.h" #include "rocksdb/slice.h" #include "rocksdb/utilities/transaction_db_mutex.h" #include "util/cast_util.h" @@ -347,6 +348,8 @@ Status TransactionLockMgr::AcquireWithTimeout( &expire_time_hint, &wait_ids); if (!result.ok() && timeout != 0) { + PERF_TIMER_GUARD(key_lock_wait_time); + PERF_COUNTER_ADD(key_lock_wait_count, 1); // If we weren't able to acquire the lock, we will keep retrying as long // as the timeout allows. bool timed_out = false; diff --git a/utilities/transactions/transaction_test.cc b/utilities/transactions/transaction_test.cc index 80aabb943..0c9ce53ff 100644 --- a/utilities/transactions/transaction_test.cc +++ b/utilities/transactions/transaction_test.cc @@ -19,6 +19,7 @@ #include "db/db_impl.h" #include "rocksdb/db.h" #include "rocksdb/options.h" +#include "rocksdb/perf_context.h" #include "rocksdb/utilities/transaction.h" #include "rocksdb/utilities/transaction_db.h" #include "table/mock_table.h" @@ -187,15 +188,18 @@ TEST_P(TransactionTest, WaitingTxn) { ASSERT_EQ(cf_id, 0); }); + get_perf_context()->Reset(); // lock key in default cf s = txn1->GetForUpdate(read_options, "foo", &value); ASSERT_OK(s); ASSERT_EQ(value, "bar"); + ASSERT_EQ(get_perf_context()->key_lock_wait_count, 0); // lock key in cfa s = txn1->GetForUpdate(read_options, cfa, "foo", &value); ASSERT_OK(s); ASSERT_EQ(value, "bar"); + ASSERT_EQ(get_perf_context()->key_lock_wait_count, 0); auto lock_data = db->GetLockStatusData(); // Locked keys exist in both column family. @@ -231,6 +235,8 @@ TEST_P(TransactionTest, WaitingTxn) { s = txn2->GetForUpdate(read_options, "foo", &value); ASSERT_TRUE(s.IsTimedOut()); ASSERT_EQ(s.ToString(), "Operation timed out: Timeout waiting to lock key"); + ASSERT_EQ(get_perf_context()->key_lock_wait_count, 1); + ASSERT_GE(get_perf_context()->key_lock_wait_time, 0); rocksdb::SyncPoint::GetInstance()->DisableProcessing(); rocksdb::SyncPoint::GetInstance()->ClearAllCallBacks();