diff --git a/db/table_cache.cc b/db/table_cache.cc index 762029e8a..f74cfb6f1 100644 --- a/db/table_cache.cc +++ b/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; } diff --git a/include/rocksdb/perf_context.h b/include/rocksdb/perf_context.h index b55482fc8..1e312a7ed 100644 --- a/include/rocksdb/perf_context.h +++ b/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) diff --git a/table/block.cc b/table/block.cc index ebae8560c..99c76f695 100644 --- a/table/block.cc +++ b/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; } diff --git a/table/block_based_table_reader.cc b/table/block_based_table_reader.cc index 47e9a6a30..79c7d0edd 100644 --- a/table/block_based_table_reader.cc +++ b/table/block_based_table_reader.cc @@ -830,6 +830,8 @@ BlockBasedTable::CachableEntry 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 = diff --git a/util/perf_context.cc b/util/perf_context.cc index b3e9bb1b6..2ba35ca72 100644 --- a/util/perf_context.cc +++ b/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 }