2013-08-13 08:59:04 +02:00
|
|
|
#include <iostream>
|
[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
|
|
|
|
2013-08-23 17:38:13 +02:00
|
|
|
#include "rocksdb/db.h"
|
|
|
|
#include "rocksdb/perf_context.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/histogram.h"
|
|
|
|
#include "util/stop_watch.h"
|
2013-08-13 08:59:04 +02:00
|
|
|
#include "util/testharness.h"
|
|
|
|
|
|
|
|
|
|
|
|
namespace leveldb {
|
|
|
|
|
|
|
|
// Path to the database on file system
|
|
|
|
const std::string kDbName = test::TmpDir() + "/perf_context_test";
|
|
|
|
|
[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::shared_ptr<DB> OpenDb(size_t write_buffer_size) {
|
2013-08-13 08:59:04 +02:00
|
|
|
DB* db;
|
|
|
|
Options options;
|
|
|
|
options.create_if_missing = true;
|
[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
|
|
|
options.write_buffer_size = write_buffer_size;
|
2013-08-13 08:59:04 +02:00
|
|
|
Status s = DB::Open(options, kDbName, &db);
|
|
|
|
ASSERT_OK(s);
|
|
|
|
return std::shared_ptr<DB>(db);
|
|
|
|
}
|
|
|
|
|
|
|
|
class PerfContextTest { };
|
|
|
|
|
|
|
|
int kTotalKeys = 100;
|
|
|
|
|
[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
|
|
|
TEST(PerfContextTest, StopWatchNanoOverhead) {
|
|
|
|
// 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);
|
|
|
|
}
|
|
|
|
|
|
|
|
std::cout << histogram.ToString();
|
|
|
|
}
|
|
|
|
|
|
|
|
TEST(PerfContextTest, StopWatchOverhead) {
|
|
|
|
// profile the timer cost by itself!
|
|
|
|
const int kTotalIterations = 1000000;
|
|
|
|
std::vector<uint64_t> timings(kTotalIterations);
|
|
|
|
|
|
|
|
StopWatch timer(Env::Default());
|
|
|
|
for (auto& timing : timings) {
|
|
|
|
timing = timer.ElapsedMicros();
|
|
|
|
}
|
|
|
|
|
|
|
|
HistogramImpl histogram;
|
|
|
|
uint64_t prev_timing = 0;
|
|
|
|
for (const auto timing : timings) {
|
|
|
|
histogram.Add(timing - prev_timing);
|
|
|
|
prev_timing = timing;
|
|
|
|
}
|
|
|
|
|
|
|
|
std::cout << histogram.ToString();
|
|
|
|
}
|
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
|
|
|
void ProfileKeyComparison() {
|
2013-08-13 08:59:04 +02:00
|
|
|
DestroyDB(kDbName, Options()); // Start this test with a fresh 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
|
|
|
auto db = OpenDb(1000000000);
|
2013-08-13 08:59:04 +02:00
|
|
|
|
|
|
|
WriteOptions write_options;
|
|
|
|
ReadOptions read_options;
|
|
|
|
|
|
|
|
uint64_t total_user_key_comparison_get = 0;
|
|
|
|
uint64_t total_user_key_comparison_put = 0;
|
|
|
|
uint64_t max_user_key_comparison_get = 0;
|
|
|
|
|
|
|
|
std::cout << "Inserting " << kTotalKeys << " key/value pairs\n...\n";
|
|
|
|
|
|
|
|
for (int i = 0; i < kTotalKeys; ++i) {
|
|
|
|
std::string key = "k" + std::to_string(i);
|
|
|
|
std::string value = "v" + std::to_string(i);
|
|
|
|
|
|
|
|
perf_context.Reset();
|
|
|
|
db->Put(write_options, key, value);
|
|
|
|
total_user_key_comparison_put += perf_context.user_key_comparison_count;
|
|
|
|
|
|
|
|
perf_context.Reset();
|
|
|
|
db->Get(read_options, key, &value);
|
|
|
|
total_user_key_comparison_get += perf_context.user_key_comparison_count;
|
|
|
|
max_user_key_comparison_get =
|
|
|
|
std::max(max_user_key_comparison_get,
|
|
|
|
perf_context.user_key_comparison_count);
|
|
|
|
}
|
|
|
|
|
|
|
|
std::cout << "total user key comparison get: "
|
|
|
|
<< total_user_key_comparison_get << "\n"
|
|
|
|
<< "total user key comparison put: "
|
|
|
|
<< total_user_key_comparison_put << "\n"
|
|
|
|
<< "max user key comparison get: "
|
|
|
|
<< max_user_key_comparison_get << "\n"
|
|
|
|
<< "avg user key comparison get:"
|
|
|
|
<< total_user_key_comparison_get/kTotalKeys << "\n";
|
|
|
|
}
|
|
|
|
|
[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
|
|
|
TEST(PerfContextTest, KeyComparisonCount) {
|
|
|
|
SetPerfLevel(kDisable);
|
|
|
|
ProfileKeyComparison();
|
|
|
|
|
|
|
|
SetPerfLevel(kEnableCount);
|
|
|
|
ProfileKeyComparison();
|
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);
|
|
|
|
ProfileKeyComparison();
|
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
|
|
|
}
|
2013-08-13 08:59:04 +02:00
|
|
|
|
|
|
|
int main(int argc, char** argv) {
|
|
|
|
|
|
|
|
if (argc > 1) {
|
|
|
|
leveldb::kTotalKeys = std::stoi(argv[1]);
|
|
|
|
}
|
|
|
|
|
|
|
|
leveldb::test::RunAllTests();
|
|
|
|
return 0;
|
|
|
|
}
|