[llvm][cas] Introduce On-disk CAS Log (#10252)

Adds a CAS logging interface to track mutations of the CAS and action
cache database files. This is designed to aid in the debugging of
data corruption and other issues with the low-level on-disk
representation.

To enable logging, set the environment variable LLVM_CAS_LOG to 1 or 2.
Level 2 includes logging of all allocations inside the index, action
cache, and datapool, which increases the overhead. The log file is
placed inside the top-level directory of the unified cache. For now it
is a human-readable textual format with one line per entry.

rdar://145675013
(cherry picked from commit a35c7dc)

rdar://145675090

Author: benlangmuir

llvm/include/llvm/CAS/MappedFileRegionBumpPtr.h

@@ -16,6 +16,10 @@
 
 namespace llvm::cas {
 
+namespace ondisk {
+class OnDiskCASLogger;
+}
+
 /// Allocator for an owned mapped file region that supports thread-safe and
 /// process-safe bump pointer allocation.
 ///
@@ -48,6 +52,7 @@ class MappedFileRegionBumpPtr {
   /// access to the file. Must call \c initializeBumpPtr.
   static Expected<MappedFileRegionBumpPtr>
   create(const Twine &Path, uint64_t Capacity, int64_t BumpPtrOffset,
+         std::shared_ptr<ondisk::OnDiskCASLogger> Logger,
          function_ref<Error(MappedFileRegionBumpPtr &)> NewFileConstructor);
 
   /// Finish initializing the bump pointer. Must be called by
@@ -99,6 +104,7 @@ class MappedFileRegionBumpPtr {
     std::swap(Path, RHS.Path);
     std::swap(FD, RHS.FD);
     std::swap(SharedLockFD, RHS.SharedLockFD);
+    std::swap(Logger, RHS.Logger);
   }
 
 private:
@@ -107,6 +113,7 @@ class MappedFileRegionBumpPtr {
   std::string Path;
   std::optional<int> FD;
   std::optional<int> SharedLockFD;
+  std::shared_ptr<ondisk::OnDiskCASLogger> Logger = nullptr;
 };
 
 } // namespace llvm::cas

llvm/include/llvm/CAS/OnDiskCASLogger.h

@@ -0,0 +1,78 @@
+//===- OnDiskCASLogger.h ----------------------------------------*- C++ -*-===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+
+#ifndef LLVM_CAS_ONDISKLOGGER_H
+#define LLVM_CAS_ONDISKLOGGER_H
+
+#include "llvm/Support/Error.h"
+#include <memory>
+
+namespace llvm {
+class raw_fd_ostream;
+class Twine;
+} // namespace llvm
+
+namespace llvm::cas::ondisk {
+
+/// Interface for logging low-level on-disk cas operations.
+///
+/// This log is intended to mirror the low-level details of the CAS in order to
+/// aid with debugging corruption or other issues with the on-disk format.
+class OnDiskCASLogger {
+public:
+  /// Create or append to a log file inside the given CAS directory \p Path.
+  ///
+  /// \param Path The parent directory of the log file.
+  /// \param LogAllocations Whether to log all low-level allocations. This is
+  ///                       on the order of twice as expensive to log.
+  static Expected<std::unique_ptr<OnDiskCASLogger>> open(const Twine &Path,
+                                                         bool LogAllocations);
+
+  /// Create or append to a log file inside the given CAS directory \p Path if
+  /// logging is enabled by the environment variable \c LLVM_CAS_LOG. If
+  /// LLVM_CAS_LOG is set >= 2 then also log allocations.
+  static Expected<std::unique_ptr<OnDiskCASLogger>>
+  openIfEnabled(const Twine &Path);
+
+  ~OnDiskCASLogger();
+
+  /// An offset into an \c OnDiskHashMappedTrie.
+  using TrieOffset = int64_t;
+
+  void log_compare_exchange_strong(void *Region, TrieOffset Trie, size_t SlotI,
+                                   TrieOffset Expected, TrieOffset New,
+                                   TrieOffset Previous);
+  void log_SubtrieHandle_create(void *Region, TrieOffset Trie,
+                                uint32_t StartBit, uint32_t NumBits);
+  void log_HashMappedTrieHandle_createRecord(void *Region,
+                                             TrieOffset TrieOffset,
+                                             ArrayRef<uint8_t> Hash);
+  void log_MappedFileRegionBumpPtr_resizeFile(StringRef Path, size_t Before,
+                                              size_t After);
+  void log_MappedFileRegionBumpPtr_create(StringRef Path, int FD, void *Region,
+                                          size_t Capacity, size_t Size);
+  void log_MappedFileRegionBumpPtr_oom(StringRef Path, size_t Capacity,
+                                       size_t Size, size_t AllocSize);
+  void log_MappedFileRegionBumpPtr_close(StringRef Path);
+  void log_MappedFileRegionBumpPtr_allocate(void *Region, TrieOffset Off,
+                                            size_t Size);
+  void log_UnifiedOnDiskCache_collectGarbage(StringRef Path);
+  void log_TempFile_create(StringRef Name);
+  void log_TempFile_keep(StringRef TmpName, StringRef Name, std::error_code EC);
+  void log_TempFile_remove(StringRef TmpName, std::error_code EC);
+
+private:
+  OnDiskCASLogger(raw_fd_ostream &OS, bool LogAllocations);
+
+  raw_fd_ostream &OS;
+  bool LogAllocations;
+};
+
+} // namespace llvm::cas::ondisk
+
+#endif // LLVM_CAS_ONDISKLOGGER_H

llvm/include/llvm/CAS/OnDiskGraphDB.h

@@ -338,6 +338,7 @@ class OnDiskGraphDB {
   static Expected<std::unique_ptr<OnDiskGraphDB>>
   open(StringRef Path, StringRef HashName, unsigned HashByteSize,
        std::unique_ptr<OnDiskGraphDB> UpstreamDB = nullptr,
+       std::shared_ptr<OnDiskCASLogger> Logger = nullptr,
        FaultInPolicy Policy = FaultInPolicy::FullTree);
 
   ~OnDiskGraphDB();
@@ -411,8 +412,8 @@ class OnDiskGraphDB {
 
   OnDiskGraphDB(StringRef RootPath, OnDiskHashMappedTrie Index,
                 OnDiskDataAllocator DataPool,
-                std::unique_ptr<OnDiskGraphDB> UpstreamDB,
-                FaultInPolicy Policy);
+                std::unique_ptr<OnDiskGraphDB> UpstreamDB, FaultInPolicy Policy,
+                std::shared_ptr<OnDiskCASLogger> Logger);
 
   /// Mapping from hash to object reference.
   ///
@@ -431,6 +432,8 @@ class OnDiskGraphDB {
   /// Optional on-disk store to be used for faulting-in nodes.
   std::unique_ptr<OnDiskGraphDB> UpstreamDB;
   FaultInPolicy FIPolicy;
+
+  std::shared_ptr<OnDiskCASLogger> Logger;
 };
 
 } // namespace llvm::cas::ondisk

llvm/include/llvm/CAS/OnDiskHashMappedTrie.h

@@ -28,6 +28,10 @@ class raw_ostream;
 
 namespace cas {
 
+namespace ondisk {
+class OnDiskCASLogger;
+}
+
 class FileOffset {
 public:
   int64_t get() const { return Offset; }
@@ -253,6 +257,7 @@ class OnDiskHashMappedTrie {
   create(const Twine &Path, const Twine &TrieName, size_t NumHashBits,
          uint64_t DataSize, uint64_t MaxFileSize,
          std::optional<uint64_t> NewFileInitialSize,
+         std::shared_ptr<ondisk::OnDiskCASLogger> Logger = nullptr,
          std::optional<size_t> NewTableNumRootBits = std::nullopt,
          std::optional<size_t> NewTableNumSubtrieBits = std::nullopt);
 
@@ -328,6 +333,7 @@ class OnDiskDataAllocator {
   create(const Twine &Path, const Twine &TableName, uint64_t MaxFileSize,
          std::optional<uint64_t> NewFileInitialSize,
          uint32_t UserHeaderSize = 0,
+         std::shared_ptr<ondisk::OnDiskCASLogger> Logger = nullptr,
          function_ref<void(void *)> UserHeaderInit = nullptr);
 
   OnDiskDataAllocator(OnDiskDataAllocator &&RHS);

llvm/include/llvm/CAS/OnDiskKeyValueDB.h

@@ -57,7 +57,8 @@ class OnDiskKeyValueDB {
   /// \param ValueSize Size for the value bytes.
   static Expected<std::unique_ptr<OnDiskKeyValueDB>>
   open(StringRef Path, StringRef HashName, unsigned KeySize,
-       StringRef ValueName, size_t ValueSize);
+       StringRef ValueName, size_t ValueSize,
+       std::shared_ptr<OnDiskCASLogger> Logger = nullptr);
 
 private:
   OnDiskKeyValueDB(size_t ValueSize, OnDiskHashMappedTrie Cache)

llvm/include/llvm/CAS/UnifiedOnDiskCache.h

@@ -117,7 +117,8 @@ class UnifiedOnDiskCache {
   ///
   /// It is recommended that garbage-collection is triggered concurrently in the
   /// background, so that it has minimal effect on the workload of the process.
-  static Error collectGarbage(StringRef Path);
+  static Error collectGarbage(StringRef Path,
+                              ondisk::OnDiskCASLogger *Logger = nullptr);
 
   Error collectGarbage();
 
@@ -145,6 +146,8 @@ class UnifiedOnDiskCache {
 
   std::unique_ptr<OnDiskKeyValueDB> UpstreamKVDB;
   std::unique_ptr<OnDiskKeyValueDB> PrimaryKVDB;
+
+  std::shared_ptr<ondisk::OnDiskCASLogger> Logger = nullptr;
 };
 
 } // namespace llvm::cas::ondisk

llvm/lib/CAS/ActionCaches.cpp

@@ -10,6 +10,7 @@
 #include "llvm/CAS/ActionCache.h"
 #include "llvm/CAS/HashMappedTrie.h"
 #include "llvm/CAS/ObjectStore.h"
+#include "llvm/CAS/OnDiskCASLogger.h"
 #include "llvm/CAS/OnDiskGraphDB.h"
 #include "llvm/CAS/OnDiskHashMappedTrie.h"
 #include "llvm/CAS/OnDiskKeyValueDB.h"
@@ -157,10 +158,14 @@ OnDiskActionCache::OnDiskActionCache(
 
 Expected<std::unique_ptr<OnDiskActionCache>>
 OnDiskActionCache::create(StringRef AbsPath) {
+  std::shared_ptr<ondisk::OnDiskCASLogger> Logger;
+  if (Error E =
+          ondisk::OnDiskCASLogger::openIfEnabled(AbsPath).moveInto(Logger))
+    return std::move(E);
   std::unique_ptr<ondisk::OnDiskKeyValueDB> DB;
   if (Error E = ondisk::OnDiskKeyValueDB::open(AbsPath, getHashName(),
                                                sizeof(HashType), getHashName(),
-                                               sizeof(DataT))
+                                               sizeof(DataT), std::move(Logger))
                     .moveInto(DB))
     return std::move(E);
   return std::unique_ptr<OnDiskActionCache>(

llvm/lib/CAS/CMakeLists.txt

@@ -19,6 +19,7 @@ add_llvm_component_library(LLVMCAS
   MappedFileRegionBumpPtr.cpp
   ObjectStore.cpp
   OnDiskCAS.cpp
+  OnDiskCASLogger.cpp
   OnDiskCommon.cpp
   OnDiskGraphDB.cpp
   OnDiskHashMappedTrie.cpp

llvm/lib/CAS/MappedFileRegionBumpPtr.cpp

@@ -54,6 +54,7 @@
 #include "llvm/CAS/MappedFileRegionBumpPtr.h"
 #include "OnDiskCommon.h"
 #include "llvm/ADT/StringMap.h"
+#include "llvm/CAS/OnDiskCASLogger.h"
 
 using namespace llvm;
 using namespace llvm::cas;
@@ -89,9 +90,11 @@ struct FileLockRAII {
 
 Expected<MappedFileRegionBumpPtr> MappedFileRegionBumpPtr::create(
     const Twine &Path, uint64_t Capacity, int64_t BumpPtrOffset,
+    std::shared_ptr<ondisk::OnDiskCASLogger> Logger,
     function_ref<Error(MappedFileRegionBumpPtr &)> NewFileConstructor) {
   MappedFileRegionBumpPtr Result;
   Result.Path = Path.str();
+  Result.Logger = std::move(Logger);
   // Open the main file.
   int FD;
   if (std::error_code EC = sys::fs::openFileForReadWrite(
@@ -147,6 +150,10 @@ Expected<MappedFileRegionBumpPtr> MappedFileRegionBumpPtr::create(
     // to make this a sparse region, if supported.
     if (std::error_code EC = sys::fs::resize_file(FD, Capacity))
       return createFileError(Result.Path, EC);
+
+    if (Result.Logger)
+      Result.Logger->log_MappedFileRegionBumpPtr_resizeFile(
+          Result.Path, Status.getSize(), Capacity);
   } else {
     // Someone else initialized it.
     Capacity = Status.getSize();
@@ -186,9 +193,14 @@ void MappedFileRegionBumpPtr::destroyImpl() {
   if (BumpPtr) {
     assert(SharedLockFD && "Must have shared lock file open");
     if (tryLockFileThreadSafe(*SharedLockFD) == std::error_code()) {
-      assert(size() <= capacity());
+      size_t Size = size();
+      size_t Capacity = capacity();
+      assert(Size < Capacity);
       (void)sys::fs::resize_file(*FD, size());
       (void)unlockFileThreadSafe(*SharedLockFD);
+
+      if (Logger)
+        Logger->log_MappedFileRegionBumpPtr_resizeFile(Path, Capacity, Size);
     }
   }
 
@@ -203,6 +215,9 @@ void MappedFileRegionBumpPtr::destroyImpl() {
   // Close the file and shared lock.
   Close(FD);
   Close(SharedLockFD);
+
+  if (Logger)
+    Logger->log_MappedFileRegionBumpPtr_close(Path);
 }
 
 void MappedFileRegionBumpPtr::initializeBumpPtr(int64_t BumpPtrOffset) {
@@ -218,6 +233,10 @@ void MappedFileRegionBumpPtr::initializeBumpPtr(int64_t BumpPtrOffset) {
   if (!BumpPtr->compare_exchange_strong(ExistingValue, BumpPtrEndOffset))
     assert(ExistingValue >= BumpPtrEndOffset &&
            "Expected 0, or past the end of the BumpPtr itself");
+
+  if (Logger)
+    Logger->log_MappedFileRegionBumpPtr_create(Path, *FD, data(), capacity(),
+                                               size());
 }
 
 static Error createAllocatorOutOfSpaceError() {
@@ -239,7 +258,15 @@ Expected<int64_t> MappedFileRegionBumpPtr::allocateOffset(uint64_t AllocSize) {
     if (OldEnd <= (int64_t)capacity())
       (void)BumpPtr->exchange(OldEnd);
 
+    if (Logger)
+      Logger->log_MappedFileRegionBumpPtr_oom(Path, capacity(), OldEnd,
+                                              AllocSize);
+
     return createAllocatorOutOfSpaceError();
   }
+
+  if (Logger)
+    Logger->log_MappedFileRegionBumpPtr_allocate(data(), OldEnd, AllocSize);
+
   return OldEnd;
 }

llvm/lib/CAS/OnDiskCAS.cpp

@@ -9,9 +9,11 @@
 #include "BuiltinCAS.h"
 #include "llvm/CAS/BuiltinCASContext.h"
 #include "llvm/CAS/BuiltinObjectHasher.h"
+#include "llvm/CAS/OnDiskCASLogger.h"
 #include "llvm/CAS/OnDiskGraphDB.h"
 #include "llvm/CAS/UnifiedOnDiskCache.h"
 #include "llvm/Support/Compiler.h"
+#include "llvm/Support/Error.h"
 #include "llvm/Support/Path.h"
 
 using namespace llvm;
@@ -168,9 +170,15 @@ Expected<std::optional<uint64_t>> OnDiskCAS::getStorageSize() const {
 Error OnDiskCAS::pruneStorageData() { return UniDB->collectGarbage(); }
 
 Expected<std::unique_ptr<OnDiskCAS>> OnDiskCAS::open(StringRef AbsPath) {
+  std::shared_ptr<ondisk::OnDiskCASLogger> Logger;
+  if (Error E =
+          ondisk::OnDiskCASLogger::openIfEnabled(AbsPath).moveInto(Logger))
+    return std::move(E);
+
   Expected<std::unique_ptr<ondisk::OnDiskGraphDB>> DB =
       ondisk::OnDiskGraphDB::open(AbsPath, BuiltinCASContext::getHashName(),
-                                  sizeof(HashType));
+                                  sizeof(HashType), /*UpstreamDB=*/nullptr,
+                                  std::move(Logger));
   if (!DB)
     return DB.takeError();
   return std::unique_ptr<OnDiskCAS>(new OnDiskCAS(std::move(*DB)));