perf_context: report time spent on reading index and bloom blocks

Summary: Add a perf context counter to help users figure out time spent on reading indexes and bloom filter blocks.

Test Plan: Will write a unit test

Subscribers: leveldb, dhruba

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

db/table_cache.cc

@@ -18,6 +18,7 @@
 #include "table/table_reader.h"
 #include "table/get_context.h"
 #include "util/coding.h"
+#include "util/perf_context_imp.h"
 #include "util/stop_watch.h"
 
 namespace rocksdb {
@@ -78,6 +79,7 @@ Status TableCache::FindTable(const EnvOptions& env_options,
                              const InternalKeyComparator& internal_comparator,
                              const FileDescriptor& fd, Cache::Handle** handle,
                              const bool no_io) {
+  PERF_TIMER_GUARD(find_table_nanos);
   Status s;
   uint64_t number = fd.GetNumber();
   Slice key = GetSliceForFileNumber(&number);
@@ -121,6 +123,8 @@ Iterator* TableCache::NewIterator(const ReadOptions& options,
                                   const FileDescriptor& fd,
                                   TableReader** table_reader_ptr,
                                   bool for_compaction, Arena* arena) {
+  PERF_TIMER_GUARD(new_table_iterator_nanos);
+
   if (table_reader_ptr != nullptr) {
     *table_reader_ptr = nullptr;
   }

include/rocksdb/perf_context.h

@@ -70,6 +70,19 @@ struct PerfContext {
   uint64_t db_condition_wait_nanos;
   // Time spent on merge operator.
   uint64_t merge_operator_time_nanos;
+
+  // Time spent on reading index block from block cache or SST file
+  uint64_t read_index_block_nanos;
+  // Time spent on reading filter block from block cache or SST file
+  uint64_t read_filter_block_nanos;
+  // Time spent on creating data block iterator
+  uint64_t new_table_block_iter_nanos;
+  // Time spent on new_table_block_iter_micros
+  uint64_t new_table_iterator_nanos;
+  // Time spent on seeking a key in data/index blocks
+  uint64_t block_seek_nanos;
+  // Time spent on finding or creating a table reader
+  uint64_t find_table_nanos;
 };
 
 #if defined(NPERF_CONTEXT) || defined(IOS_CROSS_COMPILE)

table/block.cc

@@ -22,6 +22,7 @@
 #include "table/block_prefix_index.h"
 #include "util/coding.h"
 #include "util/logging.h"
+#include "util/perf_context_imp.h"
 
 namespace rocksdb {
 
@@ -82,6 +83,7 @@ void BlockIter::Prev() {
 }
 
 void BlockIter::Seek(const Slice& target) {
+  PERF_TIMER_GUARD(block_seek_nanos);
   if (data_ == nullptr) {  // Not init yet
     return;
   }

table/block_based_table_reader.cc

@@ -830,6 +830,8 @@ BlockBasedTable::CachableEntry<FilterBlockReader> BlockBasedTable::GetFilter(
     return {rep_->filter.get(), nullptr /* cache handle */};
   }
 
+  PERF_TIMER_GUARD(read_filter_block_nanos);
+
   Cache* block_cache = rep_->table_options.block_cache.get();
   if (rep_->filter_policy == nullptr /* do not use filter */ ||
       block_cache == nullptr /* no block cache at all */) {
@@ -881,6 +883,7 @@ Iterator* BlockBasedTable::NewIndexIterator(const ReadOptions& read_options,
     return rep_->index_reader->NewIterator(
         input_iter, read_options.total_order_seek);
   }
+  PERF_TIMER_GUARD(read_index_block_nanos);
 
   bool no_io = read_options.read_tier == kBlockCacheTier;
   Cache* block_cache = rep_->table_options.block_cache.get();
@@ -941,6 +944,8 @@ Iterator* BlockBasedTable::NewIndexIterator(const ReadOptions& read_options,
 Iterator* BlockBasedTable::NewDataBlockIterator(Rep* rep,
     const ReadOptions& ro, const Slice& index_value,
     BlockIter* input_iter) {
+  PERF_TIMER_GUARD(new_table_block_iter_nanos);
+
   const bool no_io = (ro.read_tier == kBlockCacheTier);
   Cache* block_cache = rep->table_options.block_cache.get();
   Cache* block_cache_compressed =

util/perf_context.cc

@@ -47,6 +47,12 @@ void PerfContext::Reset() {
   db_mutex_lock_nanos = 0;
   db_condition_wait_nanos = 0;
   merge_operator_time_nanos = 0;
+  read_index_block_nanos = 0;
+  read_filter_block_nanos = 0;
+  new_table_block_iter_nanos = 0;
+  new_table_block_iter_nanos = 0;
+  block_seek_nanos = 0;
+  find_table_nanos = 0;
 #endif
 }
 
@@ -70,7 +76,10 @@ std::string PerfContext::ToString() const {
      << OUTPUT(seek_internal_seek_time) << OUTPUT(find_next_user_entry_time)
      << OUTPUT(write_pre_and_post_process_time) << OUTPUT(write_memtable_time)
      << OUTPUT(db_mutex_lock_nanos) << OUTPUT(db_condition_wait_nanos)
-     << OUTPUT(merge_operator_time_nanos) << OUTPUT(write_delay_time);
+     << OUTPUT(merge_operator_time_nanos) << OUTPUT(write_delay_time)
+     << OUTPUT(read_index_block_nanos) << OUTPUT(read_filter_block_nanos)
+     << OUTPUT(new_table_block_iter_nanos) << OUTPUT(new_table_iterator_nanos)
+     << OUTPUT(block_seek_nanos) << OUTPUT(find_table_nanos);
   return ss.str();
 #endif
 }