2016-05-24 08:35:23 +02:00
|
|
|
// Copyright (c) 2011-present, Facebook, Inc. All rights reserved.
|
2017-07-16 01:03:42 +02:00
|
|
|
// This source code is licensed under both the GPLv2 (found in the
|
|
|
|
// COPYING file in the root directory) and Apache 2.0 License
|
|
|
|
// (found in the LICENSE.Apache file in the root directory).
|
2016-05-24 08:35:23 +02:00
|
|
|
|
|
|
|
#include "rocksdb/utilities/sim_cache.h"
|
Don't hold DB mutex for block cache entry stat scans (#8538)
Summary:
I previously didn't notice the DB mutex was being held during
block cache entry stat scans, probably because I primarily checked for
read performance regressions, because they require the block cache and
are traditionally latency-sensitive.
This change does some refactoring to avoid holding DB mutex and to
avoid triggering and waiting for a scan in GetProperty("rocksdb.cfstats").
Some tests have to be updated because now the stats collector is
populated in the Cache aggressively on DB startup rather than lazily.
(I hope to clean up some of this added complexity in the future.)
This change also ensures proper treatment of need_out_of_mutex for
non-int DB properties.
Pull Request resolved: https://github.com/facebook/rocksdb/pull/8538
Test Plan:
Added unit test logic that uses sync points to fail if the DB mutex
is held during a scan, covering the various ways that a scan might be
triggered.
Performance test - the known impact to holding the DB mutex is on
TransactionDB, and the easiest way to see the impact is to hack the
scan code to almost always miss and take an artificially long time
scanning. Here I've injected an unconditional 5s sleep at the call to
ApplyToAllEntries.
Before (hacked):
$ TEST_TMPDIR=/dev/shm ./db_bench.base_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 433.219 micros/op 2308 ops/sec; 0.1 MB/s ( transactions:78999 aborts:0)
rocksdb.db.write.micros P50 : 16.135883 P95 : 36.622503 P99 : 66.036115 P100 : 5000614.000000 COUNT : 149677 SUM : 8364856
$ TEST_TMPDIR=/dev/shm ./db_bench.base_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 448.802 micros/op 2228 ops/sec; 0.1 MB/s ( transactions:75999 aborts:0)
rocksdb.db.write.micros P50 : 16.629221 P95 : 37.320607 P99 : 72.144341 P100 : 5000871.000000 COUNT : 143995 SUM : 13472323
Notice the 5s P100 write time.
After (hacked):
$ TEST_TMPDIR=/dev/shm ./db_bench.new_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 303.645 micros/op 3293 ops/sec; 0.1 MB/s ( transactions:98999 aborts:0)
rocksdb.db.write.micros P50 : 16.061871 P95 : 33.978834 P99 : 60.018017 P100 : 616315.000000 COUNT : 187619 SUM : 4097407
$ TEST_TMPDIR=/dev/shm ./db_bench.new_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 310.383 micros/op 3221 ops/sec; 0.1 MB/s ( transactions:96999 aborts:0)
rocksdb.db.write.micros P50 : 16.270026 P95 : 35.786844 P99 : 64.302878 P100 : 603088.000000 COUNT : 183819 SUM : 4095918
P100 write is now ~0.6s. Not good, but it's the same even if I completely bypass all the scanning code:
$ TEST_TMPDIR=/dev/shm ./db_bench.new_skip -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 311.365 micros/op 3211 ops/sec; 0.1 MB/s ( transactions:96999 aborts:0)
rocksdb.db.write.micros P50 : 16.274362 P95 : 36.221184 P99 : 68.809783 P100 : 649808.000000 COUNT : 183819 SUM : 4156767
$ TEST_TMPDIR=/dev/shm ./db_bench.new_skip -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 308.395 micros/op 3242 ops/sec; 0.1 MB/s ( transactions:97999 aborts:0)
rocksdb.db.write.micros P50 : 16.106222 P95 : 37.202403 P99 : 67.081875 P100 : 598091.000000 COUNT : 185714 SUM : 4098832
No substantial difference.
Reviewed By: siying
Differential Revision: D29738847
Pulled By: pdillinger
fbshipit-source-id: 1c5c155f5a1b62e4fea0fd4eeb515a8b7474027b
2021-07-16 23:12:06 +02:00
|
|
|
|
2016-05-24 08:35:23 +02:00
|
|
|
#include <cstdlib>
|
Don't hold DB mutex for block cache entry stat scans (#8538)
Summary:
I previously didn't notice the DB mutex was being held during
block cache entry stat scans, probably because I primarily checked for
read performance regressions, because they require the block cache and
are traditionally latency-sensitive.
This change does some refactoring to avoid holding DB mutex and to
avoid triggering and waiting for a scan in GetProperty("rocksdb.cfstats").
Some tests have to be updated because now the stats collector is
populated in the Cache aggressively on DB startup rather than lazily.
(I hope to clean up some of this added complexity in the future.)
This change also ensures proper treatment of need_out_of_mutex for
non-int DB properties.
Pull Request resolved: https://github.com/facebook/rocksdb/pull/8538
Test Plan:
Added unit test logic that uses sync points to fail if the DB mutex
is held during a scan, covering the various ways that a scan might be
triggered.
Performance test - the known impact to holding the DB mutex is on
TransactionDB, and the easiest way to see the impact is to hack the
scan code to almost always miss and take an artificially long time
scanning. Here I've injected an unconditional 5s sleep at the call to
ApplyToAllEntries.
Before (hacked):
$ TEST_TMPDIR=/dev/shm ./db_bench.base_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 433.219 micros/op 2308 ops/sec; 0.1 MB/s ( transactions:78999 aborts:0)
rocksdb.db.write.micros P50 : 16.135883 P95 : 36.622503 P99 : 66.036115 P100 : 5000614.000000 COUNT : 149677 SUM : 8364856
$ TEST_TMPDIR=/dev/shm ./db_bench.base_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 448.802 micros/op 2228 ops/sec; 0.1 MB/s ( transactions:75999 aborts:0)
rocksdb.db.write.micros P50 : 16.629221 P95 : 37.320607 P99 : 72.144341 P100 : 5000871.000000 COUNT : 143995 SUM : 13472323
Notice the 5s P100 write time.
After (hacked):
$ TEST_TMPDIR=/dev/shm ./db_bench.new_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 303.645 micros/op 3293 ops/sec; 0.1 MB/s ( transactions:98999 aborts:0)
rocksdb.db.write.micros P50 : 16.061871 P95 : 33.978834 P99 : 60.018017 P100 : 616315.000000 COUNT : 187619 SUM : 4097407
$ TEST_TMPDIR=/dev/shm ./db_bench.new_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 310.383 micros/op 3221 ops/sec; 0.1 MB/s ( transactions:96999 aborts:0)
rocksdb.db.write.micros P50 : 16.270026 P95 : 35.786844 P99 : 64.302878 P100 : 603088.000000 COUNT : 183819 SUM : 4095918
P100 write is now ~0.6s. Not good, but it's the same even if I completely bypass all the scanning code:
$ TEST_TMPDIR=/dev/shm ./db_bench.new_skip -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 311.365 micros/op 3211 ops/sec; 0.1 MB/s ( transactions:96999 aborts:0)
rocksdb.db.write.micros P50 : 16.274362 P95 : 36.221184 P99 : 68.809783 P100 : 649808.000000 COUNT : 183819 SUM : 4156767
$ TEST_TMPDIR=/dev/shm ./db_bench.new_skip -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 308.395 micros/op 3242 ops/sec; 0.1 MB/s ( transactions:97999 aborts:0)
rocksdb.db.write.micros P50 : 16.106222 P95 : 37.202403 P99 : 67.081875 P100 : 598091.000000 COUNT : 185714 SUM : 4098832
No substantial difference.
Reviewed By: siying
Differential Revision: D29738847
Pulled By: pdillinger
fbshipit-source-id: 1c5c155f5a1b62e4fea0fd4eeb515a8b7474027b
2021-07-16 23:12:06 +02:00
|
|
|
|
2016-05-24 08:35:23 +02:00
|
|
|
#include "db/db_test_util.h"
|
|
|
|
#include "port/stack_trace.h"
|
|
|
|
|
2020-02-20 21:07:53 +01:00
|
|
|
namespace ROCKSDB_NAMESPACE {
|
2016-05-24 08:35:23 +02:00
|
|
|
|
|
|
|
class SimCacheTest : public DBTestBase {
|
|
|
|
private:
|
|
|
|
size_t miss_count_ = 0;
|
|
|
|
size_t hit_count_ = 0;
|
|
|
|
size_t insert_count_ = 0;
|
|
|
|
size_t failure_count_ = 0;
|
|
|
|
|
|
|
|
public:
|
|
|
|
const size_t kNumBlocks = 5;
|
2016-06-03 03:39:25 +02:00
|
|
|
const size_t kValueSize = 1000;
|
2016-05-24 08:35:23 +02:00
|
|
|
|
2021-07-23 17:37:27 +02:00
|
|
|
SimCacheTest() : DBTestBase("sim_cache_test", /*env_do_fsync=*/true) {}
|
2016-05-24 08:35:23 +02:00
|
|
|
|
|
|
|
BlockBasedTableOptions GetTableOptions() {
|
|
|
|
BlockBasedTableOptions table_options;
|
|
|
|
// Set a small enough block size so that each key-value get its own block.
|
|
|
|
table_options.block_size = 1;
|
|
|
|
return table_options;
|
|
|
|
}
|
|
|
|
|
|
|
|
Options GetOptions(const BlockBasedTableOptions& table_options) {
|
|
|
|
Options options = CurrentOptions();
|
|
|
|
options.create_if_missing = true;
|
|
|
|
// options.compression = kNoCompression;
|
2020-02-20 21:07:53 +01:00
|
|
|
options.statistics = ROCKSDB_NAMESPACE::CreateDBStatistics();
|
2020-09-15 01:59:00 +02:00
|
|
|
options.table_factory.reset(NewBlockBasedTableFactory(table_options));
|
2016-05-24 08:35:23 +02:00
|
|
|
return options;
|
|
|
|
}
|
|
|
|
|
2018-03-05 22:08:17 +01:00
|
|
|
void InitTable(const Options& /*options*/) {
|
2016-05-24 08:35:23 +02:00
|
|
|
std::string value(kValueSize, 'a');
|
|
|
|
for (size_t i = 0; i < kNumBlocks * 2; i++) {
|
|
|
|
ASSERT_OK(Put(ToString(i), value.c_str()));
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
void RecordCacheCounters(const Options& options) {
|
|
|
|
miss_count_ = TestGetTickerCount(options, BLOCK_CACHE_MISS);
|
|
|
|
hit_count_ = TestGetTickerCount(options, BLOCK_CACHE_HIT);
|
|
|
|
insert_count_ = TestGetTickerCount(options, BLOCK_CACHE_ADD);
|
|
|
|
failure_count_ = TestGetTickerCount(options, BLOCK_CACHE_ADD_FAILURES);
|
|
|
|
}
|
|
|
|
|
|
|
|
void CheckCacheCounters(const Options& options, size_t expected_misses,
|
|
|
|
size_t expected_hits, size_t expected_inserts,
|
|
|
|
size_t expected_failures) {
|
|
|
|
size_t new_miss_count = TestGetTickerCount(options, BLOCK_CACHE_MISS);
|
|
|
|
size_t new_hit_count = TestGetTickerCount(options, BLOCK_CACHE_HIT);
|
|
|
|
size_t new_insert_count = TestGetTickerCount(options, BLOCK_CACHE_ADD);
|
|
|
|
size_t new_failure_count =
|
|
|
|
TestGetTickerCount(options, BLOCK_CACHE_ADD_FAILURES);
|
|
|
|
ASSERT_EQ(miss_count_ + expected_misses, new_miss_count);
|
|
|
|
ASSERT_EQ(hit_count_ + expected_hits, new_hit_count);
|
|
|
|
ASSERT_EQ(insert_count_ + expected_inserts, new_insert_count);
|
|
|
|
ASSERT_EQ(failure_count_ + expected_failures, new_failure_count);
|
|
|
|
miss_count_ = new_miss_count;
|
|
|
|
hit_count_ = new_hit_count;
|
|
|
|
insert_count_ = new_insert_count;
|
|
|
|
failure_count_ = new_failure_count;
|
|
|
|
}
|
|
|
|
};
|
|
|
|
|
|
|
|
TEST_F(SimCacheTest, SimCache) {
|
|
|
|
ReadOptions read_options;
|
|
|
|
auto table_options = GetTableOptions();
|
|
|
|
auto options = GetOptions(table_options);
|
|
|
|
InitTable(options);
|
2019-09-17 00:14:51 +02:00
|
|
|
LRUCacheOptions co;
|
|
|
|
co.capacity = 0;
|
|
|
|
co.num_shard_bits = 0;
|
|
|
|
co.strict_capacity_limit = false;
|
|
|
|
co.metadata_charge_policy = kDontChargeCacheMetadata;
|
|
|
|
std::shared_ptr<SimCache> simCache = NewSimCache(NewLRUCache(co), 20000, 0);
|
2016-05-24 08:35:23 +02:00
|
|
|
table_options.block_cache = simCache;
|
2020-09-15 01:59:00 +02:00
|
|
|
options.table_factory.reset(NewBlockBasedTableFactory(table_options));
|
2016-05-24 08:35:23 +02:00
|
|
|
Reopen(options);
|
|
|
|
RecordCacheCounters(options);
|
Don't hold DB mutex for block cache entry stat scans (#8538)
Summary:
I previously didn't notice the DB mutex was being held during
block cache entry stat scans, probably because I primarily checked for
read performance regressions, because they require the block cache and
are traditionally latency-sensitive.
This change does some refactoring to avoid holding DB mutex and to
avoid triggering and waiting for a scan in GetProperty("rocksdb.cfstats").
Some tests have to be updated because now the stats collector is
populated in the Cache aggressively on DB startup rather than lazily.
(I hope to clean up some of this added complexity in the future.)
This change also ensures proper treatment of need_out_of_mutex for
non-int DB properties.
Pull Request resolved: https://github.com/facebook/rocksdb/pull/8538
Test Plan:
Added unit test logic that uses sync points to fail if the DB mutex
is held during a scan, covering the various ways that a scan might be
triggered.
Performance test - the known impact to holding the DB mutex is on
TransactionDB, and the easiest way to see the impact is to hack the
scan code to almost always miss and take an artificially long time
scanning. Here I've injected an unconditional 5s sleep at the call to
ApplyToAllEntries.
Before (hacked):
$ TEST_TMPDIR=/dev/shm ./db_bench.base_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 433.219 micros/op 2308 ops/sec; 0.1 MB/s ( transactions:78999 aborts:0)
rocksdb.db.write.micros P50 : 16.135883 P95 : 36.622503 P99 : 66.036115 P100 : 5000614.000000 COUNT : 149677 SUM : 8364856
$ TEST_TMPDIR=/dev/shm ./db_bench.base_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 448.802 micros/op 2228 ops/sec; 0.1 MB/s ( transactions:75999 aborts:0)
rocksdb.db.write.micros P50 : 16.629221 P95 : 37.320607 P99 : 72.144341 P100 : 5000871.000000 COUNT : 143995 SUM : 13472323
Notice the 5s P100 write time.
After (hacked):
$ TEST_TMPDIR=/dev/shm ./db_bench.new_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 303.645 micros/op 3293 ops/sec; 0.1 MB/s ( transactions:98999 aborts:0)
rocksdb.db.write.micros P50 : 16.061871 P95 : 33.978834 P99 : 60.018017 P100 : 616315.000000 COUNT : 187619 SUM : 4097407
$ TEST_TMPDIR=/dev/shm ./db_bench.new_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 310.383 micros/op 3221 ops/sec; 0.1 MB/s ( transactions:96999 aborts:0)
rocksdb.db.write.micros P50 : 16.270026 P95 : 35.786844 P99 : 64.302878 P100 : 603088.000000 COUNT : 183819 SUM : 4095918
P100 write is now ~0.6s. Not good, but it's the same even if I completely bypass all the scanning code:
$ TEST_TMPDIR=/dev/shm ./db_bench.new_skip -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 311.365 micros/op 3211 ops/sec; 0.1 MB/s ( transactions:96999 aborts:0)
rocksdb.db.write.micros P50 : 16.274362 P95 : 36.221184 P99 : 68.809783 P100 : 649808.000000 COUNT : 183819 SUM : 4156767
$ TEST_TMPDIR=/dev/shm ./db_bench.new_skip -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 308.395 micros/op 3242 ops/sec; 0.1 MB/s ( transactions:97999 aborts:0)
rocksdb.db.write.micros P50 : 16.106222 P95 : 37.202403 P99 : 67.081875 P100 : 598091.000000 COUNT : 185714 SUM : 4098832
No substantial difference.
Reviewed By: siying
Differential Revision: D29738847
Pulled By: pdillinger
fbshipit-source-id: 1c5c155f5a1b62e4fea0fd4eeb515a8b7474027b
2021-07-16 23:12:06 +02:00
|
|
|
// due to cache entry stats collector
|
|
|
|
uint64_t base_misses = simCache->get_miss_counter();
|
2016-05-24 08:35:23 +02:00
|
|
|
|
|
|
|
std::vector<std::unique_ptr<Iterator>> iterators(kNumBlocks);
|
|
|
|
Iterator* iter = nullptr;
|
|
|
|
|
|
|
|
// Load blocks into cache.
|
|
|
|
for (size_t i = 0; i < kNumBlocks; i++) {
|
|
|
|
iter = db_->NewIterator(read_options);
|
|
|
|
iter->Seek(ToString(i));
|
|
|
|
ASSERT_OK(iter->status());
|
|
|
|
CheckCacheCounters(options, 1, 0, 1, 0);
|
|
|
|
iterators[i].reset(iter);
|
|
|
|
}
|
Don't hold DB mutex for block cache entry stat scans (#8538)
Summary:
I previously didn't notice the DB mutex was being held during
block cache entry stat scans, probably because I primarily checked for
read performance regressions, because they require the block cache and
are traditionally latency-sensitive.
This change does some refactoring to avoid holding DB mutex and to
avoid triggering and waiting for a scan in GetProperty("rocksdb.cfstats").
Some tests have to be updated because now the stats collector is
populated in the Cache aggressively on DB startup rather than lazily.
(I hope to clean up some of this added complexity in the future.)
This change also ensures proper treatment of need_out_of_mutex for
non-int DB properties.
Pull Request resolved: https://github.com/facebook/rocksdb/pull/8538
Test Plan:
Added unit test logic that uses sync points to fail if the DB mutex
is held during a scan, covering the various ways that a scan might be
triggered.
Performance test - the known impact to holding the DB mutex is on
TransactionDB, and the easiest way to see the impact is to hack the
scan code to almost always miss and take an artificially long time
scanning. Here I've injected an unconditional 5s sleep at the call to
ApplyToAllEntries.
Before (hacked):
$ TEST_TMPDIR=/dev/shm ./db_bench.base_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 433.219 micros/op 2308 ops/sec; 0.1 MB/s ( transactions:78999 aborts:0)
rocksdb.db.write.micros P50 : 16.135883 P95 : 36.622503 P99 : 66.036115 P100 : 5000614.000000 COUNT : 149677 SUM : 8364856
$ TEST_TMPDIR=/dev/shm ./db_bench.base_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 448.802 micros/op 2228 ops/sec; 0.1 MB/s ( transactions:75999 aborts:0)
rocksdb.db.write.micros P50 : 16.629221 P95 : 37.320607 P99 : 72.144341 P100 : 5000871.000000 COUNT : 143995 SUM : 13472323
Notice the 5s P100 write time.
After (hacked):
$ TEST_TMPDIR=/dev/shm ./db_bench.new_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 303.645 micros/op 3293 ops/sec; 0.1 MB/s ( transactions:98999 aborts:0)
rocksdb.db.write.micros P50 : 16.061871 P95 : 33.978834 P99 : 60.018017 P100 : 616315.000000 COUNT : 187619 SUM : 4097407
$ TEST_TMPDIR=/dev/shm ./db_bench.new_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 310.383 micros/op 3221 ops/sec; 0.1 MB/s ( transactions:96999 aborts:0)
rocksdb.db.write.micros P50 : 16.270026 P95 : 35.786844 P99 : 64.302878 P100 : 603088.000000 COUNT : 183819 SUM : 4095918
P100 write is now ~0.6s. Not good, but it's the same even if I completely bypass all the scanning code:
$ TEST_TMPDIR=/dev/shm ./db_bench.new_skip -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 311.365 micros/op 3211 ops/sec; 0.1 MB/s ( transactions:96999 aborts:0)
rocksdb.db.write.micros P50 : 16.274362 P95 : 36.221184 P99 : 68.809783 P100 : 649808.000000 COUNT : 183819 SUM : 4156767
$ TEST_TMPDIR=/dev/shm ./db_bench.new_skip -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 308.395 micros/op 3242 ops/sec; 0.1 MB/s ( transactions:97999 aborts:0)
rocksdb.db.write.micros P50 : 16.106222 P95 : 37.202403 P99 : 67.081875 P100 : 598091.000000 COUNT : 185714 SUM : 4098832
No substantial difference.
Reviewed By: siying
Differential Revision: D29738847
Pulled By: pdillinger
fbshipit-source-id: 1c5c155f5a1b62e4fea0fd4eeb515a8b7474027b
2021-07-16 23:12:06 +02:00
|
|
|
ASSERT_EQ(kNumBlocks, simCache->get_hit_counter() +
|
|
|
|
simCache->get_miss_counter() - base_misses);
|
2016-05-24 08:35:23 +02:00
|
|
|
ASSERT_EQ(0, simCache->get_hit_counter());
|
|
|
|
size_t usage = simCache->GetUsage();
|
|
|
|
ASSERT_LT(0, usage);
|
|
|
|
ASSERT_EQ(usage, simCache->GetSimUsage());
|
|
|
|
simCache->SetCapacity(usage);
|
|
|
|
ASSERT_EQ(usage, simCache->GetPinnedUsage());
|
|
|
|
|
|
|
|
// Test with strict capacity limit.
|
|
|
|
simCache->SetStrictCapacityLimit(true);
|
|
|
|
iter = db_->NewIterator(read_options);
|
|
|
|
iter->Seek(ToString(kNumBlocks * 2 - 1));
|
|
|
|
ASSERT_TRUE(iter->status().IsIncomplete());
|
|
|
|
CheckCacheCounters(options, 1, 0, 0, 1);
|
|
|
|
delete iter;
|
|
|
|
iter = nullptr;
|
|
|
|
|
|
|
|
// Release iterators and access cache again.
|
|
|
|
for (size_t i = 0; i < kNumBlocks; i++) {
|
|
|
|
iterators[i].reset();
|
|
|
|
CheckCacheCounters(options, 0, 0, 0, 0);
|
|
|
|
}
|
|
|
|
// Add kNumBlocks again
|
|
|
|
for (size_t i = 0; i < kNumBlocks; i++) {
|
|
|
|
std::unique_ptr<Iterator> it(db_->NewIterator(read_options));
|
|
|
|
it->Seek(ToString(i));
|
|
|
|
ASSERT_OK(it->status());
|
|
|
|
CheckCacheCounters(options, 0, 1, 0, 0);
|
|
|
|
}
|
|
|
|
ASSERT_EQ(5, simCache->get_hit_counter());
|
|
|
|
for (size_t i = kNumBlocks; i < kNumBlocks * 2; i++) {
|
|
|
|
std::unique_ptr<Iterator> it(db_->NewIterator(read_options));
|
|
|
|
it->Seek(ToString(i));
|
|
|
|
ASSERT_OK(it->status());
|
|
|
|
CheckCacheCounters(options, 1, 0, 1, 0);
|
|
|
|
}
|
|
|
|
ASSERT_EQ(0, simCache->GetPinnedUsage());
|
Don't hold DB mutex for block cache entry stat scans (#8538)
Summary:
I previously didn't notice the DB mutex was being held during
block cache entry stat scans, probably because I primarily checked for
read performance regressions, because they require the block cache and
are traditionally latency-sensitive.
This change does some refactoring to avoid holding DB mutex and to
avoid triggering and waiting for a scan in GetProperty("rocksdb.cfstats").
Some tests have to be updated because now the stats collector is
populated in the Cache aggressively on DB startup rather than lazily.
(I hope to clean up some of this added complexity in the future.)
This change also ensures proper treatment of need_out_of_mutex for
non-int DB properties.
Pull Request resolved: https://github.com/facebook/rocksdb/pull/8538
Test Plan:
Added unit test logic that uses sync points to fail if the DB mutex
is held during a scan, covering the various ways that a scan might be
triggered.
Performance test - the known impact to holding the DB mutex is on
TransactionDB, and the easiest way to see the impact is to hack the
scan code to almost always miss and take an artificially long time
scanning. Here I've injected an unconditional 5s sleep at the call to
ApplyToAllEntries.
Before (hacked):
$ TEST_TMPDIR=/dev/shm ./db_bench.base_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 433.219 micros/op 2308 ops/sec; 0.1 MB/s ( transactions:78999 aborts:0)
rocksdb.db.write.micros P50 : 16.135883 P95 : 36.622503 P99 : 66.036115 P100 : 5000614.000000 COUNT : 149677 SUM : 8364856
$ TEST_TMPDIR=/dev/shm ./db_bench.base_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 448.802 micros/op 2228 ops/sec; 0.1 MB/s ( transactions:75999 aborts:0)
rocksdb.db.write.micros P50 : 16.629221 P95 : 37.320607 P99 : 72.144341 P100 : 5000871.000000 COUNT : 143995 SUM : 13472323
Notice the 5s P100 write time.
After (hacked):
$ TEST_TMPDIR=/dev/shm ./db_bench.new_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 303.645 micros/op 3293 ops/sec; 0.1 MB/s ( transactions:98999 aborts:0)
rocksdb.db.write.micros P50 : 16.061871 P95 : 33.978834 P99 : 60.018017 P100 : 616315.000000 COUNT : 187619 SUM : 4097407
$ TEST_TMPDIR=/dev/shm ./db_bench.new_xxx -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 310.383 micros/op 3221 ops/sec; 0.1 MB/s ( transactions:96999 aborts:0)
rocksdb.db.write.micros P50 : 16.270026 P95 : 35.786844 P99 : 64.302878 P100 : 603088.000000 COUNT : 183819 SUM : 4095918
P100 write is now ~0.6s. Not good, but it's the same even if I completely bypass all the scanning code:
$ TEST_TMPDIR=/dev/shm ./db_bench.new_skip -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 311.365 micros/op 3211 ops/sec; 0.1 MB/s ( transactions:96999 aborts:0)
rocksdb.db.write.micros P50 : 16.274362 P95 : 36.221184 P99 : 68.809783 P100 : 649808.000000 COUNT : 183819 SUM : 4156767
$ TEST_TMPDIR=/dev/shm ./db_bench.new_skip -benchmarks=randomtransaction,stats -cache_index_and_filter_blocks=1 -bloom_bits=10 -partition_index_and_filters=1 -duration=30 -stats_dump_period_sec=12 -cache_size=100000000 -statistics -transaction_db 2>&1 | egrep 'db.db.write.micros|micros/op'
randomtransaction : 308.395 micros/op 3242 ops/sec; 0.1 MB/s ( transactions:97999 aborts:0)
rocksdb.db.write.micros P50 : 16.106222 P95 : 37.202403 P99 : 67.081875 P100 : 598091.000000 COUNT : 185714 SUM : 4098832
No substantial difference.
Reviewed By: siying
Differential Revision: D29738847
Pulled By: pdillinger
fbshipit-source-id: 1c5c155f5a1b62e4fea0fd4eeb515a8b7474027b
2021-07-16 23:12:06 +02:00
|
|
|
ASSERT_EQ(3 * kNumBlocks + 1, simCache->get_hit_counter() +
|
|
|
|
simCache->get_miss_counter() - base_misses);
|
2016-05-24 08:35:23 +02:00
|
|
|
ASSERT_EQ(6, simCache->get_hit_counter());
|
|
|
|
}
|
|
|
|
|
2017-07-28 21:18:09 +02:00
|
|
|
TEST_F(SimCacheTest, SimCacheLogging) {
|
|
|
|
auto table_options = GetTableOptions();
|
|
|
|
auto options = GetOptions(table_options);
|
|
|
|
options.disable_auto_compactions = true;
|
2019-09-17 00:14:51 +02:00
|
|
|
LRUCacheOptions co;
|
|
|
|
co.capacity = 1024 * 1024;
|
|
|
|
co.metadata_charge_policy = kDontChargeCacheMetadata;
|
|
|
|
std::shared_ptr<SimCache> sim_cache = NewSimCache(NewLRUCache(co), 20000, 0);
|
2017-07-28 21:18:09 +02:00
|
|
|
table_options.block_cache = sim_cache;
|
2020-09-15 01:59:00 +02:00
|
|
|
options.table_factory.reset(NewBlockBasedTableFactory(table_options));
|
2017-07-28 21:18:09 +02:00
|
|
|
Reopen(options);
|
|
|
|
|
|
|
|
int num_block_entries = 20;
|
|
|
|
for (int i = 0; i < num_block_entries; i++) {
|
2020-08-25 01:41:42 +02:00
|
|
|
ASSERT_OK(Put(Key(i), "val"));
|
|
|
|
ASSERT_OK(Flush());
|
2017-07-28 21:18:09 +02:00
|
|
|
}
|
|
|
|
|
2018-07-14 02:18:39 +02:00
|
|
|
std::string log_file = test::PerThreadDBPath(env_, "cache_log.txt");
|
2017-07-28 21:18:09 +02:00
|
|
|
ASSERT_OK(sim_cache->StartActivityLogging(log_file, env_));
|
|
|
|
for (int i = 0; i < num_block_entries; i++) {
|
|
|
|
ASSERT_EQ(Get(Key(i)), "val");
|
|
|
|
}
|
|
|
|
for (int i = 0; i < num_block_entries; i++) {
|
|
|
|
ASSERT_EQ(Get(Key(i)), "val");
|
|
|
|
}
|
|
|
|
sim_cache->StopActivityLogging();
|
|
|
|
ASSERT_OK(sim_cache->GetActivityLoggingStatus());
|
|
|
|
|
|
|
|
std::string file_contents = "";
|
2020-08-25 01:41:42 +02:00
|
|
|
ASSERT_OK(ReadFileToString(env_, log_file, &file_contents));
|
2022-01-11 07:02:22 +01:00
|
|
|
std::istringstream contents(file_contents);
|
2017-07-28 21:18:09 +02:00
|
|
|
|
|
|
|
int lookup_num = 0;
|
|
|
|
int add_num = 0;
|
|
|
|
|
2022-01-11 07:02:22 +01:00
|
|
|
std::string line;
|
|
|
|
// count number of lookups and additions
|
|
|
|
while (std::getline(contents, line)) {
|
|
|
|
// check if the line starts with LOOKUP or ADD
|
|
|
|
if (line.rfind("LOOKUP -", 0) == 0) {
|
|
|
|
++lookup_num;
|
|
|
|
}
|
|
|
|
if (line.rfind("ADD -", 0) == 0) {
|
|
|
|
++add_num;
|
|
|
|
}
|
2017-07-28 21:18:09 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
// We asked for every block twice
|
|
|
|
ASSERT_EQ(lookup_num, num_block_entries * 2);
|
|
|
|
|
|
|
|
// We added every block only once, since the cache can hold all blocks
|
|
|
|
ASSERT_EQ(add_num, num_block_entries);
|
|
|
|
|
|
|
|
// Log things again but stop logging automatically after reaching 512 bytes
|
2020-04-20 20:37:36 +02:00
|
|
|
int max_size = 512;
|
2017-07-28 21:18:09 +02:00
|
|
|
ASSERT_OK(sim_cache->StartActivityLogging(log_file, env_, max_size));
|
|
|
|
for (int it = 0; it < 10; it++) {
|
|
|
|
for (int i = 0; i < num_block_entries; i++) {
|
|
|
|
ASSERT_EQ(Get(Key(i)), "val");
|
|
|
|
}
|
|
|
|
}
|
|
|
|
ASSERT_OK(sim_cache->GetActivityLoggingStatus());
|
|
|
|
|
|
|
|
uint64_t fsize = 0;
|
|
|
|
ASSERT_OK(env_->GetFileSize(log_file, &fsize));
|
2020-04-20 20:37:36 +02:00
|
|
|
// error margin of 100 bytes
|
2017-07-28 21:18:09 +02:00
|
|
|
ASSERT_LT(fsize, max_size + 100);
|
2020-04-20 20:37:36 +02:00
|
|
|
ASSERT_GT(fsize, max_size - 100);
|
2017-07-28 21:18:09 +02:00
|
|
|
}
|
|
|
|
|
2020-02-20 21:07:53 +01:00
|
|
|
} // namespace ROCKSDB_NAMESPACE
|
2016-05-24 08:35:23 +02:00
|
|
|
|
|
|
|
int main(int argc, char** argv) {
|
2020-02-20 21:07:53 +01:00
|
|
|
ROCKSDB_NAMESPACE::port::InstallStackTraceHandler();
|
2016-05-24 08:35:23 +02:00
|
|
|
::testing::InitGoogleTest(&argc, argv);
|
|
|
|
return RUN_ALL_TESTS();
|
|
|
|
}
|