llvm/lib/CAS/OnDiskCASLogger.cpp

//===----------------------------------------------------------------------===//
//
// 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
//
//===----------------------------------------------------------------------===//
//
/// \file
/// This file implements OnDiskCASLogger. The logger will write the timestamp
/// and events to a log file using filestream. The logger should be thread-safe
/// and process-safe because each write is small enough to atomically update the
/// file.
///
/// The logger can be enabled via `LLVM_CAS_LOG` environmental variable.
//
//===----------------------------------------------------------------------===//

#include "llvm/CAS/OnDiskCASLogger.h"

#include "llvm/ADT/StringSwitch.h"
#include "llvm/ADT/Twine.h"
#include "llvm/Support/Error.h"
#include "llvm/Support/FileSystem.h"
#include "llvm/Support/Path.h"
#include "llvm/Support/Process.h"
#include "llvm/Support/Threading.h"
#include "llvm/Support/raw_ostream.h"
#ifdef __APPLE__
#include <sys/time.h>
#endif

using namespace llvm;
using namespace llvm::cas;
using namespace llvm::cas::ondisk;

// The version number in this log should be bumped if the log format is changed
// in an incompatible way. It is currently a human-readable text file, so in
// practice this would be if the log changed to binary or other machine-
// readable format.
static constexpr StringLiteral Filename = "v1.log";

OnDiskCASLogger::OnDiskCASLogger(raw_fd_ostream &OS, bool LogAllocations)
    : OS(OS), LogAllocations(LogAllocations) {}

OnDiskCASLogger::~OnDiskCASLogger() {
  OS.flush();
  delete &OS;
}

static bool isDisabledEnv(StringRef V) {
  return StringSwitch<bool>(V)
      .Case("0", true)
      .CaseLower("no", true)
      .CaseLower("false", true)
      .Default(false);
}

Expected<std::unique_ptr<OnDiskCASLogger>>
OnDiskCASLogger::openIfEnabled(const Twine &Path) {
  const char *V = getenv("LLVM_CAS_LOG");
  if (V && !isDisabledEnv(V)) {
    int LogLevel = -1;
    StringRef(V).getAsInteger(10, LogLevel);
    return OnDiskCASLogger::open(Path, /*LogAllocations=*/LogLevel > 1 ? true
                                                                       : false);
  }
  return nullptr;
}
Expected<std::unique_ptr<OnDiskCASLogger>>
OnDiskCASLogger::open(const Twine &Path, bool LogAllocations) {
  std::error_code EC;
  SmallString<128> FullPath;
  Path.toVector(FullPath);
  sys::path::append(FullPath, Filename);

  auto OS =
      std::make_unique<raw_fd_ostream>(FullPath, EC, sys::fs::CD_OpenAlways,
                                       sys::fs::FA_Write, sys::fs::OF_Append);
  if (EC)
    return createFileError(FullPath, EC);

  // Buffer is not thread-safe.
  OS->SetUnbuffered();

  return std::unique_ptr<OnDiskCASLogger>(
      new OnDiskCASLogger{*OS.release(), LogAllocations});
}

static uint64_t getTimestampMillis() {
#ifdef __APPLE__
  // Using chrono is roughly 50% slower.
  struct timeval T;
  gettimeofday(&T, 0);
  return T.tv_sec * 1000 + T.tv_usec / 1000;
#else
  auto Time = std::chrono::system_clock::now();
  auto Millis = std::chrono::duration_cast<std::chrono::milliseconds>(
      Time.time_since_epoch());
  return Millis.count();
#endif
}

namespace {
/// Helper to log a single line that adds the timestamp, pid, and tid. The line
/// is buffered and written in a single call to write() so that if the
/// underlying OS syscall is handled atomically so is this log message.
class TextLogLine : public raw_svector_ostream {
public:
  TextLogLine(raw_ostream &LogOS) : raw_svector_ostream(Buffer), LogOS(LogOS) {
    startLogMsg(*this);
  }

  ~TextLogLine() {
    finishLogMsg(*this);
    LogOS.write(Buffer.data(), Buffer.size());
  }

  static void startLogMsg(raw_ostream &OS) {
    auto Millis = getTimestampMillis();
    OS << format("%lld.%0.3lld", Millis / 1000, Millis % 1000);
    OS << ' ' << sys::Process::getProcessId() << ' ' << get_threadid() << ": ";
  }

  static void finishLogMsg(raw_ostream &OS) { OS << '\n'; }

private:
  raw_ostream &LogOS;
  SmallString<128> Buffer;
};
} // anonymous namespace

static void formatTrieOffset(raw_ostream &OS, int64_t Off) {
  if (Off < 0) {
    OS << '-';
    Off = -Off;
  }
  OS << format_hex(Off, 0);
}

