From 71046971f0c121e2f3cd36ff453286dbc3365173 Mon Sep 17 00:00:00 2001 From: Haobo Xu Date: Wed, 2 Oct 2013 10:28:25 -0700 Subject: [PATCH] [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 | 3 ++ db/perf_context_test.cc | 92 ++++++++++++++++++++++++++++++++++ include/rocksdb/perf_context.h | 2 + util/perf_context.cc | 2 + 4 files changed, 99 insertions(+) diff --git a/db/db_iter.cc b/db/db_iter.cc index 38e9953049..d68dcdda9a 100644 --- a/db/db_iter.cc +++ b/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; diff --git a/db/perf_context_test.cc b/db/perf_context_test.cc index 08f2c73695..2eafdbece8 100644 --- a/db/perf_context_test.cc +++ b/db/perf_context_test.cc @@ -1,6 +1,7 @@ #include #include #include +#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 OpenDb() { @@ -42,6 +54,86 @@ std::shared_ptr 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 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 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; diff --git a/include/rocksdb/perf_context.h b/include/rocksdb/perf_context.h index 45566ff19f..1e69189c78 100644 --- a/include/rocksdb/perf_context.h +++ b/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; diff --git a/util/perf_context.cc b/util/perf_context.cc index 48525d28a5..ae980714ca 100644 --- a/util/perf_context.cc +++ b/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;