[draft] Add cache hit stats to CCoinsViewCache

src/coins.cpp

@@ -14,6 +14,24 @@ TRACEPOINT_SEMAPHORE(utxocache, add);
 TRACEPOINT_SEMAPHORE(utxocache, spent);
 TRACEPOINT_SEMAPHORE(utxocache, uncache);
 
+
+void CoinsCacheStats::RecordMiss(bool nonexistent) noexcept {
+    ++m_total;
+    if (nonexistent) {
+        ++m_miss_nonexistent;
+    } else {
+        ++m_miss;
+    }
+}
+
+void CoinsCacheStats::Log(std::string_view reason) const
+{
+    const double miss_rate = m_total > 0 ? 100.0 * m_miss / m_total : 0.0;
+    const double miss_rate_nonxistent = m_total > 0 ? 100.0 * m_miss_nonexistent / m_total : 0.0;
+    LogDebug(BCLog::COINDB, "UTXO cache stats: gets=%d miss=%d (%.2f%%) missNE=%d (%.2f%%) logreason=%s\n",
+                m_total, m_miss, miss_rate, m_miss_nonexistent, miss_rate_nonxistent, reason);
+}
+
 CoinsViewEmpty& CoinsViewEmpty::Get()
 {
     static CoinsViewEmpty instance;
@@ -23,14 +41,18 @@ CoinsViewEmpty& CoinsViewEmpty::Get()
 std::optional<Coin> CCoinsViewCache::PeekCoin(const COutPoint& outpoint) const
 {
     if (auto it{cacheCoins.find(outpoint)}; it != cacheCoins.end()) {
+        if (m_log_stats) m_stats.RecordHit();
         return it->second.coin.IsSpent() ? std::nullopt : std::optional{it->second.coin};
     }
-    return base->PeekCoin(outpoint);
+    const auto ret{base->PeekCoin(outpoint)};
+    m_stats.RecordMiss(!ret);
+    return ret;
 }
 
-CCoinsViewCache::CCoinsViewCache(CCoinsView* in_base, bool deterministic) :
+CCoinsViewCache::CCoinsViewCache(CCoinsView* in_base, bool deterministic, bool log_stats) :
     CCoinsViewBacked(in_base), m_deterministic(deterministic),
-    cacheCoins(0, SaltedOutpointHasher(/*deterministic=*/deterministic), CCoinsMap::key_equal{}, &m_cache_coins_memory_resource)
+    cacheCoins(0, SaltedOutpointHasher(/*deterministic=*/deterministic), CCoinsMap::key_equal{}, &m_cache_coins_memory_resource),
+    m_log_stats(log_stats)
 {
     m_sentinel.second.SelfRef(m_sentinel);
 }
@@ -51,10 +73,14 @@ CCoinsMap::iterator CCoinsViewCache::FetchCoin(const COutPoint &outpoint) const
             ret->second.coin = std::move(*coin);
             cachedCoinsUsage += ret->second.coin.DynamicMemoryUsage();
             Assert(!ret->second.coin.IsSpent());
+            if (m_log_stats) m_stats.RecordMiss(false);
         } else {
             cacheCoins.erase(ret);
+            if (m_log_stats) m_stats.RecordMiss(true);
             return cacheCoins.end();
         }
+    } else {
+        if (m_log_stats) m_stats.RecordHit();
     }
     return ret;
 }