void OnDiskCASLogger::logSubtrieHandleCmpXchg(void *Region, TrieOffset Trie,
                                              size_t SlotI, TrieOffset Expected,
                                              TrieOffset New,
                                              TrieOffset Previous) {
  TextLogLine Log(OS);
  Log << "cmpxcgh subtrie region=" << Region << " offset=";
  formatTrieOffset(Log, Trie);
  Log << " slot=" << SlotI << " expected=";
  formatTrieOffset(Log, Expected);
  Log << " new=";
  formatTrieOffset(Log, New);
  Log << " prev=";
  formatTrieOffset(Log, Previous);
}

void OnDiskCASLogger::logSubtrieHandleCreate(void *Region, TrieOffset Trie,
                                             uint32_t StartBit,
                                             uint32_t NumBits) {
  TextLogLine Log(OS);
  Log << "create subtrie region=" << Region << " offset=";
  formatTrieOffset(Log, Trie);
  Log << " start-bit=" << StartBit << " num-bits=" << NumBits;
}

void OnDiskCASLogger::logHashMappedTrieHandleCreateRecord(
    void *Region, TrieOffset Off, ArrayRef<uint8_t> Hash) {
  TextLogLine Log(OS);
  Log << "create record region=" << Region << " offset=";
  formatTrieOffset(Log, Off);
  Log << " hash=" << format_bytes(Hash, std::nullopt, 32, 32);
}

void OnDiskCASLogger::logMappedFileRegionArenaResizeFile(StringRef Path,
                                                         size_t Before,
                                                         size_t After) {
  TextLogLine Log(OS);
  Log << "resize mapped file '" << Path << "' from=" << Before
      << " to=" << After;
}

void OnDiskCASLogger::logMappedFileRegionArenaCreate(StringRef Path, int FD,
                                                     void *Region,
                                                     size_t Capacity,
                                                     size_t Size) {
  sys::fs::file_status Stat;
  std::error_code EC = status(FD, Stat);

  TextLogLine Log(OS);
  Log << "mmap '" << Path << "' " << Region;
  Log << " size=" << Size << " capacity=" << Capacity;
  if (EC) {
    Log << " failed status with error: " << EC.message();
    return;
  }
  Log << " dev=" << format_hex(Stat.getUniqueID().getDevice(), 4);
  Log << " inode=" << format_hex(Stat.getUniqueID().getFile(), 4);
}

void OnDiskCASLogger::logMappedFileRegionArenaOom(StringRef Path,
                                                  size_t Capacity, size_t Size,
                                                  size_t AllocSize) {
  TextLogLine Log(OS);
  Log << "oom '" << Path << "' old-size=" << Size << " capacity=" << Capacity
      << "alloc-size=" << AllocSize;
}
void OnDiskCASLogger::logMappedFileRegionArenaClose(StringRef Path) {
  TextLogLine Log(OS);
  Log << "close mmap '" << Path << "'";
}
void OnDiskCASLogger::logMappedFileRegionArenaAllocate(void *Region,
                                                       TrieOffset Off,
                                                       size_t Size) {
  if (!LogAllocations)
    return;
  TextLogLine Log(OS);
  Log << "alloc " << Region << " offset=";
  formatTrieOffset(Log, Off);
  Log << " size=" << Size;
}

void OnDiskCASLogger::logUnifiedOnDiskCacheCollectGarbage(StringRef Path) {
  TextLogLine Log(OS);
  Log << "collect garbage '" << Path << "'";
}

void OnDiskCASLogger::logUnifiedOnDiskCacheValidateIfNeeded(
    StringRef Path, uint64_t BootTime, uint64_t ValidationTime, bool CheckHash,
    bool Force, StringRef ValidationError, bool Skipped) {
  TextLogLine Log(OS);
  Log << "validate-if-needed '" << Path << "'";
  Log << " boot=" << BootTime << " last-valid=" << ValidationTime;
  Log << " check-hash=" << CheckHash << " force=" << Force;
  if (Skipped)
    Log << " skipped";
  if (!ValidationError.empty())
    Log << " data was invalid " << ValidationError;
}

void OnDiskCASLogger::logUnifiedOnDiskCacheRecover(StringRef Path,
                                                   uint64_t BootTime,
                                                   StringRef RecoveryError,
                                                   bool Skipped) {
  TextLogLine Log(OS);
  Log << "recover '" << Path << "' boot=" << BootTime;
  if (Skipped)
    Log << " skipped";
  if (!RecoveryError.empty())
    Log << " failed " << RecoveryError;
}

void OnDiskCASLogger::logTempFileCreate(StringRef Name) {
  TextLogLine Log(OS);
  Log << "standalone file create '" << Name << "'";
}

void OnDiskCASLogger::logTempFileKeep(StringRef TmpName, StringRef Name,
                                      std::error_code EC) {
  TextLogLine Log(OS);
  Log << "standalone file rename '" << TmpName << "' to '" << Name << "'";
  if (EC)
    Log << " error: " << EC.message();
}

void OnDiskCASLogger::logTempFileRemove(StringRef TmpName, std::error_code EC) {
  TextLogLine Log(OS);
  Log << "standalone file remove '" << TmpName << "'";
  if (EC)
    Log << " error: " << EC.message();
}