1//===----------------------------------------------------------------------===//
2//
3// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
4// See https://llvm.org/LICENSE.txt for license information.
5// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
6//
7//===----------------------------------------------------------------------===//
8//
9/// \file
10/// This file implements OnDiskCASLogger. The logger will write the timestamp
11/// and events to a log file using filestream. The logger should be thread-safe
12/// and process-safe because each write is small enough to atomically update the
13/// file.
14///
15/// The logger can be enabled via `LLVM_CAS_LOG` environmental variable.
16//
17//===----------------------------------------------------------------------===//
18
19#include "llvm/CAS/OnDiskCASLogger.h"
20
21#include "llvm/ADT/StringSwitch.h"
22#include "llvm/ADT/Twine.h"
23#include "llvm/Support/Error.h"
24#include "llvm/Support/FileSystem.h"
25#include "llvm/Support/Path.h"
26#include "llvm/Support/Process.h"
27#include "llvm/Support/Threading.h"
28#include "llvm/Support/raw_ostream.h"
29#ifdef __APPLE__
30#include <sys/time.h>
31#endif
32
33using namespace llvm;
34using namespace llvm::cas;
35using namespace llvm::cas::ondisk;
36
37// The version number in this log should be bumped if the log format is changed
38// in an incompatible way. It is currently a human-readable text file, so in
39// practice this would be if the log changed to binary or other machine-
40// readable format.
41static constexpr StringLiteral Filename = "v1.log";
42
43OnDiskCASLogger::OnDiskCASLogger(raw_fd_ostream &OS, bool LogAllocations)
44 : OS(OS), LogAllocations(LogAllocations) {}
45
46OnDiskCASLogger::~OnDiskCASLogger() {
47 OS.flush();
48 delete &OS;
49}
50
51static bool isDisabledEnv(StringRef V) {
52 return StringSwitch<bool>(V)
53 .Case(S: "0", Value: true)
54 .CaseLower(S: "no", Value: true)
55 .CaseLower(S: "false", Value: true)
56 .Default(Value: false);
57}
58
59Expected<std::unique_ptr<OnDiskCASLogger>>
60OnDiskCASLogger::openIfEnabled(const Twine &Path) {
61 const char *V = getenv(name: "LLVM_CAS_LOG");
62 if (V && !isDisabledEnv(V)) {
63 int LogLevel = -1;
64 StringRef(V).getAsInteger(Radix: 10, Result&: LogLevel);
65 return OnDiskCASLogger::open(Path, /*LogAllocations=*/LogLevel > 1 ? true
66 : false);
67 }
68 return nullptr;
69}
70Expected<std::unique_ptr<OnDiskCASLogger>>
71OnDiskCASLogger::open(const Twine &Path, bool LogAllocations) {
72 std::error_code EC;
73 SmallString<128> FullPath;
74 Path.toVector(Out&: FullPath);
75 sys::path::append(path&: FullPath, a: Filename);
76
77 auto OS =
78 std::make_unique<raw_fd_ostream>(args&: FullPath, args&: EC, args: sys::fs::CD_OpenAlways,
79 args: sys::fs::FA_Write, args: sys::fs::OF_Append);
80 if (EC)
81 return createFileError(F: FullPath, EC);
82
83 // Buffer is not thread-safe.
84 OS->SetUnbuffered();
85
86 return std::unique_ptr<OnDiskCASLogger>(
87 new OnDiskCASLogger{*OS.release(), LogAllocations});
88}
89
90static uint64_t getTimestampMillis() {
91#ifdef __APPLE__
92 // Using chrono is roughly 50% slower.
93 struct timeval T;
94 gettimeofday(&T, 0);
95 return T.tv_sec * 1000 + T.tv_usec / 1000;
96#else
97 auto Time = std::chrono::system_clock::now();
98 auto Millis = std::chrono::duration_cast<std::chrono::milliseconds>(
99 d: Time.time_since_epoch());
100 return Millis.count();
101#endif
102}
103
104namespace {
105/// Helper to log a single line that adds the timestamp, pid, and tid. The line
106/// is buffered and written in a single call to write() so that if the
107/// underlying OS syscall is handled atomically so is this log message.
108class TextLogLine : public raw_svector_ostream {
109public:
110 TextLogLine(raw_ostream &LogOS) : raw_svector_ostream(Buffer), LogOS(LogOS) {
111 startLogMsg(OS&: *this);
112 }
113
114 ~TextLogLine() {
115 finishLogMsg(OS&: *this);
116 LogOS.write(Ptr: Buffer.data(), Size: Buffer.size());
117 }
118
119 static void startLogMsg(raw_ostream &OS) {
120 auto Millis = getTimestampMillis();
121 OS << format(Fmt: "%lld.%0.3lld", Vals: Millis / 1000, Vals: Millis % 1000);
122 OS << ' ' << sys::Process::getProcessId() << ' ' << get_threadid() << ": ";
123 }
124
125 static void finishLogMsg(raw_ostream &OS) { OS << '\n'; }
126
127private:
128 raw_ostream &LogOS;
129 SmallString<128> Buffer;
130};
131} // anonymous namespace
132
133static void formatTrieOffset(raw_ostream &OS, int64_t Off) {
134 if (Off < 0) {
135 OS << '-';
136 Off = -Off;
137 }
138 OS << format_hex(N: Off, Width: 0);
139}
140
141void OnDiskCASLogger::logSubtrieHandleCmpXchg(void *Region, TrieOffset Trie,
142 size_t SlotI, TrieOffset Expected,
143 TrieOffset New,
144 TrieOffset Previous) {
145 TextLogLine Log(OS);
146 Log << "cmpxcgh subtrie region=" << Region << " offset=";
147 formatTrieOffset(OS&: Log, Off: Trie);
148 Log << " slot=" << SlotI << " expected=";
149 formatTrieOffset(OS&: Log, Off: Expected);
150 Log << " new=";
151 formatTrieOffset(OS&: Log, Off: New);
152 Log << " prev=";
153 formatTrieOffset(OS&: Log, Off: Previous);
154}
155
156void OnDiskCASLogger::logSubtrieHandleCreate(void *Region, TrieOffset Trie,
157 uint32_t StartBit,
158 uint32_t NumBits) {
159 TextLogLine Log(OS);
160 Log << "create subtrie region=" << Region << " offset=";
161 formatTrieOffset(OS&: Log, Off: Trie);
162 Log << " start-bit=" << StartBit << " num-bits=" << NumBits;
163}
164
165void OnDiskCASLogger::logHashMappedTrieHandleCreateRecord(
166 void *Region, TrieOffset Off, ArrayRef<uint8_t> Hash) {
167 TextLogLine Log(OS);
168 Log << "create record region=" << Region << " offset=";
169 formatTrieOffset(OS&: Log, Off);
170 Log << " hash=" << format_bytes(Bytes: Hash, FirstByteOffset: std::nullopt, NumPerLine: 32, ByteGroupSize: 32);
171}
172
173void OnDiskCASLogger::logMappedFileRegionArenaResizeFile(StringRef Path,
174 size_t Before,
175 size_t After) {
176 TextLogLine Log(OS);
177 Log << "resize mapped file '" << Path << "' from=" << Before
178 << " to=" << After;
179}
180
181void OnDiskCASLogger::logMappedFileRegionArenaCreate(StringRef Path, int FD,
182 void *Region,
183 size_t Capacity,
184 size_t Size) {
185 sys::fs::file_status Stat;
186 std::error_code EC = status(FD, Result&: Stat);
187
188 TextLogLine Log(OS);
189 Log << "mmap '" << Path << "' " << Region;
190 Log << " size=" << Size << " capacity=" << Capacity;
191 if (EC) {
192 Log << " failed status with error: " << EC.message();
193 return;
194 }
195 Log << " dev=" << format_hex(N: Stat.getUniqueID().getDevice(), Width: 4);
196 Log << " inode=" << format_hex(N: Stat.getUniqueID().getFile(), Width: 4);
197}
198
199void OnDiskCASLogger::logMappedFileRegionArenaOom(StringRef Path,
200 size_t Capacity, size_t Size,
201 size_t AllocSize) {
202 TextLogLine Log(OS);
203 Log << "oom '" << Path << "' old-size=" << Size << " capacity=" << Capacity
204 << "alloc-size=" << AllocSize;
205}
206void OnDiskCASLogger::logMappedFileRegionArenaClose(StringRef Path) {
207 TextLogLine Log(OS);
208 Log << "close mmap '" << Path << "'";
209}
210void OnDiskCASLogger::logMappedFileRegionArenaAllocate(void *Region,
211 TrieOffset Off,
212 size_t Size) {
213 if (!LogAllocations)
214 return;
215 TextLogLine Log(OS);
216 Log << "alloc " << Region << " offset=";
217 formatTrieOffset(OS&: Log, Off);
218 Log << " size=" << Size;
219}
220
221void OnDiskCASLogger::logUnifiedOnDiskCacheCollectGarbage(StringRef Path) {
222 TextLogLine Log(OS);
223 Log << "collect garbage '" << Path << "'";
224}
225
226void OnDiskCASLogger::logUnifiedOnDiskCacheValidateIfNeeded(
227 StringRef Path, uint64_t BootTime, uint64_t ValidationTime, bool CheckHash,
228 bool AllowRecovery, bool Force, std::optional<StringRef> LLVMCas,
229 StringRef ValidationError, bool Skipped, bool Recovered) {
230 TextLogLine Log(OS);
231 Log << "validate-if-needed '" << Path << "'";
232 Log << " boot=" << BootTime << " last-valid=" << ValidationTime;
233 Log << " check-hash=" << CheckHash << " allow-recovery=" << AllowRecovery;
234 Log << " force=" << Force;
235 if (LLVMCas)
236 Log << " llvm-cas=" << *LLVMCas;
237 if (Skipped)
238 Log << " skipped";
239 if (Recovered)
240 Log << " recovered";
241 if (!ValidationError.empty())
242 Log << " data was invalid " << ValidationError;
243}
244
245void OnDiskCASLogger::logTempFileCreate(StringRef Name) {
246 TextLogLine Log(OS);
247 Log << "standalone file create '" << Name << "'";
248}
249
250void OnDiskCASLogger::logTempFileKeep(StringRef TmpName, StringRef Name,
251 std::error_code EC) {
252 TextLogLine Log(OS);
253 Log << "standalone file rename '" << TmpName << "' to '" << Name << "'";
254 if (EC)
255 Log << " error: " << EC.message();
256}
257
258void OnDiskCASLogger::logTempFileRemove(StringRef TmpName, std::error_code EC) {
259 TextLogLine Log(OS);
260 Log << "standalone file remove '" << TmpName << "'";
261 if (EC)
262 Log << " error: " << EC.message();
263}
264