@@ -184,6 +210,7 @@ uint256 CCoinsViewCache::GetBestBlock() const {
 void CCoinsViewCache::SetBestBlock(const uint256& in_block_hash)
 {
     m_block_hash = in_block_hash;
+    if (m_log_stats && ++m_stats.m_block_count % 2016 == 0) m_stats.Log("block period");
 }
 
 void CCoinsViewCache::BatchWrite(CoinsViewCacheCursor& cursor, const uint256& in_block_hash)
@@ -259,6 +286,7 @@ void CCoinsViewCache::BatchWrite(CoinsViewCacheCursor& cursor, const uint256& in
 
 void CCoinsViewCache::Flush(bool reallocate_cache)
 {
+    if (m_log_stats) m_stats.Log("flush");
     auto cursor{CoinsViewCacheCursor(m_dirty_count, m_sentinel, cacheCoins, /*will_erase=*/true)};
     base->BatchWrite(cursor, m_block_hash);
     Assume(m_dirty_count == 0);
@@ -271,6 +299,7 @@ void CCoinsViewCache::Flush(bool reallocate_cache)
 
 void CCoinsViewCache::Sync()
 {
+    if (m_log_stats) m_stats.Log("sync");
     auto cursor{CoinsViewCacheCursor(m_dirty_count, m_sentinel, cacheCoins, /*will_erase=*/false)};
     base->BatchWrite(cursor, m_block_hash);
     Assume(m_dirty_count == 0);
@@ -282,6 +311,7 @@ void CCoinsViewCache::Sync()
 
 void CCoinsViewCache::Reset() noexcept
 {
+    if (m_log_stats) m_stats.Log("reset");
     cacheCoins.clear();
     cachedCoinsUsage = 0;
     m_dirty_count = 0;

src/coins.h

@@ -20,6 +20,7 @@
 
 #include <cassert>
 #include <cstdint>
+#include <string_view>
 
 #include <functional>
 #include <unordered_map>
@@ -389,6 +390,23 @@ class CCoinsViewBacked : public CCoinsView
 };
 
 
+/**
+ * Cache hit statistics for CCoinsViewCache.
+ * Record separately misses for:
+ * - accesses for existing items, where the item was not found in the cache, but it was found in the DB.
+ * - accesses for non-existing items, checks, where the item was not found in the cache, but neither in the DB.
+ * */
+struct CoinsCacheStats {
+    uint64_t m_total{0};            //!< total access calls
+    uint64_t m_miss{0};             //!< misses for existing items
+    uint64_t m_miss_nonexistent{0}; //!< missed for non-existing items
+    uint32_t m_block_count{0}; //!< number of SetBestBlock calls (approximates block height)
+
+    void RecordHit() noexcept { ++m_total; }
+    void RecordMiss(bool nonexistent) noexcept;
+    void Log(std::string_view reason) const;
+};
+
 /** CCoinsView that adds a memory cache for transactions to another CCoinsView */
 class CCoinsViewCache : public CCoinsViewBacked
 {
@@ -410,6 +428,8 @@ class CCoinsViewCache : public CCoinsViewBacked
     mutable size_t cachedCoinsUsage{0};
     /* Running count of dirty Coin cache entries. */
     mutable size_t m_dirty_count{0};
+    mutable CoinsCacheStats m_stats;
+    const bool m_log_stats;
 
     /**
      * Discard all modifications made to this cache without flushing to the base view.
@@ -421,7 +441,7 @@ class CCoinsViewCache : public CCoinsViewBacked
     virtual std::optional<Coin> FetchCoinFromBase(const COutPoint& outpoint) const;
 
 public:
-    CCoinsViewCache(CCoinsView* in_base, bool deterministic = false);
+    CCoinsViewCache(CCoinsView* in_base, bool deterministic = false, bool log_stats = false);
 
     /**
      * By deleting the copy constructor, we prevent accidentally using it when one intends to create a cache on top of a base cache.

src/validation.cpp

@@ -1853,7 +1853,7 @@ CoinsViews::CoinsViews(DBParams db_params, CoinsViewOptions options)
 void CoinsViews::InitCache()
 {
     AssertLockHeld(::cs_main);
-    m_cacheview = std::make_unique<CCoinsViewCache>(&m_catcherview);
+    m_cacheview = std::make_unique<CCoinsViewCache>(&m_catcherview, /*deterministic=*/false, /*log_stats=*/true);
     m_connect_block_view = std::make_unique<CoinsViewOverlay>(&*m_cacheview);
 }
 
@@ -2464,6 +2464,8 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
     if (fEnforceBIP30 || pindex->nHeight >= BIP34_IMPLIES_BIP30_LIMIT) {
         for (const auto& tx : block.vtx) {
             for (size_t o = 0; o < tx->vout.size(); o++) {
+                // Note: there the likely case is that the new TXO doesn't exist, so it will
+                // result in a cache miss (a miss for an non-existent item).
                 if (view.HaveCoin(COutPoint(tx->GetHash(), o))) {
                     state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-BIP30",
                                   "tried to overwrite transaction");