[RocksDB] Added perf counters to track skipped internal keys during iteration

Summary: as title. unit test not polished. this is for a quick live test

Test Plan: live

Reviewers: dhruba

Reviewed By: dhruba

CC: leveldb

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

db/db_iter.cc

@@ -15,6 +15,7 @@
 #include "port/port.h"
 #include "util/logging.h"
 #include "util/mutexlock.h"
+#include "util/perf_context_imp.h"
 
 namespace leveldb {
 
@@ -197,6 +198,7 @@ void DBIter::FindNextUserEntry(bool skipping) {
       if (skipping &&
           user_comparator_->Compare(ikey.user_key, saved_key_) <= 0) {
         num_skipped++; // skip this entry
+        BumpPerfCount(&perf_context.internal_key_skipped_count);
       } else {
         skipping = false;
         switch (ikey.type) {
@@ -206,6 +208,7 @@ void DBIter::FindNextUserEntry(bool skipping) {
             SaveKey(ikey.user_key, &saved_key_);
             skipping = true;
             num_skipped = 0;
+            BumpPerfCount(&perf_context.internal_delete_skipped_count);
             break;
           case kTypeValue:
             valid_ = true;

db/perf_context_test.cc

@@ -1,6 +1,7 @@
 #include <algorithm>
 #include <iostream>
 #include <vector>
+#include "/usr/include/valgrind/callgrind.h"
 
 #include "rocksdb/db.h"
 #include "rocksdb/perf_context.h"
@@ -8,6 +9,7 @@
 #include "util/stop_watch.h"
 #include "util/testharness.h"
 
+
 bool FLAGS_random_key = false;
 bool FLAGS_use_set_based_memetable = false;
 int FLAGS_total_keys = 100;
@@ -18,6 +20,16 @@ int FLAGS_min_write_buffer_number_to_merge = 7;
 // Path to the database on file system
 const std::string kDbName = leveldb::test::TmpDir() + "/perf_context_test";
 
+void SeekToFirst(leveldb::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 leveldb {
 
 std::shared_ptr<DB> OpenDb() {
@@ -42,6 +54,86 @@ std::shared_ptr<DB> OpenDb() {
 
 class PerfContextTest { };
 
+TEST(PerfContextTest, SeekIntoDeletion) {
+  DestroyDB(kDbName, Options());
+  auto db = OpenDb();
+  WriteOptions write_options;
+  ReadOptions read_options;
+
+  for (int i = 0; i < FLAGS_total_keys; ++i) {
+    std::string key = "k" + std::to_string(i);
+    std::string value = "v" + std::to_string(i);
+
+    db->Put(write_options, key, value);
+  }
+
+  for (int i = 0; i < FLAGS_total_keys -1 ; ++i) {
+    std::string key = "k" + std::to_string(i);
+    db->Delete(write_options, key);
+  }
+
+  HistogramImpl hist_get;
+  HistogramImpl hist_get_time;
+  for (int i = 0; i < FLAGS_total_keys - 1; ++i) {
+    std::string key = "k" + std::to_string(i);
+    std::string value;
+
+    perf_context.Reset();
+    StopWatchNano timer(Env::Default(), true);
+    auto status = db->Get(read_options, key, &value);
+    auto elapsed_nanos = timer.ElapsedNanos();
+    ASSERT_TRUE(status.IsNotFound());
+    hist_get.Add(perf_context.user_key_comparison_count);
+    hist_get_time.Add(elapsed_nanos);
+  }
+
+  std::cout << "Get uesr key comparison: \n" << hist_get.ToString()
+            << "Get time: \n" << hist_get_time.ToString();
+
+  HistogramImpl hist_seek_to_first;
+  std::unique_ptr<Iterator> iter(db->NewIterator(read_options));
+
+  perf_context.Reset();
+  StopWatchNano timer(Env::Default(), true);
+  //CALLGRIND_ZERO_STATS;
+  SeekToFirst(iter.get());
+  //iter->SeekToFirst();
+  //CALLGRIND_DUMP_STATS;
+  hist_seek_to_first.Add(perf_context.user_key_comparison_count);
+  auto elapsed_nanos = timer.ElapsedNanos();
+
+  std::cout << "SeekToFirst uesr key comparison: \n" << hist_seek_to_first.ToString()
+            << "ikey skipped: " << perf_context.internal_key_skipped_count << "\n"
+            << "idelete skipped: " << perf_context.internal_delete_skipped_count << "\n"
+            << "elapsed: " << elapsed_nanos << "\n";
+
+  HistogramImpl hist_seek;
+  for (int i = 0; i < FLAGS_total_keys; ++i) {
+    std::unique_ptr<Iterator> iter(db->NewIterator(read_options));
+    std::string key = "k" + std::to_string(i);
+
+    perf_context.Reset();
+    StopWatchNano timer(Env::Default(), true);
+    iter->Seek(key);
+    auto elapsed_nanos = timer.ElapsedNanos();
+    hist_seek.Add(perf_context.user_key_comparison_count);
+    std::cout << "seek cmp: " << perf_context.user_key_comparison_count
+              << " ikey skipped " << perf_context.internal_key_skipped_count
+              << " idelete skipped " << perf_context.internal_delete_skipped_count
+              << " elapsed: " << elapsed_nanos << "ns\n";
+
+    perf_context.Reset();
+    ASSERT_TRUE(iter->Valid());
+    StopWatchNano timer2(Env::Default(), true);
+    iter->Next();
+    auto elapsed_nanos2 = timer2.ElapsedNanos();
+    std::cout << "next cmp: " << perf_context.user_key_comparison_count
+              << "elapsed: " << elapsed_nanos2 << "ns\n";
+  }
+
+  std::cout << "Seek uesr key comparison: \n" << hist_seek.ToString();
+}
+
 TEST(PerfContextTest, StopWatchNanoOverhead) {
   // profile the timer cost by itself!
   const int kTotalIterations = 1000000;

include/rocksdb/perf_context.h

@@ -28,6 +28,8 @@ struct PerfContext {
   uint64_t block_read_time;
   uint64_t block_checksum_time;
   uint64_t block_decompress_time;
+  uint64_t internal_key_skipped_count;
+  uint64_t internal_delete_skipped_count;
 };
 
 extern __thread PerfContext perf_context;

util/perf_context.cc

@@ -15,6 +15,8 @@ void PerfContext::Reset() {
   block_read_time = 0;
   block_checksum_time = 0;
   block_decompress_time = 0;
+  internal_key_skipped_count = 0;
+  internal_delete_skipped_count = 0;
 }
 
 __thread PerfContext perf_context;