diff --git a/db/perf_context_test.cc b/db/perf_context_test.cc index 81e3eb156..be35fd6d9 100644 --- a/db/perf_context_test.cc +++ b/db/perf_context_test.cc @@ -14,6 +14,7 @@ #include "util/histogram.h" #include "util/stop_watch.h" #include "util/testharness.h" +#include "util/thread_status_util.h" #include "util/string_util.h" @@ -210,6 +211,8 @@ void ProfileQueries(bool enabled_time = false) { HistogramImpl hist_write_wal_time; HistogramImpl hist_write_memtable_time; + uint64_t total_db_mutex_nanos = 0; + std::cout << "Inserting " << FLAGS_total_keys << " key/value pairs\n...\n"; std::vector keys; @@ -225,13 +228,17 @@ void ProfileQueries(bool enabled_time = false) { if (FLAGS_random_key) { std::random_shuffle(keys.begin(), keys.end()); } - +#ifndef NDEBUG + ThreadStatusUtil::TEST_SetStateDelay(ThreadStatus::STATE_MUTEX_WAIT, 1U); +#endif + int num_mutex_waited = 0; for (const int i : keys) { if (i == kFlushFlag) { FlushOptions fo; db->Flush(fo); continue; } + std::string key = "k" + ToString(i); std::string value = "v" + ToString(i); @@ -239,11 +246,20 @@ void ProfileQueries(bool enabled_time = false) { perf_context.Reset(); db->Put(write_options, key, value); + if (++num_mutex_waited > 3) { +#ifndef NDEBUG + ThreadStatusUtil::TEST_SetStateDelay(ThreadStatus::STATE_MUTEX_WAIT, 0U); +#endif + } hist_write_pre_post.Add(perf_context.write_pre_and_post_process_time); hist_write_wal_time.Add(perf_context.write_wal_time); hist_write_memtable_time.Add(perf_context.write_memtable_time); hist_put.Add(perf_context.user_key_comparison_count); + total_db_mutex_nanos += perf_context.db_mutex_lock_nanos; } +#ifndef NDEBUG + ThreadStatusUtil::TEST_SetStateDelay(ThreadStatus::STATE_MUTEX_WAIT, 0U); +#endif for (const int i : keys) { std::string key = "k" + ToString(i); @@ -279,7 +295,8 @@ void ProfileQueries(bool enabled_time = false) { << " Writing WAL time: \n" << hist_write_wal_time.ToString() << "\n" << " Writing Mem Table time: \n" - << hist_write_memtable_time.ToString() << "\n"; + << hist_write_memtable_time.ToString() << "\n" + << " Total DB mutex nanos: \n" << total_db_mutex_nanos << "\n"; std::cout << "Get(): Time to get snapshot: \n" << hist_get_snapshot.ToString() << " Time to get value from memtables: \n" @@ -316,6 +333,9 @@ void ProfileQueries(bool enabled_time = false) { ASSERT_GT(hist_mget_files.Average(), 0); ASSERT_GT(hist_mget_post_process.Average(), 0); ASSERT_GT(hist_mget_num_memtable_checked.Average(), 0); +#ifndef NDEBUG + ASSERT_GT(total_db_mutex_nanos, 2000U); +#endif } db.reset(); diff --git a/include/rocksdb/perf_context.h b/include/rocksdb/perf_context.h index e96d09d2a..18c186a95 100644 --- a/include/rocksdb/perf_context.h +++ b/include/rocksdb/perf_context.h @@ -65,6 +65,9 @@ struct PerfContext { uint64_t write_wal_time; // total time spent on writing to WAL // total time spent on writing to mem tables uint64_t write_memtable_time; + uint64_t db_mutex_lock_nanos; // time spent on acquiring DB mutex. + // Time spent on waiting with a condition variable created with DB mutex. + uint64_t db_condition_wait_nanos; }; #if defined(NPERF_CONTEXT) || defined(IOS_CROSS_COMPILE) diff --git a/util/instrumented_mutex.cc b/util/instrumented_mutex.cc index 05d19b2ae..2e240cc82 100644 --- a/util/instrumented_mutex.cc +++ b/util/instrumented_mutex.cc @@ -3,11 +3,13 @@ // LICENSE file in the root directory of this source tree. An additional grant // of patent rights can be found in the PATENTS file in the same directory. +#include "util/perf_context_imp.h" #include "util/instrumented_mutex.h" #include "util/thread_status_util.h" namespace rocksdb { void InstrumentedMutex::Lock() { + PERF_TIMER_GUARD(db_mutex_lock_nanos); uint64_t wait_time_micros = 0; if (env_ != nullptr && stats_ != nullptr) { { @@ -28,6 +30,7 @@ void InstrumentedMutex::LockInternal() { } void InstrumentedCondVar::Wait() { + PERF_TIMER_GUARD(db_condition_wait_nanos); uint64_t wait_time_micros = 0; if (env_ != nullptr && stats_ != nullptr) { { @@ -48,6 +51,7 @@ void InstrumentedCondVar::WaitInternal() { } bool InstrumentedCondVar::TimedWait(uint64_t abs_time_us) { + PERF_TIMER_GUARD(db_condition_wait_nanos); uint64_t wait_time_micros = 0; bool result = false; if (env_ != nullptr && stats_ != nullptr) { diff --git a/util/perf_context.cc b/util/perf_context.cc index 5443471d5..e89856513 100644 --- a/util/perf_context.cc +++ b/util/perf_context.cc @@ -51,6 +51,8 @@ void PerfContext::Reset() { find_next_user_entry_time = 0; write_pre_and_post_process_time = 0; write_memtable_time = 0; + db_mutex_lock_nanos = 0; + db_condition_wait_nanos = 0; #endif } @@ -82,7 +84,9 @@ std::string PerfContext::ToString() const { << OUTPUT(seek_internal_seek_time) << OUTPUT(find_next_user_entry_time) << OUTPUT(write_pre_and_post_process_time) - << OUTPUT(write_memtable_time); + << OUTPUT(write_memtable_time) + << OUTPUT(db_mutex_lock_nanos) + << OUTPUT(db_condition_wait_nanos); return ss.str(); #endif }