From f4086a88b4e5bafe9978f805a22a0b01e634c342 Mon Sep 17 00:00:00 2001 From: sdong Date: Thu, 2 Oct 2014 17:02:30 -0700 Subject: [PATCH] perf_context.get_from_output_files_time is set for MultiGet() and ReadOnly DB too. Summary: perf_context.get_from_output_files_time is now only set writable DB's DB::Get(). Extend it to MultiGet() and read only DB. Test Plan: make all check Fix perf_context_test and extend it to cover MultiGet(), as long as read-only DB. Run it and watch the results Reviewers: ljin, yhchiang, igor Reviewed By: igor Subscribers: rven, leveldb Differential Revision: https://reviews.facebook.net/D24207 --- Makefile | 2 +- db/db_impl.cc | 1 + db/db_impl_readonly.cc | 2 + db/perf_context_test.cc | 195 ++++++++++++++++++++++++++++++++++++---- 4 files changed, 182 insertions(+), 18 deletions(-) diff --git a/Makefile b/Makefile index c9d12415b..ad9082d31 100644 --- a/Makefile +++ b/Makefile @@ -154,7 +154,7 @@ TOOLS = \ options_test \ blob_store_bench -PROGRAMS = db_bench signal_test table_reader_bench log_and_apply_bench cache_bench $(TOOLS) +PROGRAMS = db_bench signal_test table_reader_bench log_and_apply_bench cache_bench perf_context_test $(TOOLS) # The library name is configurable since we are maintaining libraries of both # debug/release mode. diff --git a/db/db_impl.cc b/db/db_impl.cc index 680a22cb3..85dab9f9e 100644 --- a/db/db_impl.cc +++ b/db/db_impl.cc @@ -3602,6 +3602,7 @@ std::vector DBImpl::MultiGet( } else if (super_version->imm->Get(lkey, value, &s, &merge_context)) { // Done } else { + PERF_TIMER_GUARD(get_from_output_files_time); super_version->current->Get(options, lkey, value, &s, &merge_context); } diff --git a/db/db_impl_readonly.cc b/db/db_impl_readonly.cc index 9faebd8c2..31ebdbedd 100644 --- a/db/db_impl_readonly.cc +++ b/db/db_impl_readonly.cc @@ -8,6 +8,7 @@ #include "db/db_impl.h" #include "db/merge_context.h" #include "db/db_iter.h" +#include "util/perf_context_imp.h" namespace rocksdb { @@ -34,6 +35,7 @@ Status DBImplReadOnly::Get(const ReadOptions& read_options, LookupKey lkey(key, snapshot); if (super_version->mem->Get(lkey, value, &s, &merge_context)) { } else { + PERF_TIMER_GUARD(get_from_output_files_time); super_version->current->Get(read_options, lkey, value, &s, &merge_context); } return s; diff --git a/db/perf_context_test.cc b/db/perf_context_test.cc index a182fb521..9d34409c3 100644 --- a/db/perf_context_test.cc +++ b/db/perf_context_test.cc @@ -6,7 +6,6 @@ #include #include #include -#include "/usr/include/valgrind/callgrind.h" #include "rocksdb/db.h" #include "rocksdb/perf_context.h" @@ -29,7 +28,7 @@ const std::string kDbName = rocksdb::test::TmpDir() + "/perf_context_test"; namespace rocksdb { -std::shared_ptr OpenDb() { +std::shared_ptr OpenDb(bool read_only = false) { DB* db; Options options; options.create_if_missing = true; @@ -39,12 +38,16 @@ std::shared_ptr OpenDb() { FLAGS_min_write_buffer_number_to_merge; if (FLAGS_use_set_based_memetable) { - auto prefix_extractor = rocksdb::NewFixedPrefixTransform(0); - options.memtable_factory.reset( - NewHashSkipListRepFactory(prefix_extractor)); + options.prefix_extractor.reset(rocksdb::NewFixedPrefixTransform(0)); + options.memtable_factory.reset(NewHashSkipListRepFactory()); } - Status s = DB::Open(options, kDbName, &db); + Status s; + if (!read_only) { + s = DB::Open(options, kDbName, &db); + } else { + s = DB::OpenForReadOnly(options, kDbName, &db); + } ASSERT_OK(s); return std::shared_ptr(db); } @@ -76,7 +79,8 @@ TEST(PerfContextTest, SeekIntoDeletion) { std::string value; perf_context.Reset(); - StopWatchNano timer(Env::Default(), true); + StopWatchNano timer(Env::Default()); + timer.Start(); auto status = db->Get(read_options, key, &value); auto elapsed_nanos = timer.ElapsedNanos(); ASSERT_TRUE(status.IsNotFound()); @@ -149,11 +153,12 @@ TEST(PerfContextTest, StopWatchNanoOverhead) { TEST(PerfContextTest, StopWatchOverhead) { // profile the timer cost by itself! const int kTotalIterations = 1000000; + uint64_t elapsed = 0; std::vector timings(kTotalIterations); - StopWatch timer(Env::Default()); + StopWatch timer(Env::Default(), nullptr, 0, &elapsed); for (auto& timing : timings) { - timing = timer.ElapsedMicros(); + timing = elapsed; } HistogramImpl histogram; @@ -166,7 +171,7 @@ TEST(PerfContextTest, StopWatchOverhead) { std::cout << histogram.ToString(); } -void ProfileKeyComparison() { +void ProfileQueries(bool enabled_time = false) { DestroyDB(kDbName, Options()); // Start this test with a fresh DB auto db = OpenDb(); @@ -175,11 +180,21 @@ void ProfileKeyComparison() { ReadOptions read_options; HistogramImpl hist_put; + HistogramImpl hist_get; HistogramImpl hist_get_snapshot; HistogramImpl hist_get_memtable; + HistogramImpl hist_get_files; HistogramImpl hist_get_post_process; HistogramImpl hist_num_memtable_checked; + + HistogramImpl hist_mget; + HistogramImpl hist_mget_snapshot; + HistogramImpl hist_mget_memtable; + HistogramImpl hist_mget_files; + HistogramImpl hist_mget_post_process; + HistogramImpl hist_mget_num_memtable_checked; + HistogramImpl hist_write_pre_post; HistogramImpl hist_write_wal_time; HistogramImpl hist_write_memtable_time; @@ -187,8 +202,13 @@ void ProfileKeyComparison() { std::cout << "Inserting " << FLAGS_total_keys << " key/value pairs\n...\n"; std::vector keys; + const int kFlushFlag = -1; for (int i = 0; i < FLAGS_total_keys; ++i) { keys.push_back(i); + if (i == FLAGS_total_keys / 2) { + // Issuing a flush in the middle. + keys.push_back(kFlushFlag); + } } if (FLAGS_random_key) { @@ -196,27 +216,54 @@ void ProfileKeyComparison() { } for (const int i : keys) { + if (i == kFlushFlag) { + FlushOptions fo; + db->Flush(fo); + continue; + } std::string key = "k" + std::to_string(i); std::string value = "v" + std::to_string(i); + std::vector keys = {Slice(key)}; + std::vector values; + perf_context.Reset(); db->Put(write_options, key, value); 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); + } + + for (const int i : keys) { + std::string key = "k" + std::to_string(i); + std::string value = "v" + std::to_string(i); + + std::vector keys = {Slice(key)}; + std::vector values; perf_context.Reset(); db->Get(read_options, key, &value); hist_get_snapshot.Add(perf_context.get_snapshot_time); hist_get_memtable.Add(perf_context.get_from_memtable_time); + hist_get_files.Add(perf_context.get_from_output_files_time); hist_num_memtable_checked.Add(perf_context.get_from_memtable_count); hist_get_post_process.Add(perf_context.get_post_process_time); hist_get.Add(perf_context.user_key_comparison_count); + + perf_context.Reset(); + db->MultiGet(read_options, keys, &values); + hist_mget_snapshot.Add(perf_context.get_snapshot_time); + hist_mget_memtable.Add(perf_context.get_from_memtable_time); + hist_mget_files.Add(perf_context.get_from_output_files_time); + hist_mget_num_memtable_checked.Add(perf_context.get_from_memtable_count); + hist_mget_post_process.Add(perf_context.get_post_process_time); + hist_mget.Add(perf_context.user_key_comparison_count); } std::cout << "Put uesr key comparison: \n" << hist_put.ToString() - << "Get uesr key comparison: \n" << hist_get.ToString(); + << "Get uesr key comparison: \n" << hist_get.ToString() + << "MultiGet uesr key comparison: \n" << hist_get.ToString(); std::cout << "Put(): Pre and Post Process Time: \n" << hist_write_pre_post.ToString() << " Writing WAL time: \n" @@ -224,25 +271,139 @@ void ProfileKeyComparison() { << " Writing Mem Table time: \n" << hist_write_memtable_time.ToString() << "\n"; - std::cout << "Get(): Time to get snapshot: \n" + std::cout << "Get(): Time to get snapshot: \n" << hist_get_snapshot.ToString() + << " Time to get value from memtables: \n" + << hist_get_memtable.ToString() << "\n" + << " Time to get value from output files: \n" + << hist_get_files.ToString() << "\n" + << " Number of memtables checked: \n" + << hist_num_memtable_checked.ToString() << "\n" + << " Time to post process: \n" << hist_get_post_process.ToString() + << "\n"; + + std::cout << "MultiGet(): Time to get snapshot: \n" + << hist_mget_snapshot.ToString() + << " Time to get value from memtables: \n" + << hist_mget_memtable.ToString() << "\n" + << " Time to get value from output files: \n" + << hist_mget_files.ToString() << "\n" + << " Number of memtables checked: \n" + << hist_mget_num_memtable_checked.ToString() << "\n" + << " Time to post process: \n" << hist_mget_post_process.ToString() + << "\n"; + + if (enabled_time) { + ASSERT_GT(hist_get.Average(), 0); + ASSERT_GT(hist_get_snapshot.Average(), 0); + ASSERT_GT(hist_get_memtable.Average(), 0); + ASSERT_GT(hist_get_files.Average(), 0); + ASSERT_GT(hist_get_post_process.Average(), 0); + ASSERT_GT(hist_num_memtable_checked.Average(), 0); + + ASSERT_GT(hist_mget.Average(), 0); + ASSERT_GT(hist_mget_snapshot.Average(), 0); + ASSERT_GT(hist_mget_memtable.Average(), 0); + ASSERT_GT(hist_mget_files.Average(), 0); + ASSERT_GT(hist_mget_post_process.Average(), 0); + ASSERT_GT(hist_mget_num_memtable_checked.Average(), 0); + } + + db.reset(); + db = OpenDb(true); + + hist_get.Clear(); + hist_get_snapshot.Clear(); + hist_get_memtable.Clear(); + hist_get_files.Clear(); + hist_get_post_process.Clear(); + hist_num_memtable_checked.Clear(); + + hist_mget.Clear(); + hist_mget_snapshot.Clear(); + hist_mget_memtable.Clear(); + hist_mget_files.Clear(); + hist_mget_post_process.Clear(); + hist_mget_num_memtable_checked.Clear(); + + for (const int i : keys) { + std::string key = "k" + std::to_string(i); + std::string value = "v" + std::to_string(i); + + std::vector keys = {Slice(key)}; + std::vector values; + + perf_context.Reset(); + db->Get(read_options, key, &value); + hist_get_snapshot.Add(perf_context.get_snapshot_time); + hist_get_memtable.Add(perf_context.get_from_memtable_time); + hist_get_files.Add(perf_context.get_from_output_files_time); + hist_num_memtable_checked.Add(perf_context.get_from_memtable_count); + hist_get_post_process.Add(perf_context.get_post_process_time); + hist_get.Add(perf_context.user_key_comparison_count); + + perf_context.Reset(); + db->MultiGet(read_options, keys, &values); + hist_mget_snapshot.Add(perf_context.get_snapshot_time); + hist_mget_memtable.Add(perf_context.get_from_memtable_time); + hist_mget_files.Add(perf_context.get_from_output_files_time); + hist_mget_num_memtable_checked.Add(perf_context.get_from_memtable_count); + hist_mget_post_process.Add(perf_context.get_post_process_time); + hist_mget.Add(perf_context.user_key_comparison_count); + } + + std::cout << "ReadOnly Get uesr key comparison: \n" << hist_get.ToString() + << "ReadOnly MultiGet uesr key comparison: \n" + << hist_mget.ToString(); + + std::cout << "ReadOnly Get(): Time to get snapshot: \n" << hist_get_snapshot.ToString() << " Time to get value from memtables: \n" << hist_get_memtable.ToString() << "\n" + << " Time to get value from output files: \n" + << hist_get_files.ToString() << "\n" << " Number of memtables checked: \n" << hist_num_memtable_checked.ToString() << "\n" - << " Time to post process: \n" - << hist_get_post_process.ToString() << "\n"; + << " Time to post process: \n" << hist_get_post_process.ToString() + << "\n"; + + std::cout << "ReadOnly MultiGet(): Time to get snapshot: \n" + << hist_mget_snapshot.ToString() + << " Time to get value from memtables: \n" + << hist_mget_memtable.ToString() << "\n" + << " Time to get value from output files: \n" + << hist_mget_files.ToString() << "\n" + << " Number of memtables checked: \n" + << hist_mget_num_memtable_checked.ToString() << "\n" + << " Time to post process: \n" << hist_mget_post_process.ToString() + << "\n"; + + if (enabled_time) { + ASSERT_GT(hist_get.Average(), 0); + ASSERT_GT(hist_get_memtable.Average(), 0); + ASSERT_GT(hist_get_files.Average(), 0); + ASSERT_GT(hist_num_memtable_checked.Average(), 0); + // In read-only mode Get(), no super version operation is needed + ASSERT_EQ(hist_get_post_process.Average(), 0); + ASSERT_EQ(hist_get_snapshot.Average(), 0); + + ASSERT_GT(hist_mget.Average(), 0); + ASSERT_GT(hist_mget_snapshot.Average(), 0); + ASSERT_GT(hist_mget_memtable.Average(), 0); + ASSERT_GT(hist_mget_files.Average(), 0); + ASSERT_GT(hist_mget_post_process.Average(), 0); + ASSERT_GT(hist_mget_num_memtable_checked.Average(), 0); + } } TEST(PerfContextTest, KeyComparisonCount) { SetPerfLevel(kEnableCount); - ProfileKeyComparison(); + ProfileQueries(); SetPerfLevel(kDisable); - ProfileKeyComparison(); + ProfileQueries(); SetPerfLevel(kEnableTime); - ProfileKeyComparison(); + ProfileQueries(true); } // make perf_context_test