From 92c1eb0291d7c42459110bc1eb32fc7017bce84e Mon Sep 17 00:00:00 2001 From: Lei Jin Date: Tue, 8 Apr 2014 10:58:07 -0700 Subject: [PATCH] macros for perf_context Summary: This will allow us to disable them completely for iOS or for better performance Test Plan: will run make all check Reviewers: igor, haobo, dhruba Reviewed By: haobo CC: leveldb Differential Revision: https://reviews.facebook.net/D17511 --- Makefile | 2 +- db/db_impl.cc | 47 +++++++---------- db/db_iter.cc | 24 ++++----- db/dbformat.cc | 4 +- db/memtable.cc | 7 ++- include/rocksdb/perf_context.h | 2 +- table/block_based_table_reader.cc | 2 +- table/format.cc | 13 +++-- table/merger.cc | 24 ++++----- util/perf_context.cc | 21 +++++--- util/perf_context_imp.h | 86 ++++++++++++++++++++++++------- 11 files changed, 133 insertions(+), 99 deletions(-) diff --git a/Makefile b/Makefile index 9ccd8e4e0..47aeb5847 100644 --- a/Makefile +++ b/Makefile @@ -418,7 +418,7 @@ ldb: tools/ldb.o $(LIBOBJECTS) # --------------------------------------------------------------------------- JNI_NATIVE_SOURCES = ./java/rocksjni/rocksjni.cc ./java/rocksjni/options.cc ./java/rocksjni/write_batch.cc -JAVA_INCLUDE = -I/usr/lib/jvm/java-openjdk/include/ -I/usr/lib/jvm/java-openjdk/include/linux +JAVA_INCLUDE = -I/usr/lib/jvm/java-openjdk/include/ -I/usr/lib/jvm/java-openjdk/include/linux ROCKSDBJNILIB = ./java/librocksdbjni.so ifeq ($(PLATFORM), OS_MACOSX) diff --git a/db/db_impl.cc b/db/db_impl.cc index 211f1ddea..98964d3c2 100644 --- a/db/db_impl.cc +++ b/db/db_impl.cc @@ -3331,8 +3331,7 @@ Status DBImpl::GetImpl(const ReadOptions& options, ColumnFamilyHandle* column_family, const Slice& key, std::string* value, bool* value_found) { StopWatch sw(env_, options_.statistics.get(), DB_GET, false); - StopWatchNano snapshot_timer(env_, false); - StartPerfTimer(&snapshot_timer); + PERF_TIMER_AUTO(get_snapshot_time); auto cfh = reinterpret_cast(column_family); auto cfd = cfh->cfd(); @@ -3404,7 +3403,7 @@ Status DBImpl::GetImpl(const ReadOptions& options, // s is both in/out. When in, s could either be OK or MergeInProgress. // merge_operands will contain the sequence of merges in the latter case. LookupKey lkey(key, snapshot); - BumpPerfTime(&perf_context.get_snapshot_time, &snapshot_timer); + PERF_TIMER_STOP(get_snapshot_time); if (sv->mem->Get(lkey, value, &s, merge_context, *cfd->options())) { // Done RecordTick(options_.statistics.get(), MEMTABLE_HIT); @@ -3412,18 +3411,16 @@ Status DBImpl::GetImpl(const ReadOptions& options, // Done RecordTick(options_.statistics.get(), MEMTABLE_HIT); } else { - StopWatchNano from_files_timer(env_, false); - StartPerfTimer(&from_files_timer); + PERF_TIMER_START(get_from_output_files_time); sv->current->Get(options, lkey, value, &s, &merge_context, &stats, *cfd->options(), value_found); have_stat_update = true; - BumpPerfTime(&perf_context.get_from_output_files_time, &from_files_timer); + PERF_TIMER_STOP(get_from_output_files_time); RecordTick(options_.statistics.get(), MEMTABLE_MISS); } - StopWatchNano post_process_timer(env_, false); - StartPerfTimer(&post_process_timer); + PERF_TIMER_START(get_post_process_time); if (!cfd->options()->disable_seek_compaction && have_stat_update) { mutex_.Lock(); @@ -3464,7 +3461,7 @@ Status DBImpl::GetImpl(const ReadOptions& options, RecordTick(options_.statistics.get(), NUMBER_KEYS_READ); RecordTick(options_.statistics.get(), BYTES_READ, value->size()); - BumpPerfTime(&perf_context.get_post_process_time, &post_process_timer); + PERF_TIMER_STOP(get_post_process_time); return s; } @@ -3474,8 +3471,7 @@ std::vector DBImpl::MultiGet( const std::vector& keys, std::vector* values) { StopWatch sw(env_, options_.statistics.get(), DB_MULTIGET, false); - StopWatchNano snapshot_timer(env_, false); - StartPerfTimer(&snapshot_timer); + PERF_TIMER_AUTO(get_snapshot_time); SequenceNumber snapshot; @@ -3519,7 +3515,7 @@ std::vector DBImpl::MultiGet( // Keep track of bytes that we read for statistics-recording later uint64_t bytes_read = 0; - BumpPerfTime(&perf_context.get_snapshot_time, &snapshot_timer); + PERF_TIMER_STOP(get_snapshot_time); // For each of the given keys, apply the entire "get" process as follows: // First look in the memtable, then in the immutable memtable (if any). @@ -3555,8 +3551,7 @@ std::vector DBImpl::MultiGet( } // Post processing (decrement reference counts and record statistics) - StopWatchNano post_process_timer(env_, false); - StartPerfTimer(&post_process_timer); + PERF_TIMER_START(get_post_process_time); autovector superversions_to_delete; bool schedule_flush_or_compaction = false; @@ -3589,7 +3584,7 @@ std::vector DBImpl::MultiGet( RecordTick(options_.statistics.get(), NUMBER_MULTIGET_CALLS); RecordTick(options_.statistics.get(), NUMBER_MULTIGET_KEYS_READ, num_keys); RecordTick(options_.statistics.get(), NUMBER_MULTIGET_BYTES_READ, bytes_read); - BumpPerfTime(&perf_context.get_post_process_time, &post_process_timer); + PERF_TIMER_STOP(get_post_process_time); return stat_list; } @@ -3803,8 +3798,7 @@ Status DBImpl::Delete(const WriteOptions& options, } Status DBImpl::Write(const WriteOptions& options, WriteBatch* my_batch) { - StopWatchNano pre_post_process_timer(env_, false); - StartPerfTimer(&pre_post_process_timer); + PERF_TIMER_AUTO(write_pre_and_post_process_time); Writer w(&mutex_); w.batch = my_batch; w.sync = options.sync; @@ -3883,12 +3877,10 @@ Status DBImpl::Write(const WriteOptions& options, WriteBatch* my_batch) { if (options.disableWAL) { flush_on_destroy_ = true; } - BumpPerfTime(&perf_context.write_pre_and_post_process_time, - &pre_post_process_timer); + PERF_TIMER_STOP(write_pre_and_post_process_time); if (!options.disableWAL) { - StopWatchNano timer(env_); - StartPerfTimer(&timer); + PERF_TIMER_START(write_wal_time); Slice log_entry = WriteBatchInternal::Contents(updates); status = log_->AddRecord(log_entry); RecordTick(options_.statistics.get(), WAL_FILE_SYNCED, 1); @@ -3902,15 +3894,13 @@ Status DBImpl::Write(const WriteOptions& options, WriteBatch* my_batch) { status = log_->file()->Sync(); } } - BumpPerfTime(&perf_context.write_wal_time, &timer); + PERF_TIMER_STOP(write_wal_time); } if (status.ok()) { - StopWatchNano write_memtable_timer(env_, false); - - StartPerfTimer(&write_memtable_timer); + PERF_TIMER_START(write_memtable_time); status = WriteBatchInternal::InsertInto( updates, column_family_memtables_.get(), false, 0, this, false); - BumpPerfTime(&perf_context.write_memtable_time, &write_memtable_timer); + PERF_TIMER_STOP(write_memtable_time); if (!status.ok()) { // Iteration failed (either in-memory writebatch corruption (very @@ -3924,7 +3914,7 @@ Status DBImpl::Write(const WriteOptions& options, WriteBatch* my_batch) { SetTickerCount(options_.statistics.get(), SEQUENCE_NUMBER, last_sequence); } - StartPerfTimer(&pre_post_process_timer); + PERF_TIMER_START(write_pre_and_post_process_time); if (updates == &tmp_batch_) tmp_batch_.Clear(); mutex_.Lock(); if (status.ok()) { @@ -3952,8 +3942,7 @@ Status DBImpl::Write(const WriteOptions& options, WriteBatch* my_batch) { writers_.front()->cv.Signal(); } mutex_.Unlock(); - BumpPerfTime(&perf_context.write_pre_and_post_process_time, - &pre_post_process_timer); + PERF_TIMER_STOP(write_pre_and_post_process_time); return status; } diff --git a/db/db_iter.cc b/db/db_iter.cc index 1b1aa539f..47c07bfd9 100644 --- a/db/db_iter.cc +++ b/db/db_iter.cc @@ -189,10 +189,9 @@ void DBIter::Next() { // NOTE: In between, saved_key_ can point to a user key that has // a delete marker inline void DBIter::FindNextUserEntry(bool skipping) { - StopWatchNano timer(env_, false); - StartPerfTimer(&timer); + PERF_TIMER_AUTO(find_next_user_entry_time); FindNextUserEntryInternal(skipping); - BumpPerfTime(&perf_context.find_next_user_entry_time, &timer); + PERF_TIMER_STOP(find_next_user_entry_time); } // Actual implementation of DBIter::FindNextUserEntry() @@ -208,7 +207,7 @@ void DBIter::FindNextUserEntryInternal(bool skipping) { if (skipping && user_comparator_->Compare(ikey.user_key, saved_key_.GetKey()) <= 0) { num_skipped++; // skip this entry - BumpPerfCount(&perf_context.internal_key_skipped_count); + PERF_COUNTER_ADD(internal_key_skipped_count, 1); } else { skipping = false; switch (ikey.type) { @@ -218,7 +217,7 @@ void DBIter::FindNextUserEntryInternal(bool skipping) { saved_key_.SetUserKey(ikey.user_key); skipping = true; num_skipped = 0; - BumpPerfCount(&perf_context.internal_delete_skipped_count); + PERF_COUNTER_ADD(internal_delete_skipped_count, 1); break; case kTypeValue: valid_ = true; @@ -423,10 +422,9 @@ void DBIter::Seek(const Slice& target) { saved_key_.Clear(); // now savved_key is used to store internal key. saved_key_.SetInternalKey(target, sequence_); - StopWatchNano internal_seek_timer(env_, false); - StartPerfTimer(&internal_seek_timer); + PERF_TIMER_AUTO(seek_internal_seek_time); iter_->Seek(saved_key_.GetKey()); - BumpPerfTime(&perf_context.seek_internal_seek_time, &internal_seek_timer); + PERF_TIMER_STOP(seek_internal_seek_time); if (iter_->Valid()) { direction_ = kForward; ClearSavedValue(); @@ -439,10 +437,9 @@ void DBIter::Seek(const Slice& target) { void DBIter::SeekToFirst() { direction_ = kForward; ClearSavedValue(); - StopWatchNano internal_seek_timer(env_, false); - StartPerfTimer(&internal_seek_timer); + PERF_TIMER_AUTO(seek_internal_seek_time); iter_->SeekToFirst(); - BumpPerfTime(&perf_context.seek_internal_seek_time, &internal_seek_timer); + PERF_TIMER_STOP(seek_internal_seek_time); if (iter_->Valid()) { FindNextUserEntry(false /* not skipping */); } else { @@ -461,10 +458,9 @@ void DBIter::SeekToLast() { direction_ = kReverse; ClearSavedValue(); - StopWatchNano internal_seek_timer(env_, false); - StartPerfTimer(&internal_seek_timer); + PERF_TIMER_AUTO(seek_internal_seek_time); iter_->SeekToLast(); - BumpPerfTime(&perf_context.seek_internal_seek_time, &internal_seek_timer); + PERF_TIMER_STOP(seek_internal_seek_time); FindPrevUserEntry(); } diff --git a/db/dbformat.cc b/db/dbformat.cc index 2d35d0423..e53d16dc1 100644 --- a/db/dbformat.cc +++ b/db/dbformat.cc @@ -59,7 +59,7 @@ int InternalKeyComparator::Compare(const Slice& akey, const Slice& bkey) const { // decreasing sequence number // decreasing type (though sequence# should be enough to disambiguate) int r = user_comparator_->Compare(ExtractUserKey(akey), ExtractUserKey(bkey)); - BumpPerfCount(&perf_context.user_key_comparison_count); + PERF_COUNTER_ADD(user_key_comparison_count, 1); if (r == 0) { const uint64_t anum = DecodeFixed64(akey.data() + akey.size() - 8); const uint64_t bnum = DecodeFixed64(bkey.data() + bkey.size() - 8); @@ -79,7 +79,7 @@ int InternalKeyComparator::Compare(const ParsedInternalKey& a, // decreasing sequence number // decreasing type (though sequence# should be enough to disambiguate) int r = user_comparator_->Compare(a.user_key, b.user_key); - BumpPerfCount(&perf_context.user_key_comparison_count); + PERF_COUNTER_ADD(user_key_comparison_count, 1); if (r == 0) { if (a.sequence > b.sequence) { r = -1; diff --git a/db/memtable.cc b/db/memtable.cc index 73ce60088..2d12708c3 100644 --- a/db/memtable.cc +++ b/db/memtable.cc @@ -377,8 +377,7 @@ static bool SaveValue(void* arg, const char* entry) { bool MemTable::Get(const LookupKey& key, std::string* value, Status* s, MergeContext& merge_context, const Options& options) { - StopWatchNano memtable_get_timer(options.env, false); - StartPerfTimer(&memtable_get_timer); + PERF_TIMER_AUTO(get_from_memtable_time); Slice user_key = key.user_key(); bool found_final_value = false; @@ -408,8 +407,8 @@ bool MemTable::Get(const LookupKey& key, std::string* value, Status* s, if (!found_final_value && merge_in_progress) { *s = Status::MergeInProgress(""); } - BumpPerfTime(&perf_context.get_from_memtable_time, &memtable_get_timer); - BumpPerfCount(&perf_context.get_from_memtable_count); + PERF_TIMER_STOP(get_from_memtable_time); + PERF_COUNTER_ADD(get_from_memtable_count, 1); return found_final_value; } diff --git a/include/rocksdb/perf_context.h b/include/rocksdb/perf_context.h index 63eddb61d..0704ea210 100644 --- a/include/rocksdb/perf_context.h +++ b/include/rocksdb/perf_context.h @@ -64,7 +64,7 @@ struct PerfContext { uint64_t write_memtable_time; }; -#if defined(IOS_CROSS_COMPILE) +#if defined(NPERF_CONTEXT) || defined(IOS_CROSS_COMPILE) extern PerfContext perf_context; #else extern __thread PerfContext perf_context; diff --git a/table/block_based_table_reader.cc b/table/block_based_table_reader.cc index 967836811..a8d8695b9 100644 --- a/table/block_based_table_reader.cc +++ b/table/block_based_table_reader.cc @@ -107,7 +107,7 @@ Cache::Handle* GetEntryFromCache(Cache* block_cache, const Slice& key, Statistics* statistics) { auto cache_handle = block_cache->Lookup(key); if (cache_handle != nullptr) { - BumpPerfCount(&perf_context.block_cache_hit_count); + PERF_COUNTER_ADD(block_cache_hit_count, 1); // overall cache hit RecordTick(statistics, BLOCK_CACHE_HIT); // block-type specific cache hit diff --git a/table/format.cc b/table/format.cc index f1adf97da..0d93cb93f 100644 --- a/table/format.cc +++ b/table/format.cc @@ -125,12 +125,11 @@ Status ReadBlockContents(RandomAccessFile* file, char* buf = new char[n + kBlockTrailerSize]; Slice contents; - StopWatchNano timer(env); - StartPerfTimer(&timer); + PERF_TIMER_AUTO(block_read_time); Status s = file->Read(handle.offset(), n + kBlockTrailerSize, &contents, buf); - BumpPerfCount(&perf_context.block_read_count); - BumpPerfCount(&perf_context.block_read_byte, n + kBlockTrailerSize); - BumpPerfTime(&perf_context.block_read_time, &timer); + PERF_TIMER_MEASURE(block_read_time); + PERF_COUNTER_ADD(block_read_count, 1); + PERF_COUNTER_ADD(block_read_byte, n + kBlockTrailerSize); if (!s.ok()) { delete[] buf; @@ -151,7 +150,7 @@ Status ReadBlockContents(RandomAccessFile* file, s = Status::Corruption("block checksum mismatch"); return s; } - BumpPerfTime(&perf_context.block_checksum_time, &timer); + PERF_TIMER_MEASURE(block_checksum_time); } // If the caller has requested that the block not be uncompressed @@ -175,7 +174,7 @@ Status ReadBlockContents(RandomAccessFile* file, s = UncompressBlockContents(data, n, result); delete[] buf; } - BumpPerfTime(&perf_context.block_decompress_time, &timer); + PERF_TIMER_STOP(block_decompress_time); return s; } diff --git a/table/merger.cc b/table/merger.cc index c154e6e64..6e31f8db0 100644 --- a/table/merger.cc +++ b/table/merger.cc @@ -79,13 +79,13 @@ class MergingIterator : public Iterator { // Invalidate the heap. use_heap_ = false; IteratorWrapper* first_child = nullptr; - StopWatchNano child_seek_timer(env_, false); - StopWatchNano min_heap_timer(env_, false); + PERF_TIMER_DECLARE(); + for (auto& child : children_) { - StartPerfTimer(&child_seek_timer); + PERF_TIMER_START(seek_child_seek_time); child.Seek(target); - BumpPerfTime(&perf_context.seek_child_seek_time, &child_seek_timer); - BumpPerfCount(&perf_context.seek_child_seek_count); + PERF_TIMER_STOP(seek_child_seek_time); + PERF_COUNTER_ADD(seek_child_seek_count, 1); if (child.Valid()) { // This child has valid key @@ -97,26 +97,24 @@ class MergingIterator : public Iterator { } else { // We have more than one children with valid keys. Initialize // the heap and put the first child into the heap. - StartPerfTimer(&min_heap_timer); + PERF_TIMER_START(seek_min_heap_time); ClearHeaps(); - BumpPerfTime(&perf_context.seek_min_heap_time, &child_seek_timer); - StartPerfTimer(&min_heap_timer); minHeap_.push(first_child); - BumpPerfTime(&perf_context.seek_min_heap_time, &child_seek_timer); + PERF_TIMER_STOP(seek_min_heap_time); } } if (use_heap_) { - StartPerfTimer(&min_heap_timer); + PERF_TIMER_START(seek_min_heap_time); minHeap_.push(&child); - BumpPerfTime(&perf_context.seek_min_heap_time, &child_seek_timer); + PERF_TIMER_STOP(seek_min_heap_time); } } } if (use_heap_) { // If heap is valid, need to put the smallest key to curent_. - StartPerfTimer(&min_heap_timer); + PERF_TIMER_START(seek_min_heap_time); FindSmallest(); - BumpPerfTime(&perf_context.seek_min_heap_time, &child_seek_timer); + PERF_TIMER_STOP(seek_min_heap_time); } else { // The heap is not valid, then the current_ iterator is the first // one, or null if there is no first child. diff --git a/util/perf_context.cc b/util/perf_context.cc index 855e7c45a..264b10d73 100644 --- a/util/perf_context.cc +++ b/util/perf_context.cc @@ -9,16 +9,21 @@ namespace rocksdb { -// by default, enable counts only -#if defined(IOS_CROSS_COMPILE) +#if defined(NPERF_CONTEXT) || defined(IOS_CROSS_COMPILE) PerfLevel perf_level = kEnableCount; +// This is a dummy variable since some place references it +PerfContext perf_context; #else __thread PerfLevel perf_level = kEnableCount; +__thread PerfContext perf_context; #endif -void SetPerfLevel(PerfLevel level) { perf_level = level; } +void SetPerfLevel(PerfLevel level) { + perf_level = level; +} void PerfContext::Reset() { +#if !defined(NPERF_CONTEXT) && !defined(IOS_CROSS_COMPILE) user_key_comparison_count = 0; block_cache_hit_count = 0; block_read_count = 0; @@ -42,11 +47,15 @@ void PerfContext::Reset() { find_next_user_entry_time = 0; write_pre_and_post_process_time = 0; write_memtable_time = 0; +#endif } #define OUTPUT(counter) #counter << " = " << counter << ", " std::string PerfContext::ToString() const { +#if defined(NPERF_CONTEXT) || defined(IOS_CROSS_COMPILE) + return ""; +#else std::ostringstream ss; ss << OUTPUT(user_key_comparison_count) << OUTPUT(block_cache_hit_count) @@ -71,11 +80,7 @@ std::string PerfContext::ToString() const { << OUTPUT(write_pre_and_post_process_time) << OUTPUT(write_memtable_time); return ss.str(); +#endif } -#if defined(IOS_CROSS_COMPILE) -PerfContext perf_context; -#else -__thread PerfContext perf_context; -#endif } diff --git a/util/perf_context_imp.h b/util/perf_context_imp.h index ac044ca09..dc4ae95e5 100644 --- a/util/perf_context_imp.h +++ b/util/perf_context_imp.h @@ -9,32 +9,80 @@ namespace rocksdb { -// TODO(icanadi): when calling perf_context is macro-ed (TODO ljin), make it -// noop in case IOS_CROSS_COMPILE -#if defined(IOS_CROSS_COMPILE) -extern enum PerfLevel perf_level; +#if defined(NPERF_CONTEXT) || defined(IOS_CROSS_COMPILE) + +#define PERF_TIMER_DECLARE() +#define PERF_TIMER_START(metric) +#define PERF_TIMER_AUTO(metric) +#define PERF_TIMER_MEASURE(metric) +#define PERF_TIMER_STOP(metric) +#define PERF_COUNTER_ADD(metric, value) + #else + extern __thread PerfLevel perf_level; -#endif -inline void StartPerfTimer(StopWatchNano* timer) { - if (perf_level >= PerfLevel::kEnableTime) { - timer->Start(); +class PerfStepTimer { + public: + PerfStepTimer() + : enabled_(perf_level >= PerfLevel::kEnableTime), + env_(enabled_ ? Env::Default() : nullptr), + start_(0) { } -} -inline void BumpPerfCount(uint64_t* count, uint64_t delta = 1) { - if (perf_level >= PerfLevel::kEnableCount) { - *count += delta; + void Start() { + if (enabled_) { + start_ = env_->NowNanos(); + } } -} -inline void BumpPerfTime(uint64_t* time, - StopWatchNano* timer, - bool reset = true) { - if (perf_level >= PerfLevel::kEnableTime) { - *time += timer->ElapsedNanos(reset); + void Measure(uint64_t* metric) { + if (start_) { + uint64_t now = env_->NowNanos(); + *metric += now - start_; + start_ = now; + } } -} + + void Stop(uint64_t* metric) { + if (start_) { + *metric += env_->NowNanos() - start_; + start_ = 0; + } + } + + private: + const bool enabled_; + Env* const env_; + uint64_t start_; +}; + +// Declare the local timer object to be used later on +#define PERF_TIMER_DECLARE() \ + PerfStepTimer perf_step_timer; + +// Set start time of the timer +#define PERF_TIMER_START(metric) \ + perf_step_timer.Start(); + +// Declare and set start time of the timer +#define PERF_TIMER_AUTO(metric) \ + PerfStepTimer perf_step_timer; \ + perf_step_timer.Start(); + +// Update metric with time elapsed since last START. start time is reset +// to current timestamp. +#define PERF_TIMER_MEASURE(metric) \ + perf_step_timer.Measure(&(perf_context.metric)); + +// Update metric with time elapsed since last START. But start time is not set. +#define PERF_TIMER_STOP(metric) \ + perf_step_timer.Stop(&(perf_context.metric)); + +// Increase metric value +#define PERF_COUNTER_ADD(metric, value) \ + perf_context.metric += value; + +#endif }