log fetch statistics after checkout

Summary: Log the number of object lookups and cache hit rates for a checkout operation.

Reviewed By: simpkins

Differential Revision: D19191201

fbshipit-source-id: 5e9ad501e704810f072dabcda3fce86d027c452e

eden/fs/inodes/EdenMount.cpp

@@ -878,7 +878,19 @@ folly::Future<CheckoutResult> EdenMount::checkout(
 
             return result;
           })
-      .thenTry([this, stopWatch](Try<CheckoutResult>&& result) {
+      .thenTry([this, ctx, stopWatch, oldParents, snapshotHash](
+                   Try<CheckoutResult>&& result) {
+        auto fetchStats = ctx->getFetchContext().computeStatistics();
+        XLOG(DBG1) << (result.hasValue() ? "" : "failed ") << "checkout for "
+                   << this->getPath() << " from " << oldParents << " to "
+                   << snapshotHash << " accessed "
+                   << fetchStats.tree.accessCount << " trees ("
+                   << fetchStats.tree.cacheHitRate << "% chr), "
+                   << fetchStats.blob.accessCount << " blobs ("
+                   << fetchStats.blob.cacheHitRate << "% chr), and "
+                   << fetchStats.metadata.accessCount << " metadata ("
+                   << fetchStats.metadata.cacheHitRate << "% chr).";
+
         auto checkoutTimeInSeconds =
             std::chrono::duration<double>{stopWatch.elapsed()};
         this->serverState_->getStructuredLogger()->logEvent(

eden/fs/store/StatsFetchContext.cpp

@@ -49,5 +49,41 @@ void StatsFetchContext::merge(const StatsFetchContext& other) {
   }
 }
 
+uint64_t StatsFetchContext::countFetchesOfTypeAndOrigin(
+    ObjectType type,
+    Origin origin) const {
+  XCHECK(type < ObjectFetchContext::kObjectTypeEnumMax)
+      << "type is out of range: " << type;
+  XCHECK(origin < ObjectFetchContext::kOriginEnumMax)
+      << "origin is out of range: " << type;
+  return counts_[type][origin].load(std::memory_order_acquire);
+}
+
+FetchStatistics StatsFetchContext::computeStatistics() const {
+  auto computePercent = [&](uint64_t n, uint64_t d) -> unsigned short {
+    DCHECK_LE(n, d) << n << " > " << d;
+    if (d == 0) {
+      return 0;
+    }
+    return (1000 * n / d + 5) / 10;
+  };
+
+  auto computeAccessStats = [&](ObjectFetchContext::ObjectType type) {
+    uint64_t fromMemory = counts_[type][ObjectFetchContext::FromMemoryCache];
+    uint64_t fromDisk = counts_[type][ObjectFetchContext::FromDiskCache];
+    uint64_t fromBackingStore =
+        counts_[type][ObjectFetchContext::FromBackingStore];
+    uint64_t total = fromMemory + fromDisk + fromBackingStore;
+    return FetchStatistics::Access{
+        total, computePercent(fromMemory + fromDisk, total)};
+  };
+
+  auto result = FetchStatistics{};
+  result.tree = computeAccessStats(ObjectFetchContext::Tree);
+  result.blob = computeAccessStats(ObjectFetchContext::Blob);
+  result.metadata = computeAccessStats(ObjectFetchContext::BlobMetadata);
+  return result;
+}
+
 } // namespace eden
 } // namespace facebook

eden/fs/store/StatsFetchContext.h

@@ -13,6 +13,21 @@
 namespace facebook {
 namespace eden {
 
+struct FetchStatistics {
+  struct Access {
+    uint64_t accessCount = 0;
+    /**
+     * In range [0, 100]. unsigned char is big enough, but prints as a
+     * character.
+     */
+    unsigned short cacheHitRate = 0;
+  };
+
+  Access tree;
+  Access blob;
+  Access metadata;
+};
+
 class StatsFetchContext : public ObjectFetchContext {
  public:
   StatsFetchContext() = default;
@@ -21,6 +36,9 @@ class StatsFetchContext : public ObjectFetchContext {
   void didFetch(ObjectType type, const Hash& id, Origin origin) override;
 
   uint64_t countFetchesOfType(ObjectType type) const;
+  uint64_t countFetchesOfTypeAndOrigin(ObjectType type, Origin origin) const;
+
+  FetchStatistics computeStatistics() const;
 
   /**
    * Sums the counts from another fetch context into this one.