This commit is contained in:
kumaraaryan511 2026-08-02 03:55:54 +00:00 committed by GitHub
commit 0927ea074e
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
3 changed files with 410 additions and 1 deletions

View File

@ -20,6 +20,63 @@ using ceph::bufferlist;
using ceph::Formatter;
using ceph::common::cmd_getval;
//To help in short term tracking for cache stats
static void take_cache_snapshot(BlueStore& store) {
std::lock_guard l(store.cache_stats_lock);
BlueStore::CacheStatsSnapshot snap;
snap.timestamp = ceph::mono_clock::now();
snap.onode_hits = store.logger->get(l_bluestore_onode_hits);
snap.onode_misses = store.logger->get(l_bluestore_onode_misses);
snap.onode_miss_latency_sum = store.logger->get(l_bluestore_onode_miss_lat);
snap.onode_shard_hits = store.logger->get(l_bluestore_onode_shard_hits);
snap.onode_shard_misses = store.logger->get(l_bluestore_onode_shard_misses);
snap.onode_shard_miss_latency_sum = store.logger->get(l_bluestore_onode_shard_miss_lat);
snap.buffer_read_reqs = store.logger->get(l_bluestore_buffer_read_reqs);
snap.buffer_miss_count = store.logger->get(l_bluestore_buffer_miss_lat + 1);
snap.buffer_miss_latency_sum = store.logger->get(l_bluestore_buffer_miss_lat);
store.cache_stats_snapshots.push_back(snap);
//Remove old ones
while (store.cache_stats_snapshots.size() > BlueStore::MAX_CACHE_SNAPSHOTS) {
store.cache_stats_snapshots.pop_front();
}
}
static bool get_snapshot_windows(BlueStore& store,
BlueStore::CacheStatsSnapshot& current,
BlueStore::CacheStatsSnapshot& most_recent,
BlueStore::CacheStatsSnapshot& oldest) {
std::lock_guard l(store.cache_stats_lock);
if (store.cache_stats_snapshots.empty()) {
return false;
}
// Get current values
current.timestamp = ceph::mono_clock::now();
current.onode_hits = store.logger->get(l_bluestore_onode_hits);
current.onode_misses = store.logger->get(l_bluestore_onode_misses);
current.onode_miss_latency_sum = store.logger->get(l_bluestore_onode_miss_lat);
current.onode_shard_hits = store.logger->get(l_bluestore_onode_shard_hits);
current.onode_shard_misses = store.logger->get(l_bluestore_onode_shard_misses);
current.onode_shard_miss_latency_sum = store.logger->get(l_bluestore_onode_shard_miss_lat);
current.buffer_read_reqs = store.logger->get(l_bluestore_buffer_read_reqs);
current.buffer_miss_count = store.logger->get(l_bluestore_buffer_miss_lat + 1);
current.buffer_miss_latency_sum = store.logger->get(l_bluestore_buffer_miss_lat);
if(store.cache_stats_snapshots.size() >= 2) {
most_recent = store.cache_stats_snapshots[store.cache_stats_snapshots.size() - 2];
} else {
most_recent = store.cache_stats_snapshots.back();
}
oldest = store.cache_stats_snapshots.front();
return true;
}
BlueStore::SocketHook::SocketHook(BlueStore& store)
: store(store)
{
@ -77,6 +134,11 @@ BlueStore::SocketHook::SocketHook(BlueStore& store)
this,
"clear static fragmentation score, per collection");
ceph_assert(r == 0);
r = admin_socket->register_command(
"bluestore cache stats",
this,
"print cache performance stats");
ceph_assert(r == 0);
r = admin_socket->register_command(
"bluestore show sharding ",
this,
@ -282,6 +344,278 @@ int BlueStore::SocketHook::call(
}
}
f->close_section();
return 0;
} else if (command == "bluestore cache stats") {
//Store stats at this time for short term tracking
take_cache_snapshot(store);
f->open_object_section("cache_stats");
f->open_object_section("since_startup");
f->open_object_section("onode_cache");
uint64_t onode_hits = store.logger->get(l_bluestore_onode_hits);
f->dump_unsigned("hits", onode_hits);
f->open_object_section("onode_cache_miss_latency");
auto onode_miss_tavg = store.logger->get_tavg_ns(l_bluestore_onode_miss_lat);
uint64_t onode_miss_sum_ns = onode_miss_tavg.first;
uint64_t onode_miss_count = onode_miss_tavg.second;
f->dump_unsigned("avgcount", onode_miss_count);
f->dump_format_unquoted("sum", "%" PRId64 ".%09" PRId64,
onode_miss_sum_ns / 1000000000ull,
onode_miss_sum_ns % 1000000000ull);
if (onode_miss_count) {
uint64_t avg_ns = onode_miss_sum_ns / onode_miss_count;
f->dump_format_unquoted("avgtime", "%" PRId64 ".%09" PRId64,
avg_ns / 1000000000ull,
avg_ns % 1000000000ull);
} else {
f->dump_format_unquoted("avgtime", "%" PRId64 ".%09" PRId64, 0, 0);
}
f->close_section();
f->open_object_section("onode_shard_miss_latency");
auto shard_miss_tavg = store.logger->get_tavg_ns(l_bluestore_onode_shard_miss_lat);
uint64_t shard_miss_sum_ns = shard_miss_tavg.first;
uint64_t shard_miss_count = shard_miss_tavg.second;
f->dump_unsigned("avgcount", shard_miss_count);
f->dump_format_unquoted("sum", "%" PRId64 ".%09" PRId64,
shard_miss_sum_ns / 1000000000ull,
shard_miss_sum_ns % 1000000000ull);
if (shard_miss_count) {
uint64_t avg_ns = shard_miss_sum_ns / shard_miss_count;
f->dump_format_unquoted("avgtime", "%" PRId64 ".%09" PRId64,
avg_ns / 1000000000ull,
avg_ns % 1000000000ull);
} else {
f->dump_format_unquoted("avgtime", "%" PRId64 ".%09" PRId64, 0, 0);
}
f->close_section();
uint64_t total_accesses = onode_hits + onode_miss_count;
f->dump_unsigned("total_accesses", total_accesses);
if (total_accesses > 0) {
double hit_ratio = static_cast<double>(onode_hits) / static_cast<double>(total_accesses);
f->dump_float("hit_ratio", hit_ratio);
} else {
f->dump_float("hit_ratio", 0.0);
}
f->close_section();
f->open_object_section("onode_shard");
uint64_t shard_hits = store.logger->get(l_bluestore_onode_shard_hits);
uint64_t shard_misses = store.logger->get(l_bluestore_onode_shard_misses);
f->dump_unsigned("hits", shard_hits);
f->dump_unsigned("misses", shard_misses);
uint64_t shard_total = shard_hits + shard_misses;
if (shard_total > 0) {
f->dump_float("hit_ratio", (double)shard_hits / (double)shard_total);
} else {
f->dump_float("hit_ratio", 0.0);
}
auto shard_miss_lat_tavg = store.logger->get_tavg_ns(l_bluestore_onode_shard_miss_lat);
uint64_t shard_miss_lat_sum_ns = shard_miss_lat_tavg.first;
uint64_t shard_miss_lat_count = shard_miss_lat_tavg.second;
if (shard_miss_lat_count > 0) {
uint64_t avg_ns = shard_miss_lat_sum_ns / shard_miss_lat_count;
f->dump_format_unquoted("avg_miss_latency", "%" PRId64 ".%09" PRId64,
avg_ns / 1000000000ull,
avg_ns % 1000000000ull);
}
f->close_section();
f->open_object_section("object_data_cache");
uint64_t read_reqs = store.logger->get(l_bluestore_buffer_read_reqs);
f->dump_unsigned("read_requests", read_reqs);
f->open_object_section("buffer_miss_latency");
auto buffer_miss_tavg = store.logger->get_tavg_ns(l_bluestore_buffer_miss_lat);
uint64_t buffer_miss_sum_ns = buffer_miss_tavg.first;
uint64_t buffer_miss_count = buffer_miss_tavg.second;
f->dump_unsigned("avgcount", buffer_miss_count);
f->dump_format_unquoted("sum", "%" PRId64 ".%09" PRId64,
buffer_miss_sum_ns / 1000000000ull,
buffer_miss_sum_ns % 1000000000ull);
if (buffer_miss_count) {
uint64_t avg_ns = buffer_miss_sum_ns / buffer_miss_count;
f->dump_format_unquoted("avgtime", "%" PRId64 ".%09" PRId64,
avg_ns / 1000000000ull,
avg_ns % 1000000000ull);
} else {
f->dump_format_unquoted("avgtime", "%" PRId64 ".%09" PRId64, 0, 0);
}
f->close_section();
uint64_t buffer_hits = (read_reqs > buffer_miss_count) ? (read_reqs - buffer_miss_count) : 0;
f->dump_unsigned("hits", buffer_hits);
f->dump_unsigned("misses", buffer_miss_count);
if (read_reqs > 0) {
double buffer_hit_ratio = static_cast<double>(buffer_hits) / static_cast<double>(read_reqs);
f->dump_float("hit_ratio", buffer_hit_ratio);
} else {
f->dump_float("hit_ratio", 0.0);
}
f->close_section();
f->close_section();// since_startup
// Short-term stat
BlueStore::CacheStatsSnapshot current, most_recent, oldest;
if (get_snapshot_windows(store, current, most_recent, oldest)) {
auto recent_duration = std::chrono::duration<double>(current.timestamp - most_recent.timestamp).count();
if (recent_duration > 0) {
f->open_object_section("since_most_recent_snapshot");
f->dump_float("window_seconds", recent_duration);
f->open_object_section("onode_cache");
uint64_t delta_onode_hits = current.onode_hits - most_recent.onode_hits;
uint64_t delta_onode_misses = current.onode_misses - most_recent.onode_misses;
uint64_t delta_onode_lat = current.onode_miss_latency_sum - most_recent.onode_miss_latency_sum;
f->dump_unsigned("hits", delta_onode_hits);
f->dump_unsigned("misses", delta_onode_misses);
uint64_t delta_onode_total = delta_onode_hits + delta_onode_misses;
if (delta_onode_total > 0) {
f->dump_float("hit_ratio", (double)delta_onode_hits / (double)delta_onode_total);
} else {
f->dump_float("hit_ratio", 0.0);
}
if (delta_onode_misses > 0) {
f->dump_float("avg_miss_latency_us", (double)delta_onode_lat / (double)delta_onode_misses / 1000.0);
}
f->close_section();
f->open_object_section("onode_shard");
uint64_t delta_shard_hits = current.onode_shard_hits - most_recent.onode_shard_hits;
uint64_t delta_shard_misses = current.onode_shard_misses - most_recent.onode_shard_misses;
uint64_t delta_shard_lat = current.onode_shard_miss_latency_sum - most_recent.onode_shard_miss_latency_sum;
f->dump_unsigned("hits", delta_shard_hits);
f->dump_unsigned("misses", delta_shard_misses);
uint64_t delta_shard_total = delta_shard_hits + delta_shard_misses;
if (delta_shard_total > 0) {
f->dump_float("hit_ratio", (double)delta_shard_hits / (double)delta_shard_total);
} else {
f->dump_float("hit_ratio", 0.0);
}
if (delta_shard_misses > 0) {
f->dump_float("avg_miss_latency_us", (double)delta_shard_lat / (double)delta_shard_misses / 1000.0);
}
f->close_section();
f->open_object_section("object_data_cache");
uint64_t delta_buffer_reqs = current.buffer_read_reqs - most_recent.buffer_read_reqs;
uint64_t delta_buffer_misses = current.buffer_miss_count - most_recent.buffer_miss_count;
uint64_t delta_buffer_lat = current.buffer_miss_latency_sum - most_recent.buffer_miss_latency_sum;
uint64_t delta_buffer_hits = (delta_buffer_reqs > delta_buffer_misses) ? (delta_buffer_reqs - delta_buffer_misses) : 0;
f->dump_unsigned("read_requests", delta_buffer_reqs);
f->dump_unsigned("hits", delta_buffer_hits);
f->dump_unsigned("misses", delta_buffer_misses);
if (delta_buffer_reqs > 0) {
f->dump_float("hit_ratio", (double)delta_buffer_hits / (double)delta_buffer_reqs);
} else {
f->dump_float("hit_ratio", 0.0);
}
if (delta_buffer_misses > 0) {
f->dump_float("avg_miss_latency_us", (double)delta_buffer_lat / (double)delta_buffer_misses / 1000.0);
}
f->close_section();
f->close_section();
}
auto oldest_duration = std::chrono::duration<double>(current.timestamp - oldest.timestamp).count();
if (oldest_duration > 0) {
f->open_object_section("since_oldest_snapshot");
f->dump_float("window_seconds", oldest_duration);
f->open_object_section("onode_cache");
uint64_t delta_onode_hits = current.onode_hits - oldest.onode_hits;
uint64_t delta_onode_misses = current.onode_misses - oldest.onode_misses;
uint64_t delta_onode_lat = current.onode_miss_latency_sum - oldest.onode_miss_latency_sum;
uint64_t delta_onode_total = delta_onode_hits + delta_onode_misses;
f->dump_unsigned("hits", delta_onode_hits);
f->dump_unsigned("misses", delta_onode_misses);
f->dump_unsigned("total_accesses", delta_onode_total);
if (delta_onode_total > 0) {
f->dump_float("hit_ratio", (double)delta_onode_hits / (double)delta_onode_total);
f->dump_float("accesses_per_second", (double)delta_onode_total / oldest_duration);
} else {
f->dump_float("hit_ratio", 0.0);
f->dump_float("accesses_per_second", 0.0);
}
if (delta_onode_misses > 0) {
f->dump_float("avg_miss_latency_us", (double)delta_onode_lat / (double)delta_onode_misses / 1000.0);
}
f->close_section();
f->open_object_section("onode_shard");
uint64_t delta_shard_hits = current.onode_shard_hits - oldest.onode_shard_hits;
uint64_t delta_shard_misses = current.onode_shard_misses - oldest.onode_shard_misses;
uint64_t delta_shard_lat = current.onode_shard_miss_latency_sum - oldest.onode_shard_miss_latency_sum;
f->dump_unsigned("hits", delta_shard_hits);
f->dump_unsigned("misses", delta_shard_misses);
uint64_t delta_shard_total = delta_shard_hits + delta_shard_misses;
if (delta_shard_total > 0) {
f->dump_float("hit_ratio", (double)delta_shard_hits / (double)delta_shard_total);
} else {
f->dump_float("hit_ratio", 0.0);
}
if (delta_shard_misses > 0) {
f->dump_float("avg_miss_latency_us", (double)delta_shard_lat / (double)delta_shard_misses / 1000.0);
}
f->close_section();
f->open_object_section("object_data_cache");
uint64_t delta_buffer_reqs = current.buffer_read_reqs - oldest.buffer_read_reqs;
uint64_t delta_buffer_misses = current.buffer_miss_count - oldest.buffer_miss_count;
uint64_t delta_buffer_lat = current.buffer_miss_latency_sum - oldest.buffer_miss_latency_sum;
uint64_t delta_buffer_hits = (delta_buffer_reqs > delta_buffer_misses) ? (delta_buffer_reqs - delta_buffer_misses) : 0;
f->dump_unsigned("read_requests", delta_buffer_reqs);
f->dump_unsigned("hits", delta_buffer_hits);
f->dump_unsigned("misses", delta_buffer_misses);
if (delta_buffer_reqs > 0) {
f->dump_float("hit_ratio", (double)delta_buffer_hits / (double)delta_buffer_reqs);
f->dump_float("requests_per_second", (double)delta_buffer_reqs / oldest_duration);
} else {
f->dump_float("hit_ratio", 0.0);
f->dump_float("requests_per_second", 0.0);
}
if (delta_buffer_misses > 0) {
f->dump_float("avg_miss_latency_us", (double)delta_buffer_lat / (double)delta_buffer_misses / 1000.0);
}
f->close_section();
f->close_section();
}
}
// RocksDB performance statistics (I think the hits and misses is useful, latency is not, commented out for now)
//f->open_object_section("rocksdb_perf_stats");
//auto collection = store.cct->get_perfcounters_collection();
//if (collection) {
// collection->dump_formatted(f, false, static_cast<select_labeled_t>(0), "rocksdb", "");
//} else {
// f->dump_string("status", "perf counters collection not available");
//}
//f->close_section(); // rocksdb_perf_stats
f->close_section(); // cache_stats
return 0;
} else if (command == "bluestore clear static frag") {
std::shared_lock l(store.coll_lock);

View File

@ -1928,6 +1928,7 @@ void BlueStore::BufferSpace::read(
uint64_t miss_bytes = want_bytes - hit_bytes;
cache->logger->inc(l_bluestore_buffer_hit_bytes, hit_bytes);
cache->logger->inc(l_bluestore_buffer_miss_bytes, miss_bytes);
cache->logger->inc(l_bluestore_buffer_read_reqs, 1);
}
void BlueStore::BufferSpace::_finish_write(BufferCacheShard* cache,
@ -4358,6 +4359,9 @@ void BlueStore::ExtentMap::maybe_load_shard(
ceph_assert((size_t)start < shards.size());
auto p = &shards[start];
if (!p->loaded) {
auto shard_load_start = ceph::mono_clock::now();
BLUE_SCOPE(maybe_load_shard);
dout(30) << __func__ << " opening shard 0x" << std::hex
<< p->shard_info->offset << std::dec << dendl;
@ -4383,6 +4387,11 @@ void BlueStore::ExtentMap::maybe_load_shard(
<< " (" << v.length() << " bytes)" << dendl;
ceph_assert(p->dirty == false);
ceph_assert(v.length() == p->shard_info->bytes);
auto shard_load_end = ceph::mono_clock::now();
onode->c->store->logger->tinc(l_bluestore_onode_shard_miss_lat,
shard_load_end - shard_load_start);
onode->c->store->logger->inc(l_bluestore_onode_shard_misses);
} else {
onode->c->store->logger->inc(l_bluestore_onode_shard_hits);
@ -5402,8 +5411,10 @@ BlueStore::OnodeRef BlueStore::Collection::get_onode(
}
OnodeRef o = onode_space.lookup(oid);
if (o)
if (o) {
return o;
}
auto start = mono_clock::now();//miss
BLUE_SCOPE(get_onode);
string key;
get_object_key(store->cct, oid, &key);
@ -5429,6 +5440,7 @@ BlueStore::OnodeRef BlueStore::Collection::get_onode(
// new object, load onode if available
on = Onode::create_decode(this, oid, key, v, true, store->segment_size != 0);
o.reset(on);
store->logger->tinc(l_bluestore_onode_miss_lat, mono_clock::now() - start);
return onode_space.add_onode(oid, o);
}
@ -6528,6 +6540,20 @@ void BlueStore::_init_logger()
b.add_u64_counter(l_bluestore_write_small_skipped_bytes,
"write_small_skipped_bytes",
"Small writes into existing or sparse small blobs skipped due to zero detection (bytes)");
b.add_time_avg(l_bluestore_buffer_miss_lat, "buffer_miss_lat", "Avg data cache miss disk latency"); //bluestore data buffer
b.add_u64_counter(l_bluestore_buffer_read_reqs, "buffer_read_reqs", "Total data cache read requests"); //i think subrtacting the number of requests from the number of misses above will give number of complete hits where the entire read was in cache
//after read is called it will always increment l_bluestore_buffer_read_reqs, and if there was any part that wasnt in cache it will eventually log it in l_bluestore_buffer_miss_lat, so the difference should be ones that were fully in cache
b.add_time_avg(l_bluestore_onode_miss_lat, "cacheonode_lat",
"Average onode miss latency",
"ro_l", PerfCountersBuilder::PRIO_CRITICAL);
b.add_time_avg(l_bluestore_onode_shard_miss_lat,
"onode_shard_miss_lat",
"Average onode shard miss latency");
//****************************************
// compressions stats
@ -13262,6 +13288,9 @@ int BlueStore::_do_read(
blobs2read_t blobs2read;
_read_cache(o, offset, length, read_cache_policy, ready_regions, blobs2read);
bool is_miss = !blobs2read.empty();
ceph::mono_clock::time_point miss_start_time;
// read raw blob data.
start = mono_clock::now(); // for the sake of simplicity
@ -13277,9 +13306,19 @@ int BlueStore::_do_read(
int64_t num_ios = blobs2read.size();
if (ioc.has_pending_aios()) {
num_ios = ioc.get_num_ios();
if (is_miss) {
miss_start_time = ceph::mono_clock::now();
}
bdev->aio_submit(&ioc);
dout(20) << __func__ << " waiting for aio" << dendl;
ioc.aio_wait();
if (is_miss) {
auto miss_end_time = ceph::mono_clock::now();
logger->tinc(l_bluestore_buffer_miss_lat, miss_end_time - miss_start_time);
}
r = ioc.get_return_value();
if (r < 0) {
ceph_assert(r == -EIO); // no other errors allowed
@ -13690,9 +13729,14 @@ int BlueStore::_do_readv(
auto num_ios = m.size();
if (ioc.has_pending_aios()) {
num_ios = ioc.get_num_ios();
ceph::mono_clock::time_point miss_start_time = ceph::mono_clock::now();
bdev->aio_submit(&ioc);
dout(20) << __func__ << " waiting for aio" << dendl;
ioc.aio_wait();
auto miss_end_time = ceph::mono_clock::now();
logger->tinc(l_bluestore_buffer_miss_lat, miss_end_time - miss_start_time);
r = ioc.get_return_value();
if (r < 0) {
ceph_assert(r == -EIO); // no other errors allowed

View File

@ -186,6 +186,8 @@ enum {
l_bluestore_extents,
l_bluestore_blobs,
l_bluestore_spanning_blobs,
l_bluestore_onode_miss_lat,
l_bluestore_onode_shard_miss_lat,
//****************************************
// buffer cache stats
@ -194,6 +196,8 @@ enum {
l_bluestore_buffer_bytes,
l_bluestore_buffer_hit_bytes,
l_bluestore_buffer_miss_bytes,
l_bluestore_buffer_miss_lat, ////cost per miss
l_bluestore_buffer_read_reqs,
//****************************************
// internal stats
@ -2443,6 +2447,31 @@ private:
mempool::bluestore_cache_buffer::vector<BufferCacheShard*> buffer_cache_shards;
mempool::bluestore_cache_onode::vector<OnodeCacheShard*> onode_cache_shards;
public:
struct CacheStatsSnapshot {
ceph::mono_time timestamp;
uint64_t onode_hits;
uint64_t onode_misses;
uint64_t onode_miss_latency_sum;
uint64_t onode_shard_hits;
uint64_t onode_shard_misses;
uint64_t onode_shard_miss_latency_sum;
uint64_t buffer_read_reqs;
uint64_t buffer_miss_count;
uint64_t buffer_miss_latency_sum;
CacheStatsSnapshot()
: timestamp(ceph::mono_clock::zero()),
onode_hits(0), onode_misses(0), onode_miss_latency_sum(0),
onode_shard_hits(0), onode_shard_misses(0), onode_shard_miss_latency_sum(0),
buffer_read_reqs(0), buffer_miss_count(0), buffer_miss_latency_sum(0) {}
};
ceph::mutex cache_stats_lock = ceph::make_mutex("BlueStore::cache_stats_lock");
std::deque<CacheStatsSnapshot> cache_stats_snapshots;
static constexpr size_t MAX_CACHE_SNAPSHOTS = 5;
private:
/// protect zombie_osr_set
ceph::mutex zombie_osr_lock = ceph::make_mutex("BlueStore::zombie_osr_lock");
uint32_t next_sequencer_id = 0;
@ -2484,8 +2513,10 @@ private:
std::deque<DeferredBatch*> deferred_stable_to_finalize; ///< pending finalization
bool kv_finalize_in_progress = false;
public:
PerfCounters *logger = nullptr;
private:
std::list<CollectionRef> removed_collections;
ceph::shared_mutex debug_read_error_lock =