f7d32078e5
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.
264 lines
8.8 KiB
C++
264 lines
8.8 KiB
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
|
|
//
|
|
//===----------------------------------------------------------------------===//
|
|
//
|
|
/// \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 AllowRecovery, bool Force, std::optional<StringRef> LLVMCas,
|
|
StringRef ValidationError, bool Skipped, bool Recovered) {
|
|
TextLogLine Log(OS);
|
|
Log << "validate-if-needed '" << Path << "'";
|
|
Log << " boot=" << BootTime << " last-valid=" << ValidationTime;
|
|
Log << " check-hash=" << CheckHash << " allow-recovery=" << AllowRecovery;
|
|
Log << " force=" << Force;
|
|
if (LLVMCas)
|
|
Log << " llvm-cas=" << *LLVMCas;
|
|
if (Skipped)
|
|
Log << " skipped";
|
|
if (Recovered)
|
|
Log << " recovered";
|
|
if (!ValidationError.empty())
|
|
Log << " data was invalid " << ValidationError;
|
|
}
|
|
|
|
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();
|
|
}
|