Track latency of per item eviction/promotion between memory tiers

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-inl.h

@@ -417,17 +417,16 @@ 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(); };
 
   // number of bytes required for this item
   const auto requiredSize = Item::getRequiredSize(key, size);
 
   // the allocation class in our memory allocator.
   const auto cid = allocator_[tid]->getAllocationClassId(pid, requiredSize);
-  util::RollingLatencyTracker rollTracker{
-      (*stats_.classAllocLatency)[tid][pid][cid]};
+
+  util::RollingLatencyTracker rollTracker{(*stats_.classAllocLatency)[tid][pid][cid]};
 
   (*stats_.allocAttempts)[tid][pid][cid].inc();
 

cachelib/allocator/CacheAllocator.h

@@ -2020,6 +2020,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;
@@ -2096,6 +2097,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;

cachelib/allocator/CacheStats.cpp

@@ -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

@@ -512,6 +512,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-inl.h

@@ -762,6 +762,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

@@ -91,6 +91,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};
@@ -282,6 +284,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);
       }
     }
 
@@ -528,6 +532,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