2016-02-10 00:12:00 +01:00
|
|
|
// Copyright (c) 2011-present, Facebook, Inc. All rights reserved.
|
2013-10-16 23:59:46 +02:00
|
|
|
// This source code is licensed under the BSD-style license found in the
|
|
|
|
// LICENSE file in the root directory of this source tree. An additional grant
|
|
|
|
// of patent rights can be found in the PATENTS file in the same directory.
|
|
|
|
//
|
2013-09-10 18:35:19 +02:00
|
|
|
#include <algorithm>
|
2013-08-13 08:59:04 +02:00
|
|
|
#include <iostream>
|
2015-10-13 19:41:48 +02:00
|
|
|
#include <thread>
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 08:09:15 +02:00
|
|
|
#include <vector>
|
2013-08-13 08:59:04 +02:00
|
|
|
|
2017-04-06 04:02:00 +02:00
|
|
|
#include "monitoring/histogram.h"
|
|
|
|
#include "monitoring/instrumented_mutex.h"
|
|
|
|
#include "monitoring/thread_status_util.h"
|
|
|
|
#include "port/port.h"
|
2013-08-23 17:38:13 +02:00
|
|
|
#include "rocksdb/db.h"
|
2016-03-26 02:29:43 +01:00
|
|
|
#include "rocksdb/memtablerep.h"
|
2013-08-23 17:38:13 +02:00
|
|
|
#include "rocksdb/perf_context.h"
|
2014-03-14 21:02:20 +01:00
|
|
|
#include "rocksdb/slice_transform.h"
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 08:09:15 +02:00
|
|
|
#include "util/stop_watch.h"
|
2016-03-26 02:29:43 +01:00
|
|
|
#include "util/string_util.h"
|
2013-08-13 08:59:04 +02:00
|
|
|
#include "util/testharness.h"
|
2016-03-26 02:29:43 +01:00
|
|
|
#include "utilities/merge_operators.h"
|
2013-10-02 19:28:25 +02:00
|
|
|
|
2013-09-10 18:35:19 +02:00
|
|
|
bool FLAGS_random_key = false;
|
2013-09-25 23:35:01 +02:00
|
|
|
bool FLAGS_use_set_based_memetable = false;
|
2013-09-10 18:35:19 +02:00
|
|
|
int FLAGS_total_keys = 100;
|
|
|
|
int FLAGS_write_buffer_size = 1000000000;
|
|
|
|
int FLAGS_max_write_buffer_number = 8;
|
|
|
|
int FLAGS_min_write_buffer_number_to_merge = 7;
|
2015-03-30 22:05:35 +02:00
|
|
|
bool FLAGS_verbose = false;
|
2013-08-13 08:59:04 +02:00
|
|
|
|
|
|
|
// Path to the database on file system
|
2013-10-04 06:49:15 +02:00
|
|
|
const std::string kDbName = rocksdb::test::TmpDir() + "/perf_context_test";
|
2013-08-13 08:59:04 +02:00
|
|
|
|
2013-10-04 06:49:15 +02:00
|
|
|
namespace rocksdb {
|
2013-09-10 18:35:19 +02:00
|
|
|
|
2014-10-03 02:02:30 +02:00
|
|
|
std::shared_ptr<DB> OpenDb(bool read_only = false) {
|
2013-08-13 08:59:04 +02:00
|
|
|
DB* db;
|
|
|
|
Options options;
|
|
|
|
options.create_if_missing = true;
|
2016-04-22 00:32:06 +02:00
|
|
|
options.max_open_files = -1;
|
2013-09-10 18:35:19 +02:00
|
|
|
options.write_buffer_size = FLAGS_write_buffer_size;
|
|
|
|
options.max_write_buffer_number = FLAGS_max_write_buffer_number;
|
|
|
|
options.min_write_buffer_number_to_merge =
|
|
|
|
FLAGS_min_write_buffer_number_to_merge;
|
2013-09-25 23:35:01 +02:00
|
|
|
|
|
|
|
if (FLAGS_use_set_based_memetable) {
|
2014-11-12 22:05:12 +01:00
|
|
|
#ifndef ROCKSDB_LITE
|
2014-10-03 02:02:30 +02:00
|
|
|
options.prefix_extractor.reset(rocksdb::NewFixedPrefixTransform(0));
|
|
|
|
options.memtable_factory.reset(NewHashSkipListRepFactory());
|
2014-11-12 22:05:12 +01:00
|
|
|
#endif // ROCKSDB_LITE
|
2013-09-25 23:35:01 +02:00
|
|
|
}
|
|
|
|
|
2014-10-03 02:02:30 +02:00
|
|
|
Status s;
|
|
|
|
if (!read_only) {
|
|
|
|
s = DB::Open(options, kDbName, &db);
|
|
|
|
} else {
|
|
|
|
s = DB::OpenForReadOnly(options, kDbName, &db);
|
|
|
|
}
|
rocksdb: Replace ASSERT* with EXPECT* in functions that does not return void value
Summary:
gtest does not use exceptions to fail a unit test by design, and `ASSERT*`s are implemented using `return`. As a consequence we cannot use `ASSERT*` in a function that does not return `void` value ([[ https://code.google.com/p/googletest/wiki/AdvancedGuide#Assertion_Placement | 1]]), and have to fix our existing code. This diff does this in a generic way, with no manual changes.
In order to detect all existing `ASSERT*` that are used in functions that doesn't return void value, I change the code to generate compile errors for such cases.
In `util/testharness.h` I defined `EXPECT*` assertions, the same way as `ASSERT*`, and redefined `ASSERT*` to return `void`. Then executed:
```lang=bash
% USE_CLANG=1 make all -j55 -k 2> build.log
% perl -naF: -e 'print "-- -number=".$F[1]." ".$F[0]."\n" if /: error:/' \
build.log | xargs -L 1 perl -spi -e 's/ASSERT/EXPECT/g if $. == $number'
% make format
```
After that I reverted back change to `ASSERT*` in `util/testharness.h`. But preserved introduced `EXPECT*`, which is the same as `ASSERT*`. This will be deleted once switched to gtest.
This diff is independent and contains manual changes only in `util/testharness.h`.
Test Plan:
Make sure all tests are passing.
```lang=bash
% USE_CLANG=1 make check
```
Reviewers: igor, lgalanis, sdong, yufei.zhu, rven, meyering
Reviewed By: meyering
Subscribers: dhruba, leveldb
Differential Revision: https://reviews.facebook.net/D33333
2015-03-17 04:52:32 +01:00
|
|
|
EXPECT_OK(s);
|
2013-08-13 08:59:04 +02:00
|
|
|
return std::shared_ptr<DB>(db);
|
|
|
|
}
|
|
|
|
|
2015-03-17 22:08:00 +01:00
|
|
|
class PerfContextTest : public testing::Test {};
|
2013-08-13 08:59:04 +02:00
|
|
|
|
2015-03-17 22:08:00 +01:00
|
|
|
TEST_F(PerfContextTest, SeekIntoDeletion) {
|
2013-10-02 19:28:25 +02:00
|
|
|
DestroyDB(kDbName, Options());
|
|
|
|
auto db = OpenDb();
|
|
|
|
WriteOptions write_options;
|
|
|
|
ReadOptions read_options;
|
|
|
|
|
|
|
|
for (int i = 0; i < FLAGS_total_keys; ++i) {
|
2014-11-25 05:44:49 +01:00
|
|
|
std::string key = "k" + ToString(i);
|
|
|
|
std::string value = "v" + ToString(i);
|
2013-10-02 19:28:25 +02:00
|
|
|
|
|
|
|
db->Put(write_options, key, value);
|
|
|
|
}
|
|
|
|
|
|
|
|
for (int i = 0; i < FLAGS_total_keys -1 ; ++i) {
|
2014-11-25 05:44:49 +01:00
|
|
|
std::string key = "k" + ToString(i);
|
2013-10-02 19:28:25 +02:00
|
|
|
db->Delete(write_options, key);
|
|
|
|
}
|
|
|
|
|
|
|
|
HistogramImpl hist_get;
|
|
|
|
HistogramImpl hist_get_time;
|
|
|
|
for (int i = 0; i < FLAGS_total_keys - 1; ++i) {
|
2014-11-25 05:44:49 +01:00
|
|
|
std::string key = "k" + ToString(i);
|
2013-10-02 19:28:25 +02:00
|
|
|
std::string value;
|
|
|
|
|
|
|
|
perf_context.Reset();
|
2014-10-03 02:02:30 +02:00
|
|
|
StopWatchNano timer(Env::Default());
|
|
|
|
timer.Start();
|
2013-10-02 19:28:25 +02:00
|
|
|
auto status = db->Get(read_options, key, &value);
|
|
|
|
auto elapsed_nanos = timer.ElapsedNanos();
|
|
|
|
ASSERT_TRUE(status.IsNotFound());
|
|
|
|
hist_get.Add(perf_context.user_key_comparison_count);
|
|
|
|
hist_get_time.Add(elapsed_nanos);
|
|
|
|
}
|
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << "Get user key comparison: \n" << hist_get.ToString()
|
|
|
|
<< "Get time: \n" << hist_get_time.ToString();
|
|
|
|
}
|
2013-10-02 19:28:25 +02:00
|
|
|
|
2014-11-08 00:04:30 +01:00
|
|
|
{
|
|
|
|
HistogramImpl hist_seek_to_first;
|
|
|
|
std::unique_ptr<Iterator> iter(db->NewIterator(read_options));
|
2013-10-02 19:28:25 +02:00
|
|
|
|
2014-11-08 00:04:30 +01:00
|
|
|
perf_context.Reset();
|
|
|
|
StopWatchNano timer(Env::Default(), true);
|
|
|
|
iter->SeekToFirst();
|
|
|
|
hist_seek_to_first.Add(perf_context.user_key_comparison_count);
|
|
|
|
auto elapsed_nanos = timer.ElapsedNanos();
|
2013-10-02 19:28:25 +02:00
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << "SeekToFirst uesr key comparison: \n"
|
|
|
|
<< hist_seek_to_first.ToString()
|
|
|
|
<< "ikey skipped: " << perf_context.internal_key_skipped_count
|
|
|
|
<< "\n"
|
|
|
|
<< "idelete skipped: "
|
|
|
|
<< perf_context.internal_delete_skipped_count << "\n"
|
|
|
|
<< "elapsed: " << elapsed_nanos << "\n";
|
|
|
|
}
|
2014-11-08 00:04:30 +01:00
|
|
|
}
|
2013-10-02 19:28:25 +02:00
|
|
|
|
|
|
|
HistogramImpl hist_seek;
|
|
|
|
for (int i = 0; i < FLAGS_total_keys; ++i) {
|
|
|
|
std::unique_ptr<Iterator> iter(db->NewIterator(read_options));
|
2014-11-25 05:44:49 +01:00
|
|
|
std::string key = "k" + ToString(i);
|
2013-10-02 19:28:25 +02:00
|
|
|
|
|
|
|
perf_context.Reset();
|
|
|
|
StopWatchNano timer(Env::Default(), true);
|
|
|
|
iter->Seek(key);
|
|
|
|
auto elapsed_nanos = timer.ElapsedNanos();
|
|
|
|
hist_seek.Add(perf_context.user_key_comparison_count);
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << "seek cmp: " << perf_context.user_key_comparison_count
|
|
|
|
<< " ikey skipped " << perf_context.internal_key_skipped_count
|
|
|
|
<< " idelete skipped "
|
|
|
|
<< perf_context.internal_delete_skipped_count
|
|
|
|
<< " elapsed: " << elapsed_nanos << "ns\n";
|
|
|
|
}
|
2013-10-02 19:28:25 +02:00
|
|
|
|
|
|
|
perf_context.Reset();
|
|
|
|
ASSERT_TRUE(iter->Valid());
|
|
|
|
StopWatchNano timer2(Env::Default(), true);
|
|
|
|
iter->Next();
|
|
|
|
auto elapsed_nanos2 = timer2.ElapsedNanos();
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << "next cmp: " << perf_context.user_key_comparison_count
|
|
|
|
<< "elapsed: " << elapsed_nanos2 << "ns\n";
|
|
|
|
}
|
2013-10-02 19:28:25 +02:00
|
|
|
}
|
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << "Seek uesr key comparison: \n" << hist_seek.ToString();
|
|
|
|
}
|
2013-10-02 19:28:25 +02:00
|
|
|
}
|
|
|
|
|
2015-03-17 22:08:00 +01:00
|
|
|
TEST_F(PerfContextTest, StopWatchNanoOverhead) {
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 08:09:15 +02:00
|
|
|
// profile the timer cost by itself!
|
|
|
|
const int kTotalIterations = 1000000;
|
|
|
|
std::vector<uint64_t> timings(kTotalIterations);
|
|
|
|
|
|
|
|
StopWatchNano timer(Env::Default(), true);
|
|
|
|
for (auto& timing : timings) {
|
|
|
|
timing = timer.ElapsedNanos(true /* reset */);
|
|
|
|
}
|
|
|
|
|
|
|
|
HistogramImpl histogram;
|
|
|
|
for (const auto timing : timings) {
|
|
|
|
histogram.Add(timing);
|
|
|
|
}
|
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << histogram.ToString();
|
|
|
|
}
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 08:09:15 +02:00
|
|
|
}
|
|
|
|
|
2015-03-17 22:08:00 +01:00
|
|
|
TEST_F(PerfContextTest, StopWatchOverhead) {
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 08:09:15 +02:00
|
|
|
// profile the timer cost by itself!
|
|
|
|
const int kTotalIterations = 1000000;
|
2014-10-03 02:02:30 +02:00
|
|
|
uint64_t elapsed = 0;
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 08:09:15 +02:00
|
|
|
std::vector<uint64_t> timings(kTotalIterations);
|
|
|
|
|
2014-10-03 02:02:30 +02:00
|
|
|
StopWatch timer(Env::Default(), nullptr, 0, &elapsed);
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 08:09:15 +02:00
|
|
|
for (auto& timing : timings) {
|
2014-10-03 02:02:30 +02:00
|
|
|
timing = elapsed;
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 08:09:15 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
HistogramImpl histogram;
|
|
|
|
uint64_t prev_timing = 0;
|
|
|
|
for (const auto timing : timings) {
|
|
|
|
histogram.Add(timing - prev_timing);
|
|
|
|
prev_timing = timing;
|
|
|
|
}
|
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << histogram.ToString();
|
|
|
|
}
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 08:09:15 +02:00
|
|
|
}
|
2013-08-13 08:59:04 +02:00
|
|
|
|
2014-10-03 02:02:30 +02:00
|
|
|
void ProfileQueries(bool enabled_time = false) {
|
2013-08-13 08:59:04 +02:00
|
|
|
DestroyDB(kDbName, Options()); // Start this test with a fresh DB
|
|
|
|
|
2013-09-10 18:35:19 +02:00
|
|
|
auto db = OpenDb();
|
2013-08-13 08:59:04 +02:00
|
|
|
|
|
|
|
WriteOptions write_options;
|
|
|
|
ReadOptions read_options;
|
|
|
|
|
2013-09-25 23:35:01 +02:00
|
|
|
HistogramImpl hist_put;
|
2014-10-03 02:02:30 +02:00
|
|
|
|
2013-09-25 23:35:01 +02:00
|
|
|
HistogramImpl hist_get;
|
2013-11-18 20:32:54 +01:00
|
|
|
HistogramImpl hist_get_snapshot;
|
|
|
|
HistogramImpl hist_get_memtable;
|
2014-10-03 02:02:30 +02:00
|
|
|
HistogramImpl hist_get_files;
|
2013-11-18 20:32:54 +01:00
|
|
|
HistogramImpl hist_get_post_process;
|
|
|
|
HistogramImpl hist_num_memtable_checked;
|
2014-10-03 02:02:30 +02:00
|
|
|
|
|
|
|
HistogramImpl hist_mget;
|
|
|
|
HistogramImpl hist_mget_snapshot;
|
|
|
|
HistogramImpl hist_mget_memtable;
|
|
|
|
HistogramImpl hist_mget_files;
|
|
|
|
HistogramImpl hist_mget_post_process;
|
|
|
|
HistogramImpl hist_mget_num_memtable_checked;
|
|
|
|
|
2013-11-18 20:32:54 +01:00
|
|
|
HistogramImpl hist_write_pre_post;
|
|
|
|
HistogramImpl hist_write_wal_time;
|
|
|
|
HistogramImpl hist_write_memtable_time;
|
2013-08-13 08:59:04 +02:00
|
|
|
|
2015-02-10 01:12:31 +01:00
|
|
|
uint64_t total_db_mutex_nanos = 0;
|
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << "Inserting " << FLAGS_total_keys << " key/value pairs\n...\n";
|
|
|
|
}
|
2013-08-13 08:59:04 +02:00
|
|
|
|
2013-09-25 23:35:01 +02:00
|
|
|
std::vector<int> keys;
|
2014-10-03 02:02:30 +02:00
|
|
|
const int kFlushFlag = -1;
|
2013-09-10 18:35:19 +02:00
|
|
|
for (int i = 0; i < FLAGS_total_keys; ++i) {
|
2013-09-25 23:35:01 +02:00
|
|
|
keys.push_back(i);
|
2014-10-03 02:02:30 +02:00
|
|
|
if (i == FLAGS_total_keys / 2) {
|
|
|
|
// Issuing a flush in the middle.
|
|
|
|
keys.push_back(kFlushFlag);
|
|
|
|
}
|
2013-09-25 23:35:01 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
if (FLAGS_random_key) {
|
|
|
|
std::random_shuffle(keys.begin(), keys.end());
|
|
|
|
}
|
2015-02-10 01:12:31 +01:00
|
|
|
#ifndef NDEBUG
|
|
|
|
ThreadStatusUtil::TEST_SetStateDelay(ThreadStatus::STATE_MUTEX_WAIT, 1U);
|
|
|
|
#endif
|
|
|
|
int num_mutex_waited = 0;
|
2013-09-25 23:35:01 +02:00
|
|
|
for (const int i : keys) {
|
2014-10-03 02:02:30 +02:00
|
|
|
if (i == kFlushFlag) {
|
|
|
|
FlushOptions fo;
|
|
|
|
db->Flush(fo);
|
|
|
|
continue;
|
|
|
|
}
|
2015-02-10 01:12:31 +01:00
|
|
|
|
2014-11-25 05:44:49 +01:00
|
|
|
std::string key = "k" + ToString(i);
|
|
|
|
std::string value = "v" + ToString(i);
|
2013-08-13 08:59:04 +02:00
|
|
|
|
2014-10-03 02:02:30 +02:00
|
|
|
std::vector<std::string> values;
|
|
|
|
|
2013-08-13 08:59:04 +02:00
|
|
|
perf_context.Reset();
|
|
|
|
db->Put(write_options, key, value);
|
2015-02-10 01:12:31 +01:00
|
|
|
if (++num_mutex_waited > 3) {
|
|
|
|
#ifndef NDEBUG
|
|
|
|
ThreadStatusUtil::TEST_SetStateDelay(ThreadStatus::STATE_MUTEX_WAIT, 0U);
|
|
|
|
#endif
|
|
|
|
}
|
2013-11-18 20:32:54 +01:00
|
|
|
hist_write_pre_post.Add(perf_context.write_pre_and_post_process_time);
|
|
|
|
hist_write_wal_time.Add(perf_context.write_wal_time);
|
|
|
|
hist_write_memtable_time.Add(perf_context.write_memtable_time);
|
2013-09-25 23:35:01 +02:00
|
|
|
hist_put.Add(perf_context.user_key_comparison_count);
|
2015-02-10 01:12:31 +01:00
|
|
|
total_db_mutex_nanos += perf_context.db_mutex_lock_nanos;
|
2014-10-03 02:02:30 +02:00
|
|
|
}
|
2015-02-10 01:12:31 +01:00
|
|
|
#ifndef NDEBUG
|
|
|
|
ThreadStatusUtil::TEST_SetStateDelay(ThreadStatus::STATE_MUTEX_WAIT, 0U);
|
|
|
|
#endif
|
2014-10-03 02:02:30 +02:00
|
|
|
|
|
|
|
for (const int i : keys) {
|
2016-04-22 00:32:06 +02:00
|
|
|
if (i == kFlushFlag) {
|
|
|
|
continue;
|
|
|
|
}
|
2014-11-25 05:44:49 +01:00
|
|
|
std::string key = "k" + ToString(i);
|
2016-04-22 00:32:06 +02:00
|
|
|
std::string expected_value = "v" + ToString(i);
|
|
|
|
std::string value;
|
2014-10-03 02:02:30 +02:00
|
|
|
|
2014-11-08 00:04:30 +01:00
|
|
|
std::vector<Slice> multiget_keys = {Slice(key)};
|
2014-10-03 02:02:30 +02:00
|
|
|
std::vector<std::string> values;
|
2013-08-13 08:59:04 +02:00
|
|
|
|
|
|
|
perf_context.Reset();
|
2016-04-22 00:32:06 +02:00
|
|
|
ASSERT_OK(db->Get(read_options, key, &value));
|
|
|
|
ASSERT_EQ(expected_value, value);
|
2013-11-18 20:32:54 +01:00
|
|
|
hist_get_snapshot.Add(perf_context.get_snapshot_time);
|
|
|
|
hist_get_memtable.Add(perf_context.get_from_memtable_time);
|
2014-10-03 02:02:30 +02:00
|
|
|
hist_get_files.Add(perf_context.get_from_output_files_time);
|
2013-11-18 20:32:54 +01:00
|
|
|
hist_num_memtable_checked.Add(perf_context.get_from_memtable_count);
|
|
|
|
hist_get_post_process.Add(perf_context.get_post_process_time);
|
2013-09-25 23:35:01 +02:00
|
|
|
hist_get.Add(perf_context.user_key_comparison_count);
|
2014-10-03 02:02:30 +02:00
|
|
|
|
|
|
|
perf_context.Reset();
|
2014-11-08 00:04:30 +01:00
|
|
|
db->MultiGet(read_options, multiget_keys, &values);
|
2014-10-03 02:02:30 +02:00
|
|
|
hist_mget_snapshot.Add(perf_context.get_snapshot_time);
|
|
|
|
hist_mget_memtable.Add(perf_context.get_from_memtable_time);
|
|
|
|
hist_mget_files.Add(perf_context.get_from_output_files_time);
|
|
|
|
hist_mget_num_memtable_checked.Add(perf_context.get_from_memtable_count);
|
|
|
|
hist_mget_post_process.Add(perf_context.get_post_process_time);
|
|
|
|
hist_mget.Add(perf_context.user_key_comparison_count);
|
2013-08-13 08:59:04 +02:00
|
|
|
}
|
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << "Put uesr key comparison: \n" << hist_put.ToString()
|
|
|
|
<< "Get uesr key comparison: \n" << hist_get.ToString()
|
|
|
|
<< "MultiGet uesr key comparison: \n" << hist_get.ToString();
|
|
|
|
std::cout << "Put(): Pre and Post Process Time: \n"
|
|
|
|
<< hist_write_pre_post.ToString() << " Writing WAL time: \n"
|
|
|
|
<< hist_write_wal_time.ToString() << "\n"
|
|
|
|
<< " Writing Mem Table time: \n"
|
|
|
|
<< hist_write_memtable_time.ToString() << "\n"
|
|
|
|
<< " Total DB mutex nanos: \n" << total_db_mutex_nanos << "\n";
|
|
|
|
|
|
|
|
std::cout << "Get(): Time to get snapshot: \n"
|
|
|
|
<< hist_get_snapshot.ToString()
|
|
|
|
<< " Time to get value from memtables: \n"
|
|
|
|
<< hist_get_memtable.ToString() << "\n"
|
|
|
|
<< " Time to get value from output files: \n"
|
|
|
|
<< hist_get_files.ToString() << "\n"
|
|
|
|
<< " Number of memtables checked: \n"
|
|
|
|
<< hist_num_memtable_checked.ToString() << "\n"
|
|
|
|
<< " Time to post process: \n" << hist_get_post_process.ToString()
|
|
|
|
<< "\n";
|
|
|
|
|
|
|
|
std::cout << "MultiGet(): Time to get snapshot: \n"
|
|
|
|
<< hist_mget_snapshot.ToString()
|
|
|
|
<< " Time to get value from memtables: \n"
|
|
|
|
<< hist_mget_memtable.ToString() << "\n"
|
|
|
|
<< " Time to get value from output files: \n"
|
|
|
|
<< hist_mget_files.ToString() << "\n"
|
|
|
|
<< " Number of memtables checked: \n"
|
|
|
|
<< hist_mget_num_memtable_checked.ToString() << "\n"
|
|
|
|
<< " Time to post process: \n"
|
|
|
|
<< hist_mget_post_process.ToString() << "\n";
|
|
|
|
}
|
2014-10-03 02:02:30 +02:00
|
|
|
|
|
|
|
if (enabled_time) {
|
|
|
|
ASSERT_GT(hist_get.Average(), 0);
|
|
|
|
ASSERT_GT(hist_get_snapshot.Average(), 0);
|
|
|
|
ASSERT_GT(hist_get_memtable.Average(), 0);
|
|
|
|
ASSERT_GT(hist_get_files.Average(), 0);
|
|
|
|
ASSERT_GT(hist_get_post_process.Average(), 0);
|
|
|
|
ASSERT_GT(hist_num_memtable_checked.Average(), 0);
|
|
|
|
|
|
|
|
ASSERT_GT(hist_mget.Average(), 0);
|
|
|
|
ASSERT_GT(hist_mget_snapshot.Average(), 0);
|
|
|
|
ASSERT_GT(hist_mget_memtable.Average(), 0);
|
|
|
|
ASSERT_GT(hist_mget_files.Average(), 0);
|
|
|
|
ASSERT_GT(hist_mget_post_process.Average(), 0);
|
|
|
|
ASSERT_GT(hist_mget_num_memtable_checked.Average(), 0);
|
2015-02-10 01:12:31 +01:00
|
|
|
#ifndef NDEBUG
|
|
|
|
ASSERT_GT(total_db_mutex_nanos, 2000U);
|
|
|
|
#endif
|
2014-10-03 02:02:30 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
db.reset();
|
|
|
|
db = OpenDb(true);
|
|
|
|
|
|
|
|
hist_get.Clear();
|
|
|
|
hist_get_snapshot.Clear();
|
|
|
|
hist_get_memtable.Clear();
|
|
|
|
hist_get_files.Clear();
|
|
|
|
hist_get_post_process.Clear();
|
|
|
|
hist_num_memtable_checked.Clear();
|
|
|
|
|
|
|
|
hist_mget.Clear();
|
|
|
|
hist_mget_snapshot.Clear();
|
|
|
|
hist_mget_memtable.Clear();
|
|
|
|
hist_mget_files.Clear();
|
|
|
|
hist_mget_post_process.Clear();
|
|
|
|
hist_mget_num_memtable_checked.Clear();
|
|
|
|
|
|
|
|
for (const int i : keys) {
|
2016-04-22 00:32:06 +02:00
|
|
|
if (i == kFlushFlag) {
|
|
|
|
continue;
|
|
|
|
}
|
2014-11-25 05:44:49 +01:00
|
|
|
std::string key = "k" + ToString(i);
|
2016-04-22 00:32:06 +02:00
|
|
|
std::string expected_value = "v" + ToString(i);
|
|
|
|
std::string value;
|
2014-10-03 02:02:30 +02:00
|
|
|
|
2014-11-08 00:04:30 +01:00
|
|
|
std::vector<Slice> multiget_keys = {Slice(key)};
|
2014-10-03 02:02:30 +02:00
|
|
|
std::vector<std::string> values;
|
|
|
|
|
|
|
|
perf_context.Reset();
|
2016-04-22 00:32:06 +02:00
|
|
|
ASSERT_OK(db->Get(read_options, key, &value));
|
|
|
|
ASSERT_EQ(expected_value, value);
|
2014-10-03 02:02:30 +02:00
|
|
|
hist_get_snapshot.Add(perf_context.get_snapshot_time);
|
|
|
|
hist_get_memtable.Add(perf_context.get_from_memtable_time);
|
|
|
|
hist_get_files.Add(perf_context.get_from_output_files_time);
|
|
|
|
hist_num_memtable_checked.Add(perf_context.get_from_memtable_count);
|
|
|
|
hist_get_post_process.Add(perf_context.get_post_process_time);
|
|
|
|
hist_get.Add(perf_context.user_key_comparison_count);
|
|
|
|
|
|
|
|
perf_context.Reset();
|
2014-11-08 00:04:30 +01:00
|
|
|
db->MultiGet(read_options, multiget_keys, &values);
|
2014-10-03 02:02:30 +02:00
|
|
|
hist_mget_snapshot.Add(perf_context.get_snapshot_time);
|
|
|
|
hist_mget_memtable.Add(perf_context.get_from_memtable_time);
|
|
|
|
hist_mget_files.Add(perf_context.get_from_output_files_time);
|
|
|
|
hist_mget_num_memtable_checked.Add(perf_context.get_from_memtable_count);
|
|
|
|
hist_mget_post_process.Add(perf_context.get_post_process_time);
|
|
|
|
hist_mget.Add(perf_context.user_key_comparison_count);
|
|
|
|
}
|
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << "ReadOnly Get uesr key comparison: \n" << hist_get.ToString()
|
|
|
|
<< "ReadOnly MultiGet uesr key comparison: \n"
|
|
|
|
<< hist_mget.ToString();
|
|
|
|
|
|
|
|
std::cout << "ReadOnly Get(): Time to get snapshot: \n"
|
|
|
|
<< hist_get_snapshot.ToString()
|
|
|
|
<< " Time to get value from memtables: \n"
|
|
|
|
<< hist_get_memtable.ToString() << "\n"
|
|
|
|
<< " Time to get value from output files: \n"
|
|
|
|
<< hist_get_files.ToString() << "\n"
|
|
|
|
<< " Number of memtables checked: \n"
|
|
|
|
<< hist_num_memtable_checked.ToString() << "\n"
|
|
|
|
<< " Time to post process: \n" << hist_get_post_process.ToString()
|
|
|
|
<< "\n";
|
|
|
|
|
|
|
|
std::cout << "ReadOnly MultiGet(): Time to get snapshot: \n"
|
|
|
|
<< hist_mget_snapshot.ToString()
|
|
|
|
<< " Time to get value from memtables: \n"
|
|
|
|
<< hist_mget_memtable.ToString() << "\n"
|
|
|
|
<< " Time to get value from output files: \n"
|
|
|
|
<< hist_mget_files.ToString() << "\n"
|
|
|
|
<< " Number of memtables checked: \n"
|
|
|
|
<< hist_mget_num_memtable_checked.ToString() << "\n"
|
|
|
|
<< " Time to post process: \n"
|
|
|
|
<< hist_mget_post_process.ToString() << "\n";
|
|
|
|
}
|
2014-10-03 02:02:30 +02:00
|
|
|
|
|
|
|
if (enabled_time) {
|
|
|
|
ASSERT_GT(hist_get.Average(), 0);
|
|
|
|
ASSERT_GT(hist_get_memtable.Average(), 0);
|
|
|
|
ASSERT_GT(hist_get_files.Average(), 0);
|
|
|
|
ASSERT_GT(hist_num_memtable_checked.Average(), 0);
|
|
|
|
// In read-only mode Get(), no super version operation is needed
|
|
|
|
ASSERT_EQ(hist_get_post_process.Average(), 0);
|
|
|
|
ASSERT_EQ(hist_get_snapshot.Average(), 0);
|
|
|
|
|
|
|
|
ASSERT_GT(hist_mget.Average(), 0);
|
|
|
|
ASSERT_GT(hist_mget_snapshot.Average(), 0);
|
|
|
|
ASSERT_GT(hist_mget_memtable.Average(), 0);
|
|
|
|
ASSERT_GT(hist_mget_files.Average(), 0);
|
|
|
|
ASSERT_GT(hist_mget_post_process.Average(), 0);
|
|
|
|
ASSERT_GT(hist_mget_num_memtable_checked.Average(), 0);
|
|
|
|
}
|
2013-08-13 08:59:04 +02:00
|
|
|
}
|
|
|
|
|
2015-10-13 19:32:05 +02:00
|
|
|
#ifndef ROCKSDB_LITE
|
2015-03-17 22:08:00 +01:00
|
|
|
TEST_F(PerfContextTest, KeyComparisonCount) {
|
2013-09-10 18:35:19 +02:00
|
|
|
SetPerfLevel(kEnableCount);
|
2014-10-03 02:02:30 +02:00
|
|
|
ProfileQueries();
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 08:09:15 +02:00
|
|
|
|
2013-09-10 18:35:19 +02:00
|
|
|
SetPerfLevel(kDisable);
|
2014-10-03 02:02:30 +02:00
|
|
|
ProfileQueries();
|
2013-08-13 08:59:04 +02:00
|
|
|
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 08:09:15 +02:00
|
|
|
SetPerfLevel(kEnableTime);
|
2014-10-03 02:02:30 +02:00
|
|
|
ProfileQueries(true);
|
2013-08-13 08:59:04 +02:00
|
|
|
}
|
2015-10-13 19:32:05 +02:00
|
|
|
#endif // ROCKSDB_LITE
|
2013-08-13 08:59:04 +02:00
|
|
|
|
2013-09-10 18:35:19 +02:00
|
|
|
// make perf_context_test
|
2013-10-05 07:32:05 +02:00
|
|
|
// export ROCKSDB_TESTS=PerfContextTest.SeekKeyComparison
|
2013-09-10 18:35:19 +02:00
|
|
|
// For one memtable:
|
|
|
|
// ./perf_context_test --write_buffer_size=500000 --total_keys=10000
|
|
|
|
// For two memtables:
|
|
|
|
// ./perf_context_test --write_buffer_size=250000 --total_keys=10000
|
|
|
|
// Specify --random_key=1 to shuffle the key before insertion
|
|
|
|
// Results show that, for sequential insertion, worst-case Seek Key comparison
|
|
|
|
// is close to the total number of keys (linear), when there is only one
|
|
|
|
// memtable. When there are two memtables, even the avg Seek Key comparison
|
|
|
|
// starts to become linear to the input size.
|
|
|
|
|
2015-03-17 22:08:00 +01:00
|
|
|
TEST_F(PerfContextTest, SeekKeyComparison) {
|
2013-09-10 18:35:19 +02:00
|
|
|
DestroyDB(kDbName, Options());
|
|
|
|
auto db = OpenDb();
|
|
|
|
WriteOptions write_options;
|
|
|
|
ReadOptions read_options;
|
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << "Inserting " << FLAGS_total_keys << " key/value pairs\n...\n";
|
|
|
|
}
|
2013-09-10 18:35:19 +02:00
|
|
|
|
|
|
|
std::vector<int> keys;
|
|
|
|
for (int i = 0; i < FLAGS_total_keys; ++i) {
|
|
|
|
keys.push_back(i);
|
|
|
|
}
|
|
|
|
|
|
|
|
if (FLAGS_random_key) {
|
|
|
|
std::random_shuffle(keys.begin(), keys.end());
|
|
|
|
}
|
|
|
|
|
2013-10-23 08:26:51 +02:00
|
|
|
HistogramImpl hist_put_time;
|
|
|
|
HistogramImpl hist_wal_time;
|
|
|
|
HistogramImpl hist_time_diff;
|
|
|
|
|
|
|
|
SetPerfLevel(kEnableTime);
|
|
|
|
StopWatchNano timer(Env::Default());
|
2013-09-10 18:35:19 +02:00
|
|
|
for (const int i : keys) {
|
2014-11-25 05:44:49 +01:00
|
|
|
std::string key = "k" + ToString(i);
|
|
|
|
std::string value = "v" + ToString(i);
|
2013-09-10 18:35:19 +02:00
|
|
|
|
2013-10-23 08:26:51 +02:00
|
|
|
perf_context.Reset();
|
|
|
|
timer.Start();
|
2013-09-10 18:35:19 +02:00
|
|
|
db->Put(write_options, key, value);
|
2013-10-23 08:26:51 +02:00
|
|
|
auto put_time = timer.ElapsedNanos();
|
|
|
|
hist_put_time.Add(put_time);
|
2013-11-18 20:32:54 +01:00
|
|
|
hist_wal_time.Add(perf_context.write_wal_time);
|
|
|
|
hist_time_diff.Add(put_time - perf_context.write_wal_time);
|
2013-09-10 18:35:19 +02:00
|
|
|
}
|
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << "Put time:\n" << hist_put_time.ToString() << "WAL time:\n"
|
|
|
|
<< hist_wal_time.ToString() << "time diff:\n"
|
|
|
|
<< hist_time_diff.ToString();
|
|
|
|
}
|
2013-10-23 08:26:51 +02:00
|
|
|
|
2013-09-25 23:35:01 +02:00
|
|
|
HistogramImpl hist_seek;
|
|
|
|
HistogramImpl hist_next;
|
|
|
|
|
2013-09-10 18:35:19 +02:00
|
|
|
for (int i = 0; i < FLAGS_total_keys; ++i) {
|
2014-11-25 05:44:49 +01:00
|
|
|
std::string key = "k" + ToString(i);
|
|
|
|
std::string value = "v" + ToString(i);
|
2013-09-10 18:35:19 +02:00
|
|
|
|
|
|
|
std::unique_ptr<Iterator> iter(db->NewIterator(read_options));
|
|
|
|
perf_context.Reset();
|
|
|
|
iter->Seek(key);
|
|
|
|
ASSERT_TRUE(iter->Valid());
|
|
|
|
ASSERT_EQ(iter->value().ToString(), value);
|
2013-09-25 23:35:01 +02:00
|
|
|
hist_seek.Add(perf_context.user_key_comparison_count);
|
2013-09-10 18:35:19 +02:00
|
|
|
}
|
2013-09-25 23:35:01 +02:00
|
|
|
|
|
|
|
std::unique_ptr<Iterator> iter(db->NewIterator(read_options));
|
|
|
|
for (iter->SeekToFirst(); iter->Valid();) {
|
|
|
|
perf_context.Reset();
|
|
|
|
iter->Next();
|
|
|
|
hist_next.Add(perf_context.user_key_comparison_count);
|
|
|
|
}
|
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << "Seek:\n" << hist_seek.ToString() << "Next:\n"
|
|
|
|
<< hist_next.ToString();
|
|
|
|
}
|
2013-09-10 18:35:19 +02:00
|
|
|
}
|
|
|
|
|
2015-10-13 19:41:48 +02:00
|
|
|
TEST_F(PerfContextTest, DBMutexLockCounter) {
|
|
|
|
int stats_code[] = {0, static_cast<int>(DB_MUTEX_WAIT_MICROS)};
|
2016-01-21 22:55:56 +01:00
|
|
|
for (PerfLevel perf_level :
|
|
|
|
{PerfLevel::kEnableTimeExceptForMutex, PerfLevel::kEnableTime}) {
|
|
|
|
for (int c = 0; c < 2; ++c) {
|
2015-10-13 19:41:48 +02:00
|
|
|
InstrumentedMutex mutex(nullptr, Env::Default(), stats_code[c]);
|
|
|
|
mutex.Lock();
|
2017-02-06 23:43:55 +01:00
|
|
|
rocksdb::port::Thread child_thread([&] {
|
2016-01-21 22:55:56 +01:00
|
|
|
SetPerfLevel(perf_level);
|
2015-10-13 19:41:48 +02:00
|
|
|
perf_context.Reset();
|
|
|
|
ASSERT_EQ(perf_context.db_mutex_lock_nanos, 0);
|
|
|
|
mutex.Lock();
|
|
|
|
mutex.Unlock();
|
2016-01-21 22:55:56 +01:00
|
|
|
if (perf_level == PerfLevel::kEnableTimeExceptForMutex ||
|
|
|
|
stats_code[c] != DB_MUTEX_WAIT_MICROS) {
|
|
|
|
ASSERT_EQ(perf_context.db_mutex_lock_nanos, 0);
|
|
|
|
} else {
|
2015-10-13 19:41:48 +02:00
|
|
|
// increment the counter only when it's a DB Mutex
|
|
|
|
ASSERT_GT(perf_context.db_mutex_lock_nanos, 0);
|
|
|
|
}
|
|
|
|
});
|
|
|
|
Env::Default()->SleepForMicroseconds(100);
|
|
|
|
mutex.Unlock();
|
|
|
|
child_thread.join();
|
|
|
|
}
|
2016-01-21 22:55:56 +01:00
|
|
|
}
|
2015-10-13 19:41:48 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
TEST_F(PerfContextTest, FalseDBMutexWait) {
|
|
|
|
SetPerfLevel(kEnableTime);
|
|
|
|
int stats_code[] = {0, static_cast<int>(DB_MUTEX_WAIT_MICROS)};
|
|
|
|
for (int c = 0; c < 2; ++c) {
|
|
|
|
InstrumentedMutex mutex(nullptr, Env::Default(), stats_code[c]);
|
|
|
|
InstrumentedCondVar lock(&mutex);
|
|
|
|
perf_context.Reset();
|
|
|
|
mutex.Lock();
|
|
|
|
lock.TimedWait(100);
|
|
|
|
mutex.Unlock();
|
|
|
|
if (stats_code[c] == static_cast<int>(DB_MUTEX_WAIT_MICROS)) {
|
|
|
|
// increment the counter only when it's a DB Mutex
|
|
|
|
ASSERT_GT(perf_context.db_condition_wait_nanos, 0);
|
|
|
|
} else {
|
|
|
|
ASSERT_EQ(perf_context.db_condition_wait_nanos, 0);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
2016-02-01 22:41:13 +01:00
|
|
|
|
|
|
|
TEST_F(PerfContextTest, ToString) {
|
|
|
|
perf_context.Reset();
|
|
|
|
perf_context.block_read_count = 12345;
|
|
|
|
|
|
|
|
std::string zero_included = perf_context.ToString();
|
|
|
|
ASSERT_NE(std::string::npos, zero_included.find("= 0"));
|
|
|
|
ASSERT_NE(std::string::npos, zero_included.find("= 12345"));
|
|
|
|
|
|
|
|
std::string zero_excluded = perf_context.ToString(true);
|
|
|
|
ASSERT_EQ(std::string::npos, zero_excluded.find("= 0"));
|
|
|
|
ASSERT_NE(std::string::npos, zero_excluded.find("= 12345"));
|
|
|
|
}
|
2016-03-26 02:29:43 +01:00
|
|
|
|
|
|
|
TEST_F(PerfContextTest, MergeOperatorTime) {
|
|
|
|
DestroyDB(kDbName, Options());
|
|
|
|
DB* db;
|
|
|
|
Options options;
|
|
|
|
options.create_if_missing = true;
|
|
|
|
options.merge_operator = MergeOperators::CreateStringAppendOperator();
|
|
|
|
Status s = DB::Open(options, kDbName, &db);
|
|
|
|
EXPECT_OK(s);
|
|
|
|
|
|
|
|
std::string val;
|
|
|
|
ASSERT_OK(db->Merge(WriteOptions(), "k1", "val1"));
|
|
|
|
ASSERT_OK(db->Merge(WriteOptions(), "k1", "val2"));
|
|
|
|
ASSERT_OK(db->Merge(WriteOptions(), "k1", "val3"));
|
|
|
|
ASSERT_OK(db->Merge(WriteOptions(), "k1", "val4"));
|
|
|
|
|
|
|
|
SetPerfLevel(kEnableTime);
|
|
|
|
perf_context.Reset();
|
|
|
|
ASSERT_OK(db->Get(ReadOptions(), "k1", &val));
|
|
|
|
EXPECT_GT(perf_context.merge_operator_time_nanos, 0);
|
|
|
|
|
|
|
|
ASSERT_OK(db->Flush(FlushOptions()));
|
|
|
|
|
|
|
|
perf_context.Reset();
|
|
|
|
ASSERT_OK(db->Get(ReadOptions(), "k1", &val));
|
|
|
|
EXPECT_GT(perf_context.merge_operator_time_nanos, 0);
|
|
|
|
|
|
|
|
ASSERT_OK(db->CompactRange(CompactRangeOptions(), nullptr, nullptr));
|
|
|
|
|
|
|
|
perf_context.Reset();
|
|
|
|
ASSERT_OK(db->Get(ReadOptions(), "k1", &val));
|
|
|
|
EXPECT_GT(perf_context.merge_operator_time_nanos, 0);
|
|
|
|
|
|
|
|
delete db;
|
|
|
|
}
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 08:09:15 +02:00
|
|
|
}
|
2013-08-13 08:59:04 +02:00
|
|
|
|
|
|
|
int main(int argc, char** argv) {
|
2015-03-17 22:08:00 +01:00
|
|
|
::testing::InitGoogleTest(&argc, argv);
|
2013-08-13 08:59:04 +02:00
|
|
|
|
2013-09-10 18:35:19 +02:00
|
|
|
for (int i = 1; i < argc; i++) {
|
|
|
|
int n;
|
|
|
|
char junk;
|
|
|
|
|
|
|
|
if (sscanf(argv[i], "--write_buffer_size=%d%c", &n, &junk) == 1) {
|
|
|
|
FLAGS_write_buffer_size = n;
|
|
|
|
}
|
|
|
|
|
|
|
|
if (sscanf(argv[i], "--total_keys=%d%c", &n, &junk) == 1) {
|
|
|
|
FLAGS_total_keys = n;
|
|
|
|
}
|
|
|
|
|
|
|
|
if (sscanf(argv[i], "--random_key=%d%c", &n, &junk) == 1 &&
|
|
|
|
(n == 0 || n == 1)) {
|
|
|
|
FLAGS_random_key = n;
|
|
|
|
}
|
|
|
|
|
2013-09-25 23:35:01 +02:00
|
|
|
if (sscanf(argv[i], "--use_set_based_memetable=%d%c", &n, &junk) == 1 &&
|
|
|
|
(n == 0 || n == 1)) {
|
|
|
|
FLAGS_use_set_based_memetable = n;
|
|
|
|
}
|
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (sscanf(argv[i], "--verbose=%d%c", &n, &junk) == 1 &&
|
|
|
|
(n == 0 || n == 1)) {
|
|
|
|
FLAGS_verbose = n;
|
|
|
|
}
|
2013-08-13 08:59:04 +02:00
|
|
|
}
|
|
|
|
|
2015-03-30 22:05:35 +02:00
|
|
|
if (FLAGS_verbose) {
|
|
|
|
std::cout << kDbName << "\n";
|
|
|
|
}
|
2013-09-10 18:35:19 +02:00
|
|
|
|
2015-03-17 22:08:00 +01:00
|
|
|
return RUN_ALL_TESTS();
|
2013-08-13 08:59:04 +02:00
|
|
|
}
|