Track latency of per item eviction/promotion between memory tiers

----------------------------------------------------------------
this can go with background evictors multi-tier part 1

Author: guptask

cachelib/allocator/Cache.cpp

@@ -477,6 +477,10 @@ void CacheBase::updateGlobalCacheStats(const std::string& statPrefix) const {
 
   visitEstimates(uploadStatsNanoToMicro, stats.allocateLatencyNs,
                  statPrefix + "allocate.latency_us");
+  visitEstimates(uploadStatsNanoToMicro, stats.bgEvictLatencyNs,
+                 statPrefix + "background.eviction.latency_us");
+  visitEstimates(uploadStatsNanoToMicro, stats.bgPromoteLatencyNs,
+                 statPrefix + "background.promotion.latency_us");
   visitEstimates(uploadStatsNanoToMicro, stats.moveChainedLatencyNs,
                  statPrefix + "move.chained.latency_us");
   visitEstimates(uploadStatsNanoToMicro, stats.moveRegularLatencyNs,

cachelib/allocator/CacheAllocator.h

@@ -2013,6 +2013,7 @@ class CacheAllocator : public CacheBase {
                                unsigned int pid,
                                unsigned int cid,
                                size_t batch) {
+    util::LatencyTracker tracker{stats().bgEvictLatency_, batch};
     auto& mmContainer = getMMContainer(tid, pid, cid);
     size_t evictions = 0;
     size_t evictionCandidates = 0;
@@ -2089,6 +2090,7 @@ class CacheAllocator : public CacheBase {
                                  unsigned int pid,
                                  unsigned int cid,
                                  size_t batch) {
+    util::LatencyTracker tracker{stats().bgPromoteLatency_, batch};
     auto& mmContainer = getMMContainer(tid, pid, cid);
     size_t promotions = 0;
     std::vector<Item*> candidates;
@@ -3004,7 +3006,7 @@ CacheAllocator<CacheTrait>::allocateInternalTier(TierId tid,
                                                  uint32_t expiryTime,
                                                  bool fromBgThread,
                                                  bool evict) {
-  util::LatencyTracker tracker{stats().allocateLatency_};
+  util::LatencyTracker tracker{stats().allocateLatency_, static_cast<size_t>(!fromBgThread)};
 
   SCOPE_FAIL { stats_.invalidAllocs.inc(); };
 

cachelib/allocator/CacheStats.cpp

@@ -56,7 +56,7 @@ struct SizeVerify {};
 
 void Stats::populateGlobalCacheStats(GlobalCacheStats& ret) const {
 #ifndef SKIP_SIZE_VERIFY
-  SizeVerify<sizeof(Stats)> a = SizeVerify<16368>{};
+  SizeVerify<sizeof(Stats)> a = SizeVerify<16720>{};
   std::ignore = a;
 #endif
   ret.numCacheGets = numCacheGets.get();
@@ -105,6 +105,8 @@ void Stats::populateGlobalCacheStats(GlobalCacheStats& ret) const {
   ret.numNvmItemDestructorAllocErrors = numNvmItemDestructorAllocErrors.get();
 
   ret.allocateLatencyNs = this->allocateLatency_.estimate();
+  ret.bgEvictLatencyNs = this->bgEvictLatency_.estimate();
+  ret.bgPromoteLatencyNs = this->bgPromoteLatency_.estimate();
   ret.moveChainedLatencyNs = this->moveChainedLatency_.estimate();
   ret.moveRegularLatencyNs = this->moveRegularLatency_.estimate();
   ret.nvmLookupLatencyNs = this->nvmLookupLatency_.estimate();

cachelib/allocator/CacheStats.h

@@ -529,6 +529,8 @@ struct GlobalCacheStats {
 
   // latency and percentile stats of various cachelib operations
   util::PercentileStats::Estimates allocateLatencyNs{};
+  util::PercentileStats::Estimates bgEvictLatencyNs{};
+  util::PercentileStats::Estimates bgPromoteLatencyNs{};
   util::PercentileStats::Estimates moveChainedLatencyNs{};
   util::PercentileStats::Estimates moveRegularLatencyNs{};
   util::PercentileStats::Estimates nvmLookupLatencyNs{};

cachelib/allocator/CacheStatsInternal.h

@@ -189,6 +189,8 @@ struct Stats {
 
   // latency stats of various cachelib operations
   mutable util::PercentileStats allocateLatency_;
+  mutable util::PercentileStats bgEvictLatency_;
+  mutable util::PercentileStats bgPromoteLatency_;
   mutable util::PercentileStats moveChainedLatency_;
   mutable util::PercentileStats moveRegularLatency_;
   mutable util::PercentileStats nvmLookupLatency_;

cachelib/cachebench/cache/Cache.h

@@ -1217,6 +1217,8 @@ Stats Cache<Allocator>::getStats() const {
       static_cast<int64_t>(itemRecords_.count()) - totalDestructor_;
 
   ret.cacheAllocateLatencyNs = cacheStats.allocateLatencyNs;
+  ret.cacheBgEvictLatencyNs = cacheStats.bgEvictLatencyNs;
+  ret.cacheBgPromoteLatencyNs = cacheStats.bgPromoteLatencyNs;
   ret.cacheFindLatencyNs = cacheFindLatency_.estimate();
 
   // Populate counters.

cachelib/cachebench/cache/CacheStats.h

@@ -70,6 +70,8 @@ struct Stats {
   uint64_t numNvmItemRemovedSetSize{0};
 
   util::PercentileStats::Estimates cacheAllocateLatencyNs;
+  util::PercentileStats::Estimates cacheBgEvictLatencyNs;
+  util::PercentileStats::Estimates cacheBgPromoteLatencyNs;
   util::PercentileStats::Estimates cacheFindLatencyNs;
 
   double nvmReadLatencyMicrosP50{0};
@@ -295,6 +297,8 @@ struct Stats {
 
         printLatencies("Cache Find API latency", cacheFindLatencyNs);
         printLatencies("Cache Allocate API latency", cacheAllocateLatencyNs);
+        printLatencies("Cache Background Eviction API latency", cacheBgEvictLatencyNs);
+        printLatencies("Cache Background Promotion API latency", cacheBgPromoteLatencyNs);
       }
     }
 
@@ -535,6 +539,8 @@ struct Stats {
 
     counters["find_latency_p99"] = cacheFindLatencyNs.p99;
     counters["alloc_latency_p99"] = cacheAllocateLatencyNs.p99;
+    counters["bg_evict_latency_p99"] = cacheBgEvictLatencyNs.p99;
+    counters["bg_promote_latency_p99"] = cacheBgPromoteLatencyNs.p99;
 
     counters["ram_hit_rate"] = calcInvertPctFn(numCacheGetMiss, numCacheGets);
     counters["nvm_hit_rate"] = calcInvertPctFn(numCacheGetMiss, numCacheGets);

cachelib/common/PercentileStats.h

@@ -107,24 +107,24 @@ class PercentileStats {
 
 class LatencyTracker {
  public:
-  explicit LatencyTracker(PercentileStats& stats)
-      : stats_(&stats), begin_(std::chrono::steady_clock::now()) {}
+  explicit LatencyTracker(PercentileStats& stats, size_t nSamples = 1)
+      : stats_(&stats), nSamples_(nSamples), begin_(std::chrono::steady_clock::now()) {}
   LatencyTracker() {}
   ~LatencyTracker() {
-    if (stats_) {
+    if (nSamples_ > 0 && stats_) {
       auto tp = std::chrono::steady_clock::now();
       auto diffNanos =
           std::chrono::duration_cast<std::chrono::nanoseconds>(tp - begin_)
               .count();
-      stats_->trackValue(static_cast<double>(diffNanos), tp);
+      stats_->trackValue(static_cast<double>(diffNanos/nSamples_), tp);
     }
   }
 
   LatencyTracker(const LatencyTracker&) = delete;
   LatencyTracker& operator=(const LatencyTracker&) = delete;
 
   LatencyTracker(LatencyTracker&& rhs) noexcept
-      : stats_(rhs.stats_), begin_(rhs.begin_) {
+      : stats_(rhs.stats_), nSamples_(rhs.nSamples_), begin_(rhs.begin_) {
     rhs.stats_ = nullptr;
   }
 
@@ -138,6 +138,7 @@ class LatencyTracker {
 
  private:
   PercentileStats* stats_{nullptr};
+  size_t nSamples_{1};
   std::chrono::time_point<std::chrono::steady_clock> begin_;
 };
 } // namespace util