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

@@ -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)

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<ColumnFamilyHandleImpl*>(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<Status> DBImpl::MultiGet(
     const std::vector<Slice>& keys, std::vector<std::string>* 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<Status> 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<Status> 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<SuperVersion*> superversions_to_delete;
 
   bool schedule_flush_or_compaction = false;
@@ -3589,7 +3584,7 @@ std::vector<Status> 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;
 }
 

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();
 }
 

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;

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;
 }
 

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;

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

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;
 }
 

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.

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
 }

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
 
 }