Perf Context to report DB mutex waiting time

Summary: Add counters in perf context to allow users to figure out how time spent on waiting for DB mutex

Test Plan: Add a test and run it.

Reviewers: yhchiang, rven, igor

Reviewed By: igor

Subscribers: leveldb, dhruba

Differential Revision: https://reviews.facebook.net/D33177

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<int> 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();

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)

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) {

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
 }