[RocksDB] Add perf_context.wal_write_time to track time spent on writ…

…ing the recovery log.

Summary: as title

Test Plan: make check; ./perf_context_test

Reviewers: dhruba

Reviewed By: dhruba

CC: leveldb

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

db/db_impl.cc

@@ -50,6 +50,7 @@
 #include "util/coding.h"
 #include "util/logging.h"
 #include "util/mutexlock.h"
+#include "util/perf_context_imp.h"
 #include "util/stop_watch.h"
 
 namespace rocksdb {
@@ -2576,7 +2577,10 @@ Status DBImpl::Write(const WriteOptions& options, WriteBatch* my_batch) {
       }
 
       if (!options.disableWAL) {
+        StopWatchNano timer(env_);
+        StartPerfTimer(&timer);
         status = log_->AddRecord(WriteBatchInternal::Contents(updates));
+        BumpPerfTime(&perf_context.wal_write_time, &timer);
         if (status.ok() && options.sync) {
           if (options_.use_fsync) {
             StopWatch(env_, options_.statistics, WAL_FILE_SYNC_MICROS);

db/perf_context_test.cc

@@ -25,16 +25,6 @@ int FLAGS_min_write_buffer_number_to_merge = 7;
 // Path to the database on file system
 const std::string kDbName = rocksdb::test::TmpDir() + "/perf_context_test";
 
-void SeekToFirst(rocksdb::Iterator* iter) {
-//  std::cout << "Press a key to continue:";
-//  std::string s;
-//  std::cin >> s;
-  iter->SeekToFirst();
-//  std::cout << "Press a key to continue:";
-//  std::string s2;
-//  std::cin >> s2;
-}
-
 namespace rocksdb {
 
 std::shared_ptr<DB> OpenDb() {
@@ -100,10 +90,7 @@ TEST(PerfContextTest, SeekIntoDeletion) {
 
   perf_context.Reset();
   StopWatchNano timer(Env::Default(), true);
-  //CALLGRIND_ZERO_STATS;
-  SeekToFirst(iter.get());
-  //iter->SeekToFirst();
-  //CALLGRIND_DUMP_STATS;
+  iter->SeekToFirst();
   hist_seek_to_first.Add(perf_context.user_key_comparison_count);
   auto elapsed_nanos = timer.ElapsedNanos();
 
@@ -257,13 +244,29 @@ TEST(PerfContextTest, SeekKeyComparison) {
     std::random_shuffle(keys.begin(), keys.end());
   }
 
+  HistogramImpl hist_put_time;
+  HistogramImpl hist_wal_time;
+  HistogramImpl hist_time_diff;
+
+  SetPerfLevel(kEnableTime);
+  StopWatchNano timer(Env::Default());
   for (const int i : keys) {
     std::string key = "k" + std::to_string(i);
     std::string value = "v" + std::to_string(i);
 
+    perf_context.Reset();
+    timer.Start();
     db->Put(write_options, key, value);
+    auto put_time = timer.ElapsedNanos();
+    hist_put_time.Add(put_time);
+    hist_wal_time.Add(perf_context.wal_write_time);
+    hist_time_diff.Add(put_time - perf_context.wal_write_time);
   }
 
+  std::cout << "Put time:\n" << hist_put_time.ToString()
+            << "WAL time:\n" << hist_wal_time.ToString()
+            << "time diff:\n" << hist_time_diff.ToString();
+
   HistogramImpl hist_seek;
   HistogramImpl hist_next;
 

include/rocksdb/perf_context.h

@@ -22,14 +22,18 @@ struct PerfContext {
   void Reset(); // reset all performance counters to zero
 
   uint64_t user_key_comparison_count; // total number of user key comparisons
-  uint64_t block_cache_hit_count;
-  uint64_t block_read_count;
-  uint64_t block_read_byte;
-  uint64_t block_read_time;
-  uint64_t block_checksum_time;
-  uint64_t block_decompress_time;
+  uint64_t block_cache_hit_count;     // total number of block cache hits
+  uint64_t block_read_count;          // total number of block reads (with IO)
+  uint64_t block_read_byte;           // total number of bytes from block reads
+  uint64_t block_read_time;           // total time spent on block reads
+  uint64_t block_checksum_time;       // total time spent on block checksum
+  uint64_t block_decompress_time;     // total time spent on block decompression
+  // total number of internal keys skipped over during iteration (overwritten or
+  // deleted, to be more specific, hidden by a put or delete of the same key)
   uint64_t internal_key_skipped_count;
+  // total number of deletes skipped over during iteration
   uint64_t internal_delete_skipped_count;
+  uint64_t wal_write_time;            // total time spent on writing to WAL
 };
 
 extern __thread PerfContext perf_context;

util/perf_context.cc

@@ -22,6 +22,7 @@ void PerfContext::Reset() {
   block_decompress_time = 0;
   internal_key_skipped_count = 0;
   internal_delete_skipped_count = 0;
+  wal_write_time = 0;
 }
 
 __thread PerfContext perf_context;