78a309bf86
Summary: Adds a new Cache::ApplyToAllEntries API that we expect to use (in follow-up PRs) for efficiently gathering block cache statistics. Notable features vs. old ApplyToAllCacheEntries: * Includes key and deleter (in addition to value and charge). We could have passed in a Handle but then more virtual function calls would be needed to get the "fields" of each entry. We expect to use the 'deleter' to identify the origin of entries, perhaps even more. * Heavily tuned to minimize latency impact on operating cache. It does this by iterating over small sections of each cache shard while cycling through the shards. * Supports tuning roughly how many entries to operate on for each lock acquire and release, to control the impact on the latency of other operations without excessive lock acquire & release. The right balance can depend on the cost of the callback. Good default seems to be around 256. * There should be no need to disable thread safety. (I would expect uncontended locks to be sufficiently fast.) I have enhanced cache_bench to validate this approach: * Reports a histogram of ns per operation, so we can look at the ditribution of times, not just throughput (average). * Can add a thread for simulated "gather stats" which calls ApplyToAllEntries at a specified interval. We also generate a histogram of time to run ApplyToAllEntries. To make the iteration over some entries of each shard work as cleanly as possible, even with resize between next set of entries, I have re-arranged which hash bits are used for sharding and which for indexing within a shard. Pull Request resolved: https://github.com/facebook/rocksdb/pull/8225 Test Plan: A couple of unit tests are added, but primary validation is manual, as the primary risk is to performance. The primary validation is using cache_bench to ensure that neither the minor hashing changes nor the simulated stats gathering significantly impact QPS or latency distribution. Note that adding op latency histogram seriously impacts the benchmark QPS, so for a fair baseline, we need the cache_bench changes (except remove simulated stat gathering to make it compile). In short, we don't see any reproducible difference in ops/sec or op latency unless we are gathering stats nearly continuously. Test uses 10GB block cache with 8KB values to be somewhat realistic in the number of items to iterate over. Baseline typical output: ``` Complete in 92.017 s; Rough parallel ops/sec = 869401 Thread ops/sec = 54662 Operation latency (ns): Count: 80000000 Average: 11223.9494 StdDev: 29.61 Min: 0 Median: 7759.3973 Max: 9620500 Percentiles: P50: 7759.40 P75: 14190.73 P99: 46922.75 P99.9: 77509.84 P99.99: 217030.58 ------------------------------------------------------ [ 0, 1 ] 68 0.000% 0.000% ( 2900, 4400 ] 89 0.000% 0.000% ( 4400, 6600 ] 33630240 42.038% 42.038% ######## ( 6600, 9900 ] 18129842 22.662% 64.700% ##### ( 9900, 14000 ] 7877533 9.847% 74.547% ## ( 14000, 22000 ] 15193238 18.992% 93.539% #### ( 22000, 33000 ] 3037061 3.796% 97.335% # ( 33000, 50000 ] 1626316 2.033% 99.368% ( 50000, 75000 ] 421532 0.527% 99.895% ( 75000, 110000 ] 56910 0.071% 99.966% ( 110000, 170000 ] 16134 0.020% 99.986% ( 170000, 250000 ] 5166 0.006% 99.993% ( 250000, 380000 ] 3017 0.004% 99.996% ( 380000, 570000 ] 1337 0.002% 99.998% ( 570000, 860000 ] 805 0.001% 99.999% ( 860000, 1200000 ] 319 0.000% 100.000% ( 1200000, 1900000 ] 231 0.000% 100.000% ( 1900000, 2900000 ] 100 0.000% 100.000% ( 2900000, 4300000 ] 39 0.000% 100.000% ( 4300000, 6500000 ] 16 0.000% 100.000% ( 6500000, 9800000 ] 7 0.000% 100.000% ``` New, gather_stats=false. Median thread ops/sec of 5 runs: ``` Complete in 92.030 s; Rough parallel ops/sec = 869285 Thread ops/sec = 54458 Operation latency (ns): Count: 80000000 Average: 11298.1027 StdDev: 42.18 Min: 0 Median: 7722.0822 Max: 6398720 Percentiles: P50: 7722.08 P75: 14294.68 P99: 47522.95 P99.9: 85292.16 P99.99: 228077.78 ------------------------------------------------------ [ 0, 1 ] 109 0.000% 0.000% ( 2900, 4400 ] 793 0.001% 0.001% ( 4400, 6600 ] 34054563 42.568% 42.569% ######### ( 6600, 9900 ] 17482646 21.853% 64.423% #### ( 9900, 14000 ] 7908180 9.885% 74.308% ## ( 14000, 22000 ] 15032072 18.790% 93.098% #### ( 22000, 33000 ] 3237834 4.047% 97.145% # ( 33000, 50000 ] 1736882 2.171% 99.316% ( 50000, 75000 ] 446851 0.559% 99.875% ( 75000, 110000 ] 68251 0.085% 99.960% ( 110000, 170000 ] 18592 0.023% 99.983% ( 170000, 250000 ] 7200 0.009% 99.992% ( 250000, 380000 ] 3334 0.004% 99.997% ( 380000, 570000 ] 1393 0.002% 99.998% ( 570000, 860000 ] 700 0.001% 99.999% ( 860000, 1200000 ] 293 0.000% 100.000% ( 1200000, 1900000 ] 196 0.000% 100.000% ( 1900000, 2900000 ] 69 0.000% 100.000% ( 2900000, 4300000 ] 32 0.000% 100.000% ( 4300000, 6500000 ] 10 0.000% 100.000% ``` New, gather_stats=true, 1 second delay between scans. Scans take about 1 second here so it's spending about 50% time scanning. Still the effect on ops/sec and latency seems to be in the noise. Median thread ops/sec of 5 runs: ``` Complete in 91.890 s; Rough parallel ops/sec = 870608 Thread ops/sec = 54551 Operation latency (ns): Count: 80000000 Average: 11311.2629 StdDev: 45.28 Min: 0 Median: 7686.5458 Max: 10018340 Percentiles: P50: 7686.55 P75: 14481.95 P99: 47232.60 P99.9: 79230.18 P99.99: 232998.86 ------------------------------------------------------ [ 0, 1 ] 71 0.000% 0.000% ( 2900, 4400 ] 291 0.000% 0.000% ( 4400, 6600 ] 34492060 43.115% 43.116% ######### ( 6600, 9900 ] 16727328 20.909% 64.025% #### ( 9900, 14000 ] 7845828 9.807% 73.832% ## ( 14000, 22000 ] 15510654 19.388% 93.220% #### ( 22000, 33000 ] 3216533 4.021% 97.241% # ( 33000, 50000 ] 1680859 2.101% 99.342% ( 50000, 75000 ] 439059 0.549% 99.891% ( 75000, 110000 ] 60540 0.076% 99.967% ( 110000, 170000 ] 14649 0.018% 99.985% ( 170000, 250000 ] 5242 0.007% 99.991% ( 250000, 380000 ] 3260 0.004% 99.995% ( 380000, 570000 ] 1599 0.002% 99.997% ( 570000, 860000 ] 1043 0.001% 99.999% ( 860000, 1200000 ] 471 0.001% 99.999% ( 1200000, 1900000 ] 275 0.000% 100.000% ( 1900000, 2900000 ] 143 0.000% 100.000% ( 2900000, 4300000 ] 60 0.000% 100.000% ( 4300000, 6500000 ] 27 0.000% 100.000% ( 6500000, 9800000 ] 7 0.000% 100.000% ( 9800000, 14000000 ] 1 0.000% 100.000% Gather stats latency (us): Count: 46 Average: 980387.5870 StdDev: 60911.18 Min: 879155 Median: 1033777.7778 Max: 1261431 Percentiles: P50: 1033777.78 P75: 1120666.67 P99: 1261431.00 P99.9: 1261431.00 P99.99: 1261431.00 ------------------------------------------------------ ( 860000, 1200000 ] 45 97.826% 97.826% #################### ( 1200000, 1900000 ] 1 2.174% 100.000% Most recent cache entry stats: Number of entries: 1295133 Total charge: 9.88 GB Average key size: 23.4982 Average charge: 8.00 KB Unique deleters: 3 ``` Reviewed By: mrambacher Differential Revision: D28295742 Pulled By: pdillinger fbshipit-source-id: bbc4a552f91ba0fe10e5cc025c42cef5a81f2b95
363 lines
11 KiB
C++
363 lines
11 KiB
C++
// Copyright (c) 2011-present, Facebook, Inc. All rights reserved.
|
|
// 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).
|
|
|
|
#include "rocksdb/utilities/sim_cache.h"
|
|
|
|
#include <atomic>
|
|
|
|
#include "file/writable_file_writer.h"
|
|
#include "monitoring/statistics.h"
|
|
#include "port/port.h"
|
|
#include "rocksdb/env.h"
|
|
#include "rocksdb/file_system.h"
|
|
#include "util/mutexlock.h"
|
|
#include "util/string_util.h"
|
|
|
|
namespace ROCKSDB_NAMESPACE {
|
|
|
|
namespace {
|
|
|
|
class CacheActivityLogger {
|
|
public:
|
|
CacheActivityLogger()
|
|
: activity_logging_enabled_(false), max_logging_size_(0) {}
|
|
|
|
~CacheActivityLogger() {
|
|
MutexLock l(&mutex_);
|
|
|
|
StopLoggingInternal();
|
|
bg_status_.PermitUncheckedError();
|
|
}
|
|
|
|
Status StartLogging(const std::string& activity_log_file, Env* env,
|
|
uint64_t max_logging_size = 0) {
|
|
assert(activity_log_file != "");
|
|
assert(env != nullptr);
|
|
|
|
Status status;
|
|
FileOptions file_opts;
|
|
|
|
MutexLock l(&mutex_);
|
|
|
|
// Stop existing logging if any
|
|
StopLoggingInternal();
|
|
|
|
// Open log file
|
|
status = WritableFileWriter::Create(env->GetFileSystem(), activity_log_file,
|
|
file_opts, &file_writer_, nullptr);
|
|
if (!status.ok()) {
|
|
return status;
|
|
}
|
|
|
|
max_logging_size_ = max_logging_size;
|
|
activity_logging_enabled_.store(true);
|
|
|
|
return status;
|
|
}
|
|
|
|
void StopLogging() {
|
|
MutexLock l(&mutex_);
|
|
|
|
StopLoggingInternal();
|
|
}
|
|
|
|
void ReportLookup(const Slice& key) {
|
|
if (activity_logging_enabled_.load() == false) {
|
|
return;
|
|
}
|
|
|
|
std::string log_line = "LOOKUP - " + key.ToString(true) + "\n";
|
|
|
|
// line format: "LOOKUP - <KEY>"
|
|
MutexLock l(&mutex_);
|
|
Status s = file_writer_->Append(log_line);
|
|
if (!s.ok() && bg_status_.ok()) {
|
|
bg_status_ = s;
|
|
}
|
|
if (MaxLoggingSizeReached() || !bg_status_.ok()) {
|
|
// Stop logging if we have reached the max file size or
|
|
// encountered an error
|
|
StopLoggingInternal();
|
|
}
|
|
}
|
|
|
|
void ReportAdd(const Slice& key, size_t size) {
|
|
if (activity_logging_enabled_.load() == false) {
|
|
return;
|
|
}
|
|
|
|
std::string log_line = "ADD - ";
|
|
log_line += key.ToString(true);
|
|
log_line += " - ";
|
|
AppendNumberTo(&log_line, size);
|
|
log_line += "\n";
|
|
|
|
// line format: "ADD - <KEY> - <KEY-SIZE>"
|
|
MutexLock l(&mutex_);
|
|
Status s = file_writer_->Append(log_line);
|
|
if (!s.ok() && bg_status_.ok()) {
|
|
bg_status_ = s;
|
|
}
|
|
|
|
if (MaxLoggingSizeReached() || !bg_status_.ok()) {
|
|
// Stop logging if we have reached the max file size or
|
|
// encountered an error
|
|
StopLoggingInternal();
|
|
}
|
|
}
|
|
|
|
Status& bg_status() {
|
|
MutexLock l(&mutex_);
|
|
return bg_status_;
|
|
}
|
|
|
|
private:
|
|
bool MaxLoggingSizeReached() {
|
|
mutex_.AssertHeld();
|
|
|
|
return (max_logging_size_ > 0 &&
|
|
file_writer_->GetFileSize() >= max_logging_size_);
|
|
}
|
|
|
|
void StopLoggingInternal() {
|
|
mutex_.AssertHeld();
|
|
|
|
if (!activity_logging_enabled_) {
|
|
return;
|
|
}
|
|
|
|
activity_logging_enabled_.store(false);
|
|
Status s = file_writer_->Close();
|
|
if (!s.ok() && bg_status_.ok()) {
|
|
bg_status_ = s;
|
|
}
|
|
}
|
|
|
|
// Mutex to sync writes to file_writer, and all following
|
|
// class data members
|
|
port::Mutex mutex_;
|
|
// Indicates if logging is currently enabled
|
|
// atomic to allow reads without mutex
|
|
std::atomic<bool> activity_logging_enabled_;
|
|
// When reached, we will stop logging and close the file
|
|
// Value of 0 means unlimited
|
|
uint64_t max_logging_size_;
|
|
std::unique_ptr<WritableFileWriter> file_writer_;
|
|
Status bg_status_;
|
|
};
|
|
|
|
// SimCacheImpl definition
|
|
class SimCacheImpl : public SimCache {
|
|
public:
|
|
// capacity for real cache (ShardedLRUCache)
|
|
// test_capacity for key only cache
|
|
SimCacheImpl(std::shared_ptr<Cache> sim_cache, std::shared_ptr<Cache> cache)
|
|
: cache_(cache),
|
|
key_only_cache_(sim_cache),
|
|
miss_times_(0),
|
|
hit_times_(0),
|
|
stats_(nullptr) {}
|
|
|
|
~SimCacheImpl() override {}
|
|
void SetCapacity(size_t capacity) override { cache_->SetCapacity(capacity); }
|
|
|
|
void SetStrictCapacityLimit(bool strict_capacity_limit) override {
|
|
cache_->SetStrictCapacityLimit(strict_capacity_limit);
|
|
}
|
|
|
|
Status Insert(const Slice& key, void* value, size_t charge,
|
|
void (*deleter)(const Slice& key, void* value), Handle** handle,
|
|
Priority priority) override {
|
|
// The handle and value passed in are for real cache, so we pass nullptr
|
|
// to key_only_cache_ for both instead. Also, the deleter function pointer
|
|
// will be called by user to perform some external operation which should
|
|
// be applied only once. Thus key_only_cache accepts an empty function.
|
|
// *Lambda function without capture can be assgined to a function pointer
|
|
Handle* h = key_only_cache_->Lookup(key);
|
|
if (h == nullptr) {
|
|
// TODO: Check for error here?
|
|
auto s = key_only_cache_->Insert(
|
|
key, nullptr, charge, [](const Slice& /*k*/, void* /*v*/) {}, nullptr,
|
|
priority);
|
|
s.PermitUncheckedError();
|
|
} else {
|
|
key_only_cache_->Release(h);
|
|
}
|
|
|
|
cache_activity_logger_.ReportAdd(key, charge);
|
|
if (!cache_) {
|
|
return Status::OK();
|
|
}
|
|
return cache_->Insert(key, value, charge, deleter, handle, priority);
|
|
}
|
|
|
|
Handle* Lookup(const Slice& key, Statistics* stats) override {
|
|
Handle* h = key_only_cache_->Lookup(key);
|
|
if (h != nullptr) {
|
|
key_only_cache_->Release(h);
|
|
inc_hit_counter();
|
|
RecordTick(stats, SIM_BLOCK_CACHE_HIT);
|
|
} else {
|
|
inc_miss_counter();
|
|
RecordTick(stats, SIM_BLOCK_CACHE_MISS);
|
|
}
|
|
|
|
cache_activity_logger_.ReportLookup(key);
|
|
if (!cache_) {
|
|
return nullptr;
|
|
}
|
|
return cache_->Lookup(key, stats);
|
|
}
|
|
|
|
bool Ref(Handle* handle) override { return cache_->Ref(handle); }
|
|
|
|
bool Release(Handle* handle, bool force_erase = false) override {
|
|
return cache_->Release(handle, force_erase);
|
|
}
|
|
|
|
void Erase(const Slice& key) override {
|
|
cache_->Erase(key);
|
|
key_only_cache_->Erase(key);
|
|
}
|
|
|
|
void* Value(Handle* handle) override { return cache_->Value(handle); }
|
|
|
|
uint64_t NewId() override { return cache_->NewId(); }
|
|
|
|
size_t GetCapacity() const override { return cache_->GetCapacity(); }
|
|
|
|
bool HasStrictCapacityLimit() const override {
|
|
return cache_->HasStrictCapacityLimit();
|
|
}
|
|
|
|
size_t GetUsage() const override { return cache_->GetUsage(); }
|
|
|
|
size_t GetUsage(Handle* handle) const override {
|
|
return cache_->GetUsage(handle);
|
|
}
|
|
|
|
size_t GetCharge(Handle* handle) const override {
|
|
return cache_->GetCharge(handle);
|
|
}
|
|
|
|
size_t GetPinnedUsage() const override { return cache_->GetPinnedUsage(); }
|
|
|
|
void DisownData() override {
|
|
cache_->DisownData();
|
|
key_only_cache_->DisownData();
|
|
}
|
|
|
|
void ApplyToAllCacheEntries(void (*callback)(void*, size_t),
|
|
bool thread_safe) override {
|
|
// only apply to _cache since key_only_cache doesn't hold value
|
|
cache_->ApplyToAllCacheEntries(callback, thread_safe);
|
|
}
|
|
|
|
void ApplyToAllEntries(
|
|
const std::function<void(const Slice& key, void* value, size_t charge,
|
|
DeleterFn deleter)>& callback,
|
|
const ApplyToAllEntriesOptions& opts) override {
|
|
cache_->ApplyToAllEntries(callback, opts);
|
|
}
|
|
|
|
void EraseUnRefEntries() override {
|
|
cache_->EraseUnRefEntries();
|
|
key_only_cache_->EraseUnRefEntries();
|
|
}
|
|
|
|
size_t GetSimCapacity() const override {
|
|
return key_only_cache_->GetCapacity();
|
|
}
|
|
size_t GetSimUsage() const override { return key_only_cache_->GetUsage(); }
|
|
void SetSimCapacity(size_t capacity) override {
|
|
key_only_cache_->SetCapacity(capacity);
|
|
}
|
|
|
|
uint64_t get_miss_counter() const override {
|
|
return miss_times_.load(std::memory_order_relaxed);
|
|
}
|
|
|
|
uint64_t get_hit_counter() const override {
|
|
return hit_times_.load(std::memory_order_relaxed);
|
|
}
|
|
|
|
void reset_counter() override {
|
|
miss_times_.store(0, std::memory_order_relaxed);
|
|
hit_times_.store(0, std::memory_order_relaxed);
|
|
SetTickerCount(stats_, SIM_BLOCK_CACHE_HIT, 0);
|
|
SetTickerCount(stats_, SIM_BLOCK_CACHE_MISS, 0);
|
|
}
|
|
|
|
std::string ToString() const override {
|
|
std::string res;
|
|
res.append("SimCache MISSes: " + std::to_string(get_miss_counter()) + "\n");
|
|
res.append("SimCache HITs: " + std::to_string(get_hit_counter()) + "\n");
|
|
char buff[350];
|
|
auto lookups = get_miss_counter() + get_hit_counter();
|
|
snprintf(buff, sizeof(buff), "SimCache HITRATE: %.2f%%\n",
|
|
(lookups == 0 ? 0 : get_hit_counter() * 100.0f / lookups));
|
|
res.append(buff);
|
|
return res;
|
|
}
|
|
|
|
std::string GetPrintableOptions() const override {
|
|
std::string ret;
|
|
ret.reserve(20000);
|
|
ret.append(" cache_options:\n");
|
|
ret.append(cache_->GetPrintableOptions());
|
|
ret.append(" sim_cache_options:\n");
|
|
ret.append(key_only_cache_->GetPrintableOptions());
|
|
return ret;
|
|
}
|
|
|
|
Status StartActivityLogging(const std::string& activity_log_file, Env* env,
|
|
uint64_t max_logging_size = 0) override {
|
|
return cache_activity_logger_.StartLogging(activity_log_file, env,
|
|
max_logging_size);
|
|
}
|
|
|
|
void StopActivityLogging() override { cache_activity_logger_.StopLogging(); }
|
|
|
|
Status GetActivityLoggingStatus() override {
|
|
return cache_activity_logger_.bg_status();
|
|
}
|
|
|
|
private:
|
|
std::shared_ptr<Cache> cache_;
|
|
std::shared_ptr<Cache> key_only_cache_;
|
|
std::atomic<uint64_t> miss_times_;
|
|
std::atomic<uint64_t> hit_times_;
|
|
Statistics* stats_;
|
|
CacheActivityLogger cache_activity_logger_;
|
|
|
|
void inc_miss_counter() {
|
|
miss_times_.fetch_add(1, std::memory_order_relaxed);
|
|
}
|
|
void inc_hit_counter() { hit_times_.fetch_add(1, std::memory_order_relaxed); }
|
|
};
|
|
|
|
} // end anonymous namespace
|
|
|
|
// For instrumentation purpose, use NewSimCache instead
|
|
std::shared_ptr<SimCache> NewSimCache(std::shared_ptr<Cache> cache,
|
|
size_t sim_capacity, int num_shard_bits) {
|
|
LRUCacheOptions co;
|
|
co.capacity = sim_capacity;
|
|
co.num_shard_bits = num_shard_bits;
|
|
co.metadata_charge_policy = kDontChargeCacheMetadata;
|
|
return NewSimCache(NewLRUCache(co), cache, num_shard_bits);
|
|
}
|
|
|
|
std::shared_ptr<SimCache> NewSimCache(std::shared_ptr<Cache> sim_cache,
|
|
std::shared_ptr<Cache> cache,
|
|
int num_shard_bits) {
|
|
if (num_shard_bits >= 20) {
|
|
return nullptr; // the cache cannot be sharded into too many fine pieces
|
|
}
|
|
return std::make_shared<SimCacheImpl>(sim_cache, cache);
|
|
}
|
|
|
|
} // namespace ROCKSDB_NAMESPACE
|