diff --git a/db/db_impl.cc b/db/db_impl.cc index d7c10261c..7c57ace97 100644 --- a/db/db_impl.cc +++ b/db/db_impl.cc @@ -50,6 +50,7 @@ #include "util/coding.h" #include "util/logging.h" #include "util/mutexlock.h" +#include "util/perf_context_imp.h" #include "util/stop_watch.h" namespace rocksdb { @@ -2576,7 +2577,10 @@ Status DBImpl::Write(const WriteOptions& options, WriteBatch* my_batch) { } if (!options.disableWAL) { + StopWatchNano timer(env_); + StartPerfTimer(&timer); status = log_->AddRecord(WriteBatchInternal::Contents(updates)); + BumpPerfTime(&perf_context.wal_write_time, &timer); if (status.ok() && options.sync) { if (options_.use_fsync) { StopWatch(env_, options_.statistics, WAL_FILE_SYNC_MICROS); diff --git a/db/perf_context_test.cc b/db/perf_context_test.cc index db525e914..05416748d 100644 --- a/db/perf_context_test.cc +++ b/db/perf_context_test.cc @@ -25,16 +25,6 @@ int FLAGS_min_write_buffer_number_to_merge = 7; // Path to the database on file system const std::string kDbName = rocksdb::test::TmpDir() + "/perf_context_test"; -void SeekToFirst(rocksdb::Iterator* iter) { -// std::cout << "Press a key to continue:"; -// std::string s; -// std::cin >> s; - iter->SeekToFirst(); -// std::cout << "Press a key to continue:"; -// std::string s2; -// std::cin >> s2; -} - namespace rocksdb { std::shared_ptr OpenDb() { @@ -100,10 +90,7 @@ TEST(PerfContextTest, SeekIntoDeletion) { perf_context.Reset(); StopWatchNano timer(Env::Default(), true); - //CALLGRIND_ZERO_STATS; - SeekToFirst(iter.get()); - //iter->SeekToFirst(); - //CALLGRIND_DUMP_STATS; + iter->SeekToFirst(); hist_seek_to_first.Add(perf_context.user_key_comparison_count); auto elapsed_nanos = timer.ElapsedNanos(); @@ -257,13 +244,29 @@ TEST(PerfContextTest, SeekKeyComparison) { std::random_shuffle(keys.begin(), keys.end()); } + HistogramImpl hist_put_time; + HistogramImpl hist_wal_time; + HistogramImpl hist_time_diff; + + SetPerfLevel(kEnableTime); + StopWatchNano timer(Env::Default()); for (const int i : keys) { std::string key = "k" + std::to_string(i); std::string value = "v" + std::to_string(i); + perf_context.Reset(); + timer.Start(); db->Put(write_options, key, value); + auto put_time = timer.ElapsedNanos(); + hist_put_time.Add(put_time); + hist_wal_time.Add(perf_context.wal_write_time); + hist_time_diff.Add(put_time - perf_context.wal_write_time); } + std::cout << "Put time:\n" << hist_put_time.ToString() + << "WAL time:\n" << hist_wal_time.ToString() + << "time diff:\n" << hist_time_diff.ToString(); + HistogramImpl hist_seek; HistogramImpl hist_next; diff --git a/include/rocksdb/perf_context.h b/include/rocksdb/perf_context.h index 332bf0d3c..914200807 100644 --- a/include/rocksdb/perf_context.h +++ b/include/rocksdb/perf_context.h @@ -22,14 +22,18 @@ struct PerfContext { void Reset(); // reset all performance counters to zero uint64_t user_key_comparison_count; // total number of user key comparisons - uint64_t block_cache_hit_count; - uint64_t block_read_count; - uint64_t block_read_byte; - uint64_t block_read_time; - uint64_t block_checksum_time; - uint64_t block_decompress_time; + uint64_t block_cache_hit_count; // total number of block cache hits + uint64_t block_read_count; // total number of block reads (with IO) + uint64_t block_read_byte; // total number of bytes from block reads + uint64_t block_read_time; // total time spent on block reads + uint64_t block_checksum_time; // total time spent on block checksum + uint64_t block_decompress_time; // total time spent on block decompression + // total number of internal keys skipped over during iteration (overwritten or + // deleted, to be more specific, hidden by a put or delete of the same key) uint64_t internal_key_skipped_count; + // total number of deletes skipped over during iteration uint64_t internal_delete_skipped_count; + uint64_t wal_write_time; // total time spent on writing to WAL }; extern __thread PerfContext perf_context; diff --git a/util/perf_context.cc b/util/perf_context.cc index 608b300ec..1e8ddfb5e 100644 --- a/util/perf_context.cc +++ b/util/perf_context.cc @@ -22,6 +22,7 @@ void PerfContext::Reset() { block_decompress_time = 0; internal_key_skipped_count = 0; internal_delete_skipped_count = 0; + wal_write_time = 0; } __thread PerfContext perf_context;