From 5ec8441feaade78fb7913d0c3fecde4943d18886 Mon Sep 17 00:00:00 2001 From: Bryan Call Date: Wed, 28 Jan 2026 22:54:47 -0800 Subject: [PATCH 1/3] Add stripe lock contention metric Adds proxy.process.cache.stripe.lock_contention counter that increments each time a thread fails to acquire the stripe mutex. This helps identify cache lock contention issues when tuning thread counts vs volume counts. Also available per-volume as proxy.process.cache.volume_N.stripe.lock_contention --- src/iocore/cache/CacheProcessor.cc | 71 +++++++++++++++--------------- src/iocore/cache/P_CacheInternal.h | 12 +++++ src/iocore/cache/P_CacheStats.h | 71 +++++++++++++++--------------- 3 files changed, 84 insertions(+), 70 deletions(-) diff --git a/src/iocore/cache/CacheProcessor.cc b/src/iocore/cache/CacheProcessor.cc index 5610ed7040b..2407934a699 100644 --- a/src/iocore/cache/CacheProcessor.cc +++ b/src/iocore/cache/CacheProcessor.cc @@ -1115,41 +1115,42 @@ register_cache_stats(CacheStatsBlock *rsb, const std::string &prefix) rsb->fragment_document_count[2] = ts::Metrics::Counter::createPtr(prefix + ".frags_per_doc.3+"); // And then everything else - rsb->bytes_used = ts::Metrics::Gauge::createPtr(prefix + ".bytes_used"); - rsb->bytes_total = ts::Metrics::Gauge::createPtr(prefix + ".bytes_total"); - rsb->stripes = ts::Metrics::Gauge::createPtr(prefix + ".stripes"); - rsb->ram_cache_bytes_total = ts::Metrics::Gauge::createPtr(prefix + ".ram_cache.total_bytes"); - rsb->ram_cache_bytes = ts::Metrics::Gauge::createPtr(prefix + ".ram_cache.bytes_used"); - rsb->ram_cache_hits = ts::Metrics::Counter::createPtr(prefix + ".ram_cache.hits"); - rsb->last_open_read_hits = ts::Metrics::Counter::createPtr(prefix + ".last_open_read.hits"); - rsb->agg_buffer_hits = ts::Metrics::Counter::createPtr(prefix + ".aggregation_buffer.hits"); - rsb->ram_cache_misses = ts::Metrics::Counter::createPtr(prefix + ".ram_cache.misses"); - rsb->all_mem_misses = ts::Metrics::Counter::createPtr(prefix + ".all_memory_caches.misses"); - rsb->pread_count = ts::Metrics::Counter::createPtr(prefix + ".pread_count"); - rsb->percent_full = ts::Metrics::Gauge::createPtr(prefix + ".percent_full"); - rsb->read_seek_fail = ts::Metrics::Counter::createPtr(prefix + ".read.seek.failure"); - rsb->read_invalid = ts::Metrics::Counter::createPtr(prefix + ".read.invalid"); - rsb->write_backlog_failure = ts::Metrics::Counter::createPtr(prefix + ".write.backlog.failure"); - rsb->direntries_total = ts::Metrics::Gauge::createPtr(prefix + ".direntries.total"); - rsb->direntries_used = ts::Metrics::Gauge::createPtr(prefix + ".direntries.used"); - rsb->directory_collision = ts::Metrics::Counter::createPtr(prefix + ".directory_collision"); - rsb->read_busy_success = ts::Metrics::Counter::createPtr(prefix + ".read_busy.success"); - rsb->read_busy_failure = ts::Metrics::Counter::createPtr(prefix + ".read_busy.failure"); - rsb->write_bytes = ts::Metrics::Counter::createPtr(prefix + ".write_bytes_stat"); - rsb->hdr_vector_marshal = ts::Metrics::Counter::createPtr(prefix + ".vector_marshals"); - rsb->hdr_marshal = ts::Metrics::Counter::createPtr(prefix + ".hdr_marshals"); - rsb->hdr_marshal_bytes = ts::Metrics::Counter::createPtr(prefix + ".hdr_marshal_bytes"); - rsb->gc_bytes_evacuated = ts::Metrics::Counter::createPtr(prefix + ".gc_bytes_evacuated"); - rsb->gc_frags_evacuated = ts::Metrics::Counter::createPtr(prefix + ".gc_frags_evacuated"); - rsb->directory_wrap = ts::Metrics::Counter::createPtr(prefix + ".wrap_count"); - rsb->directory_sync_count = ts::Metrics::Counter::createPtr(prefix + ".sync.count"); - rsb->directory_sync_bytes = ts::Metrics::Counter::createPtr(prefix + ".sync.bytes"); - rsb->directory_sync_time = ts::Metrics::Counter::createPtr(prefix + ".sync.time"); - rsb->span_errors_read = ts::Metrics::Counter::createPtr(prefix + ".span.errors.read"); - rsb->span_errors_write = ts::Metrics::Counter::createPtr(prefix + ".span.errors.write"); - rsb->span_failing = ts::Metrics::Gauge::createPtr(prefix + ".span.failing"); - rsb->span_offline = ts::Metrics::Gauge::createPtr(prefix + ".span.offline"); - rsb->span_online = ts::Metrics::Gauge::createPtr(prefix + ".span.online"); + rsb->bytes_used = ts::Metrics::Gauge::createPtr(prefix + ".bytes_used"); + rsb->bytes_total = ts::Metrics::Gauge::createPtr(prefix + ".bytes_total"); + rsb->stripes = ts::Metrics::Gauge::createPtr(prefix + ".stripes"); + rsb->ram_cache_bytes_total = ts::Metrics::Gauge::createPtr(prefix + ".ram_cache.total_bytes"); + rsb->ram_cache_bytes = ts::Metrics::Gauge::createPtr(prefix + ".ram_cache.bytes_used"); + rsb->ram_cache_hits = ts::Metrics::Counter::createPtr(prefix + ".ram_cache.hits"); + rsb->last_open_read_hits = ts::Metrics::Counter::createPtr(prefix + ".last_open_read.hits"); + rsb->agg_buffer_hits = ts::Metrics::Counter::createPtr(prefix + ".aggregation_buffer.hits"); + rsb->ram_cache_misses = ts::Metrics::Counter::createPtr(prefix + ".ram_cache.misses"); + rsb->all_mem_misses = ts::Metrics::Counter::createPtr(prefix + ".all_memory_caches.misses"); + rsb->pread_count = ts::Metrics::Counter::createPtr(prefix + ".pread_count"); + rsb->percent_full = ts::Metrics::Gauge::createPtr(prefix + ".percent_full"); + rsb->read_seek_fail = ts::Metrics::Counter::createPtr(prefix + ".read.seek.failure"); + rsb->read_invalid = ts::Metrics::Counter::createPtr(prefix + ".read.invalid"); + rsb->write_backlog_failure = ts::Metrics::Counter::createPtr(prefix + ".write.backlog.failure"); + rsb->direntries_total = ts::Metrics::Gauge::createPtr(prefix + ".direntries.total"); + rsb->direntries_used = ts::Metrics::Gauge::createPtr(prefix + ".direntries.used"); + rsb->directory_collision = ts::Metrics::Counter::createPtr(prefix + ".directory_collision"); + rsb->read_busy_success = ts::Metrics::Counter::createPtr(prefix + ".read_busy.success"); + rsb->read_busy_failure = ts::Metrics::Counter::createPtr(prefix + ".read_busy.failure"); + rsb->write_bytes = ts::Metrics::Counter::createPtr(prefix + ".write_bytes_stat"); + rsb->hdr_vector_marshal = ts::Metrics::Counter::createPtr(prefix + ".vector_marshals"); + rsb->hdr_marshal = ts::Metrics::Counter::createPtr(prefix + ".hdr_marshals"); + rsb->hdr_marshal_bytes = ts::Metrics::Counter::createPtr(prefix + ".hdr_marshal_bytes"); + rsb->gc_bytes_evacuated = ts::Metrics::Counter::createPtr(prefix + ".gc_bytes_evacuated"); + rsb->gc_frags_evacuated = ts::Metrics::Counter::createPtr(prefix + ".gc_frags_evacuated"); + rsb->directory_wrap = ts::Metrics::Counter::createPtr(prefix + ".wrap_count"); + rsb->directory_sync_count = ts::Metrics::Counter::createPtr(prefix + ".sync.count"); + rsb->directory_sync_bytes = ts::Metrics::Counter::createPtr(prefix + ".sync.bytes"); + rsb->directory_sync_time = ts::Metrics::Counter::createPtr(prefix + ".sync.time"); + rsb->span_errors_read = ts::Metrics::Counter::createPtr(prefix + ".span.errors.read"); + rsb->span_errors_write = ts::Metrics::Counter::createPtr(prefix + ".span.errors.write"); + rsb->span_failing = ts::Metrics::Gauge::createPtr(prefix + ".span.failing"); + rsb->span_offline = ts::Metrics::Gauge::createPtr(prefix + ".span.offline"); + rsb->span_online = ts::Metrics::Gauge::createPtr(prefix + ".span.online"); + rsb->stripe_lock_contention = ts::Metrics::Counter::createPtr(prefix + ".stripe.lock_contention"); } void diff --git a/src/iocore/cache/P_CacheInternal.h b/src/iocore/cache/P_CacheInternal.h index 674dd98059c..237467c0089 100644 --- a/src/iocore/cache/P_CacheInternal.h +++ b/src/iocore/cache/P_CacheInternal.h @@ -61,12 +61,20 @@ struct EvacuationBlock; #define VC_LOCK_RETRY_EVENT() \ do { \ + ts::Metrics::Counter::increment(cache_rsb.stripe_lock_contention); \ + if (stripe && stripe->cache_vol) { \ + ts::Metrics::Counter::increment(stripe->cache_vol->vol_rsb.stripe_lock_contention); \ + } \ trigger = mutex->thread_holding->schedule_in_local(this, HRTIME_MSECONDS(cache_config_mutex_retry_delay), event); \ return EVENT_CONT; \ } while (0) #define VC_SCHED_LOCK_RETRY() \ do { \ + ts::Metrics::Counter::increment(cache_rsb.stripe_lock_contention); \ + if (stripe && stripe->cache_vol) { \ + ts::Metrics::Counter::increment(stripe->cache_vol->vol_rsb.stripe_lock_contention); \ + } \ trigger = mutex->thread_holding->schedule_in_local(this, HRTIME_MSECONDS(cache_config_mutex_retry_delay)); \ return EVENT_CONT; \ } while (0) @@ -330,6 +338,10 @@ CacheVC::handleWriteLock(int /* event ATS_UNUSED */, Event *e) { CACHE_TRY_LOCK(lock, stripe->mutex, mutex->thread_holding); if (!lock.is_locked()) { + ts::Metrics::Counter::increment(cache_rsb.stripe_lock_contention); + if (stripe && stripe->cache_vol) { + ts::Metrics::Counter::increment(stripe->cache_vol->vol_rsb.stripe_lock_contention); + } set_agg_write_in_progress(); trigger = mutex->thread_holding->schedule_in_local(this, HRTIME_MSECONDS(cache_config_mutex_retry_delay)); return EVENT_CONT; diff --git a/src/iocore/cache/P_CacheStats.h b/src/iocore/cache/P_CacheStats.h index 4a713220ae1..b53dd1560bd 100644 --- a/src/iocore/cache/P_CacheStats.h +++ b/src/iocore/cache/P_CacheStats.h @@ -37,39 +37,40 @@ struct CacheStatsBlock { ts::Metrics::Counter::AtomicType *fragment_document_count[3] = {nullptr, nullptr, nullptr}; // For 1, 2 and 3+ fragments - ts::Metrics::Gauge::AtomicType *bytes_used = nullptr; - ts::Metrics::Gauge::AtomicType *bytes_total = nullptr; - ts::Metrics::Gauge::AtomicType *stripes = nullptr; - ts::Metrics::Gauge::AtomicType *ram_cache_bytes = nullptr; - ts::Metrics::Gauge::AtomicType *ram_cache_bytes_total = nullptr; - ts::Metrics::Gauge::AtomicType *direntries_total = nullptr; - ts::Metrics::Gauge::AtomicType *direntries_used = nullptr; - ts::Metrics::Counter::AtomicType *ram_cache_hits = nullptr; - ts::Metrics::Counter::AtomicType *last_open_read_hits = nullptr; - ts::Metrics::Counter::AtomicType *agg_buffer_hits = nullptr; - ts::Metrics::Counter::AtomicType *ram_cache_misses = nullptr; - ts::Metrics::Counter::AtomicType *all_mem_misses = nullptr; - ts::Metrics::Counter::AtomicType *pread_count = nullptr; - ts::Metrics::Gauge::AtomicType *percent_full = nullptr; - ts::Metrics::Counter::AtomicType *read_seek_fail = nullptr; - ts::Metrics::Counter::AtomicType *read_invalid = nullptr; - ts::Metrics::Counter::AtomicType *write_backlog_failure = nullptr; - ts::Metrics::Counter::AtomicType *directory_collision = nullptr; - ts::Metrics::Counter::AtomicType *read_busy_success = nullptr; - ts::Metrics::Counter::AtomicType *read_busy_failure = nullptr; - ts::Metrics::Counter::AtomicType *gc_bytes_evacuated = nullptr; - ts::Metrics::Counter::AtomicType *gc_frags_evacuated = nullptr; - ts::Metrics::Counter::AtomicType *write_bytes = nullptr; - ts::Metrics::Counter::AtomicType *hdr_vector_marshal = nullptr; - ts::Metrics::Counter::AtomicType *hdr_marshal = nullptr; - ts::Metrics::Counter::AtomicType *hdr_marshal_bytes = nullptr; - ts::Metrics::Counter::AtomicType *directory_wrap = nullptr; - ts::Metrics::Counter::AtomicType *directory_sync_count = nullptr; - ts::Metrics::Counter::AtomicType *directory_sync_time = nullptr; - ts::Metrics::Counter::AtomicType *directory_sync_bytes = nullptr; - ts::Metrics::Counter::AtomicType *span_errors_read = nullptr; - ts::Metrics::Counter::AtomicType *span_errors_write = nullptr; - ts::Metrics::Gauge::AtomicType *span_offline = nullptr; - ts::Metrics::Gauge::AtomicType *span_online = nullptr; - ts::Metrics::Gauge::AtomicType *span_failing = nullptr; + ts::Metrics::Gauge::AtomicType *bytes_used = nullptr; + ts::Metrics::Gauge::AtomicType *bytes_total = nullptr; + ts::Metrics::Gauge::AtomicType *stripes = nullptr; + ts::Metrics::Gauge::AtomicType *ram_cache_bytes = nullptr; + ts::Metrics::Gauge::AtomicType *ram_cache_bytes_total = nullptr; + ts::Metrics::Gauge::AtomicType *direntries_total = nullptr; + ts::Metrics::Gauge::AtomicType *direntries_used = nullptr; + ts::Metrics::Counter::AtomicType *ram_cache_hits = nullptr; + ts::Metrics::Counter::AtomicType *last_open_read_hits = nullptr; + ts::Metrics::Counter::AtomicType *agg_buffer_hits = nullptr; + ts::Metrics::Counter::AtomicType *ram_cache_misses = nullptr; + ts::Metrics::Counter::AtomicType *all_mem_misses = nullptr; + ts::Metrics::Counter::AtomicType *pread_count = nullptr; + ts::Metrics::Gauge::AtomicType *percent_full = nullptr; + ts::Metrics::Counter::AtomicType *read_seek_fail = nullptr; + ts::Metrics::Counter::AtomicType *read_invalid = nullptr; + ts::Metrics::Counter::AtomicType *write_backlog_failure = nullptr; + ts::Metrics::Counter::AtomicType *directory_collision = nullptr; + ts::Metrics::Counter::AtomicType *read_busy_success = nullptr; + ts::Metrics::Counter::AtomicType *read_busy_failure = nullptr; + ts::Metrics::Counter::AtomicType *gc_bytes_evacuated = nullptr; + ts::Metrics::Counter::AtomicType *gc_frags_evacuated = nullptr; + ts::Metrics::Counter::AtomicType *write_bytes = nullptr; + ts::Metrics::Counter::AtomicType *hdr_vector_marshal = nullptr; + ts::Metrics::Counter::AtomicType *hdr_marshal = nullptr; + ts::Metrics::Counter::AtomicType *hdr_marshal_bytes = nullptr; + ts::Metrics::Counter::AtomicType *directory_wrap = nullptr; + ts::Metrics::Counter::AtomicType *directory_sync_count = nullptr; + ts::Metrics::Counter::AtomicType *directory_sync_time = nullptr; + ts::Metrics::Counter::AtomicType *directory_sync_bytes = nullptr; + ts::Metrics::Counter::AtomicType *span_errors_read = nullptr; + ts::Metrics::Counter::AtomicType *span_errors_write = nullptr; + ts::Metrics::Gauge::AtomicType *span_offline = nullptr; + ts::Metrics::Gauge::AtomicType *span_online = nullptr; + ts::Metrics::Gauge::AtomicType *span_failing = nullptr; + ts::Metrics::Counter::AtomicType *stripe_lock_contention = nullptr; }; From 4bde886aa3298b02b2274d0bae685227658b6aa3 Mon Sep 17 00:00:00 2001 From: Bryan Call Date: Thu, 29 Jan 2026 07:48:18 -0800 Subject: [PATCH 2/3] Fix stripe lock contention metric accuracy Add VC_SCHED_LOCK_RETRY_NO_METRIC() macro for lock retries that are not for stripe->mutex (e.g., write_vc->mutex in read aggregation). This ensures the stripe_lock_contention metric only counts actual stripe mutex contention. --- src/iocore/cache/CacheRead.cc | 2 +- src/iocore/cache/P_CacheInternal.h | 7 +++++++ 2 files changed, 8 insertions(+), 1 deletion(-) diff --git a/src/iocore/cache/CacheRead.cc b/src/iocore/cache/CacheRead.cc index 5bdba317cad..da26e3d71cc 100644 --- a/src/iocore/cache/CacheRead.cc +++ b/src/iocore/cache/CacheRead.cc @@ -275,7 +275,7 @@ CacheVC::openReadFromWriter(int event, Event *e) CACHE_TRY_LOCK(writer_lock, write_vc->mutex, mutex->thread_holding); if (!writer_lock.is_locked()) { DDbg(dbg_ctl_cache_read_agg, "%p: key: %X lock miss", this, first_key.slice32(1)); - VC_SCHED_LOCK_RETRY(); + VC_SCHED_LOCK_RETRY_NO_METRIC(); // Not stripe->mutex, don't count as stripe contention } MUTEX_RELEASE(lock); diff --git a/src/iocore/cache/P_CacheInternal.h b/src/iocore/cache/P_CacheInternal.h index 237467c0089..53e88975d65 100644 --- a/src/iocore/cache/P_CacheInternal.h +++ b/src/iocore/cache/P_CacheInternal.h @@ -79,6 +79,13 @@ struct EvacuationBlock; return EVENT_CONT; \ } while (0) +// Variant without metric increment for non-stripe lock retries (e.g., write_vc->mutex) +#define VC_SCHED_LOCK_RETRY_NO_METRIC() \ + do { \ + trigger = mutex->thread_holding->schedule_in_local(this, HRTIME_MSECONDS(cache_config_mutex_retry_delay)); \ + return EVENT_CONT; \ + } while (0) + #define CONT_SCHED_LOCK_RETRY_RET(_c) \ do { \ _c->mutex->thread_holding->schedule_in_local(_c, HRTIME_MSECONDS(cache_config_mutex_retry_delay)); \ From f488fe83b8b0109f41da5778628703b5d4b87924 Mon Sep 17 00:00:00 2001 From: Bryan Call Date: Thu, 29 Jan 2026 07:49:44 -0800 Subject: [PATCH 3/3] Add writer lock contention metric Add proxy.process.cache.writer.lock_contention to track contention on the writer VC mutex during read aggregation (separate from stripe mutex). --- src/iocore/cache/CacheProcessor.cc | 1 + src/iocore/cache/CacheRead.cc | 2 +- src/iocore/cache/P_CacheInternal.h | 5 +++-- src/iocore/cache/P_CacheStats.h | 1 + 4 files changed, 6 insertions(+), 3 deletions(-) diff --git a/src/iocore/cache/CacheProcessor.cc b/src/iocore/cache/CacheProcessor.cc index 2407934a699..8d1faf68716 100644 --- a/src/iocore/cache/CacheProcessor.cc +++ b/src/iocore/cache/CacheProcessor.cc @@ -1151,6 +1151,7 @@ register_cache_stats(CacheStatsBlock *rsb, const std::string &prefix) rsb->span_offline = ts::Metrics::Gauge::createPtr(prefix + ".span.offline"); rsb->span_online = ts::Metrics::Gauge::createPtr(prefix + ".span.online"); rsb->stripe_lock_contention = ts::Metrics::Counter::createPtr(prefix + ".stripe.lock_contention"); + rsb->writer_lock_contention = ts::Metrics::Counter::createPtr(prefix + ".writer.lock_contention"); } void diff --git a/src/iocore/cache/CacheRead.cc b/src/iocore/cache/CacheRead.cc index da26e3d71cc..0b5dcd6be17 100644 --- a/src/iocore/cache/CacheRead.cc +++ b/src/iocore/cache/CacheRead.cc @@ -275,7 +275,7 @@ CacheVC::openReadFromWriter(int event, Event *e) CACHE_TRY_LOCK(writer_lock, write_vc->mutex, mutex->thread_holding); if (!writer_lock.is_locked()) { DDbg(dbg_ctl_cache_read_agg, "%p: key: %X lock miss", this, first_key.slice32(1)); - VC_SCHED_LOCK_RETRY_NO_METRIC(); // Not stripe->mutex, don't count as stripe contention + VC_SCHED_WRITER_LOCK_RETRY(); } MUTEX_RELEASE(lock); diff --git a/src/iocore/cache/P_CacheInternal.h b/src/iocore/cache/P_CacheInternal.h index 53e88975d65..08560ba85ee 100644 --- a/src/iocore/cache/P_CacheInternal.h +++ b/src/iocore/cache/P_CacheInternal.h @@ -79,9 +79,10 @@ struct EvacuationBlock; return EVENT_CONT; \ } while (0) -// Variant without metric increment for non-stripe lock retries (e.g., write_vc->mutex) -#define VC_SCHED_LOCK_RETRY_NO_METRIC() \ +// Variant for writer lock contention (write_vc->mutex during read aggregation) +#define VC_SCHED_WRITER_LOCK_RETRY() \ do { \ + ts::Metrics::Counter::increment(cache_rsb.writer_lock_contention); \ trigger = mutex->thread_holding->schedule_in_local(this, HRTIME_MSECONDS(cache_config_mutex_retry_delay)); \ return EVENT_CONT; \ } while (0) diff --git a/src/iocore/cache/P_CacheStats.h b/src/iocore/cache/P_CacheStats.h index b53dd1560bd..7673cf56e0e 100644 --- a/src/iocore/cache/P_CacheStats.h +++ b/src/iocore/cache/P_CacheStats.h @@ -73,4 +73,5 @@ struct CacheStatsBlock { ts::Metrics::Gauge::AtomicType *span_online = nullptr; ts::Metrics::Gauge::AtomicType *span_failing = nullptr; ts::Metrics::Counter::AtomicType *stripe_lock_contention = nullptr; + ts::Metrics::Counter::AtomicType *writer_lock_contention = nullptr; };