[clang] Adding an Atomic Line Logger (#205395)

This PR adds an atomic line logger to `clang`.

Situations have arisen where `clang` performs multi-threaded tasks (such
as dependency scanning), and race conditions may happen. Such race
conditions are difficult to debug using either `lldb` or with
`llvm::errs()`.

This logger provides atomic logging per line to a file on disk with time
stamps at each line to facilitate such investigations. Specifically, the
logger is designed with the following properties:

1. Each line is atomically written to the backing file. This avoids
concurrent writes making the output text interleaving.
2. Each line is prefixed with a timestamp, a process ID and a thread ID.
3. `LogLine` implements a `<<` operator to allow arbitrary printable
types to be piped into it.
4. The `LogLine`'s user does not need to check if it is setup or valid.
A LogLine is always valid and can always accept input from `<<`. It
becomes a no-op if the `LogLine` object is returned from a default
constructed `AtomicLineLogger`.
5. The write happens when a `LogLine` object goes out of scope.

The logger is inspired by the
[OnDiskCASLogger](09abee845d/llvm/include/llvm/CAS/OnDiskCASLogger.h (L33)).
A followup PR https://github.com/llvm/llvm-project/pull/195896 wires up
this logger to clang's dependency scanning stack.

Assisted-by: claude-opus-4.6

rdar://39907408

clang/include/clang/Basic/AtomicLineLogger.h

@@ -0,0 +1,74 @@
+//===- AtomicLineLogger.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
+//
+//===----------------------------------------------------------------------===//
+//
+/// \file
+/// Defines a logger where each line is written atomically to the file. It is
+/// safe to share a logger instance across threads.
+//
+//===----------------------------------------------------------------------===//
+
+#ifndef LLVM_CLANG_BASIC_ATOMICLINELOGGER_H
+#define LLVM_CLANG_BASIC_ATOMICLINELOGGER_H
+
+#include "clang/Basic/LLVM.h"
+#include "llvm/ADT/SmallString.h"
+#include "llvm/Support/raw_ostream.h"
+#include <atomic>
+#include <optional>
+#include <string>
+
+namespace clang {
+
+class LogLine {
+  SmallString<128> Buffer;
+  std::optional<llvm::raw_svector_ostream> FormattingOS;
+  int FD = -1;
+  std::atomic<uint64_t> *DroppedLines = nullptr;
+
+  explicit LogLine(int FD, std::atomic<uint64_t> *DroppedLines);
+
+public:
+  LogLine() {}
+  LogLine(LogLine &&Other);
+  LogLine(const LogLine &) = delete;
+  LogLine &operator=(const LogLine &) = delete;
+  LogLine &operator=(LogLine &&) = delete;
+
+  ~LogLine();
+
+  template <typename T> LogLine &operator<<(const T &Val) {
+    if (FormattingOS)
+      *FormattingOS << Val;
+    return *this;
+  }
+
+  friend class AtomicLineLogger;
+};
+
+class AtomicLineLogger {
+  int FD = -1;
+  std::string LogPath;
+  std::atomic<uint64_t> DroppedLines{0};
+
+public:
+  AtomicLineLogger() {}
+  AtomicLineLogger(StringRef LogFilePath);
+
+  // AtomicLineLogger is non-movable because LogLines have pointers to the
+  // atomic member DroppedLines.
+  AtomicLineLogger(AtomicLineLogger &&) = delete;
+  AtomicLineLogger &operator=(AtomicLineLogger &&) = delete;
+
+  ~AtomicLineLogger();
+
+  LogLine log();
+};
+
+} // namespace clang
+
+#endif

clang/lib/Basic/AtomicLineLogger.cpp

@@ -0,0 +1,119 @@
+//===- AtomicLineLogger.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
+//
+//===----------------------------------------------------------------------===//
+//
+// This file defines the implementation of an AtomicLineLogger and the relevant
+// supporting classes.
+//
+//===----------------------------------------------------------------------===//
+
+#include "clang/Basic/AtomicLineLogger.h"
+#include "llvm/ADT/StringRef.h"
+#include "llvm/Support/Errno.h"
+#include "llvm/Support/FileSystem.h"
+#include "llvm/Support/Format.h"
+#include "llvm/Support/Process.h"
+#include "llvm/Support/Threading.h"
+#ifndef _WIN32
+#include <unistd.h>
+#endif
+#ifdef __APPLE__
+#include <sys/time.h>
+#endif
+
+using namespace clang;
+
+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
+}
+
+// Writes the whole line into an FD that is opened with OF_Append.
+// This function only does one write (up to retry due to interrupts), and the
+// single write is blocking and atomic on POSIX systems.
+static bool writeLineToFD(int FD, const char *Data, size_t Size) {
+#ifndef _WIN32
+  ssize_t Written = llvm::sys::RetryAfterSignal(-1, write, FD, Data, Size);
+  return Written >= 0 && (static_cast<size_t>(Written) == Size);
+#else
+  (void)FD, (void)Data, (void)Size;
+  llvm_unreachable("Logging not supported on Windows!");
+  return false;
+#endif
+}
+
+LogLine::LogLine(int FD, std::atomic<uint64_t> *DroppedLines)
+    : FormattingOS(Buffer), FD(FD), DroppedLines(DroppedLines) {
+  auto Millis = getTimestampMillis();
+  *FormattingOS << llvm::format("[%lld.%0.3lld]", Millis / 1000, Millis % 1000);
+  *FormattingOS << ' ' << llvm::sys::Process::getProcessId() << ' '
+                << llvm::get_threadid() << ": ";
+}
+
+LogLine::LogLine(LogLine &&Other)
+    : Buffer(std::move(Other.Buffer)), FD(Other.FD),
+      DroppedLines(Other.DroppedLines) {
+  if (Other.FormattingOS)
+    FormattingOS.emplace(Buffer);
+
+  // Destroy the info in Other so its destructor does not write out the line.
+  Other.FormattingOS.reset();
+  Other.FD = -1;
+  Other.DroppedLines = nullptr;
+}
+
+LogLine::~LogLine() {
+  if (!FormattingOS)
+    return;
+  *FormattingOS << "\n";
+  if (!writeLineToFD(FD, Buffer.data(), Buffer.size()))
+    DroppedLines->fetch_add(1, std::memory_order_relaxed);
+}
+
+AtomicLineLogger::AtomicLineLogger(StringRef LogFilePath)
+    : LogPath(LogFilePath.str()) {
+#ifndef _WIN32
+  if (LogFilePath.empty())
+    return;
+
+  std::error_code EC = llvm::sys::fs::openFileForWrite(
+      LogFilePath, FD, llvm::sys::fs::CD_OpenAlways, llvm::sys::fs::OF_Append);
+  if (EC) {
+    llvm::errs() << "warning: unable to open log file '" << LogFilePath
+                 << "': " << EC.message() << "\n";
+    FD = -1;
+    return;
+  }
+#endif
+  // Write to files opened with OF_Append may not be guaranteed to be atomic
+  // on Windows, so we do not enable logging on Windows.
+}
+
+LogLine AtomicLineLogger::log() {
+  if (FD != -1)
+    return LogLine(FD, &DroppedLines);
+  return LogLine();
+}
+
+AtomicLineLogger::~AtomicLineLogger() {
+  if (FD == -1)
+    return;
+  if (uint64_t Dropped = DroppedLines.load(std::memory_order_relaxed))
+    llvm::errs() << "warning: log '" << LogPath
+                 << "' is incomplete: " << Dropped
+                 << " line(s) dropped due to write errors\n";
+  llvm::sys::Process::SafelyCloseFileDescriptor(FD);
+}

clang/lib/Basic/CMakeLists.txt

@@ -57,6 +57,7 @@ endif()
 add_clang_library(clangBasic
   ASTSourceDescriptor.cpp
   Attributes.cpp
+  AtomicLineLogger.cpp
   Builtins.cpp
   CLWarnings.cpp
   CharInfo.cpp

clang/unittests/Basic/AtomicLineLoggerTest.cpp

@@ -0,0 +1,232 @@
+//===- unittests/Basic/AtomicLineLoggerTest.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
+//
+//===----------------------------------------------------------------------===//
+
+#include "clang/Basic/AtomicLineLogger.h"
+#include "llvm/Support/MemoryBuffer.h"
+#include "llvm/Support/Process.h"
+#include "llvm/Support/Threading.h"
+#include "llvm/Testing/Support/SupportHelpers.h"
+#include "gtest/gtest.h"
+#include <thread>
+
+using namespace clang;
+
+TEST(AtomicLineLoggerTest, DisabledLoggerDoesNotCrash) {
+  AtomicLineLogger Logger;
+  Logger.log() << "this goes nowhere";
+
+  // An empty logger should not crash.
+  EXPECT_TRUE(true);
+}
+
+#ifndef _WIN32
+TEST(AtomicLineLoggerTest, LogLineMoveConstructor) {
+  llvm::unittest::TempDir Dir("atomic-logger-test", /*Unique=*/true);
+  SmallString<128> LogPath(Dir.path());
+  llvm::sys::path::append(LogPath, "test.log");
+
+  {
+    AtomicLineLogger Logger(LogPath);
+    LogLine Original = Logger.log();
+    LogLine Moved(std::move(Original));
+    Moved << "after_move";
+  }
+
+  auto BufOrErr = llvm::MemoryBuffer::getFile(LogPath);
+  ASSERT_TRUE(BufOrErr) << "Failed to read log file";
+  StringRef Content = (*BufOrErr)->getBuffer();
+
+  // Only one line should be written (from Moved, not from Original).
+  EXPECT_EQ(Content.count('\n'), 1u);
+  EXPECT_TRUE(Content.contains("after_move"));
+}
+
+TEST(AtomicLineLoggerTest, LogLinePIDTIDMsg) {
+  llvm::unittest::TempDir Dir("atomic-logger-test", /*Unique=*/true);
+  SmallString<128> LogPath(Dir.path());
+  llvm::sys::path::append(LogPath, "test.log");
+
+  {
+    AtomicLineLogger Logger(LogPath);
+    Logger.log() << "test_event: " << "some_file.pcm";
+  }
+
+  auto BufOrErr = llvm::MemoryBuffer::getFile(LogPath);
+  ASSERT_TRUE(BufOrErr) << "Failed to read log file";
+  StringRef Content = (*BufOrErr)->getBuffer();
+
+  // Ends with message + newline.
+  EXPECT_TRUE(Content.ends_with("test_event: some_file.pcm\n"));
+
+  // Prefix has the form: "<timestamp> <pid> <tid>: "
+  // Verify PID matches this process.
+  std::string ExpectedPID = std::to_string(llvm::sys::Process::getProcessId());
+  EXPECT_TRUE(Content.contains(ExpectedPID));
+
+  // Verify TID is present.
+  std::string ExpectedTID = std::to_string(llvm::get_threadid());
+  EXPECT_TRUE(Content.contains(ExpectedTID));
+}
+
+TEST(AtomicLineLoggerTest, LogLineTimestamp) {
+  llvm::unittest::TempDir Dir("atomic-logger-test", /*Unique=*/true);
+  SmallString<128> LogPath(Dir.path());
+  llvm::sys::path::append(LogPath, "test.log");
+
+  // Test that the timestamp generated is always sandwiched between Before
+  // and After to verify the correctness.
+  auto Before = std::chrono::duration_cast<std::chrono::milliseconds>(
+                    std::chrono::system_clock::now().time_since_epoch())
+                    .count();
+
+  {
+    AtomicLineLogger Logger(LogPath);
+    Logger.log() << "test_event";
+  }
+
+  auto After = std::chrono::duration_cast<std::chrono::milliseconds>(
+                   std::chrono::system_clock::now().time_since_epoch())
+                   .count();
+
+  auto BufOrErr = llvm::MemoryBuffer::getFile(LogPath);
+  ASSERT_TRUE(BufOrErr) << "Failed to read log file";
+  StringRef Content = (*BufOrErr)->getBuffer();
+
+  // Extract timestamp from "[<seconds>.<millis>]" prefix.
+  ASSERT_TRUE(Content.starts_with("["));
+  size_t CloseBracket = Content.find(']');
+  ASSERT_NE(CloseBracket, StringRef::npos);
+  StringRef TimestampStr = Content.slice(1, CloseBracket);
+
+  // Parse "<seconds>.<millis>".
+  auto [SecStr, MillisStr] = TimestampStr.split('.');
+  uint64_t Seconds, Millis;
+  ASSERT_FALSE(SecStr.getAsInteger(10, Seconds));
+  ASSERT_FALSE(MillisStr.getAsInteger(10, Millis));
+
+  uint64_t LoggedMillis = Seconds * 1000 + Millis;
+  EXPECT_GE(LoggedMillis, (uint64_t)Before);
+  EXPECT_LE(LoggedMillis, (uint64_t)After);
+}
+
+TEST(AtomicLineLoggerTest, SingleLineWrittenToFile) {
+  // Create a temp directory and build a log file path inside it.
+  llvm::unittest::TempDir Dir("atomic-logger-test", /*Unique=*/true);
+  SmallString<128> LogPath(Dir.path());
+  llvm::sys::path::append(LogPath, "test.log");
+
+  {
+    AtomicLineLogger Logger(LogPath);
+    Logger.log() << "pcm_write: module.pcm";
+  }
+  // Logger destroyed here. Log file is written to disk.
+
+  // Read the file back.
+  auto BufOrErr = llvm::MemoryBuffer::getFile(LogPath);
+  ASSERT_TRUE(BufOrErr) << "Failed to read log file";
+  StringRef Content = (*BufOrErr)->getBuffer();
+
+  // Verify the message is present and the line ends with a newline.
+  EXPECT_TRUE(Content.contains("pcm_write: module.pcm"));
+  EXPECT_TRUE(Content.ends_with("\n"));
+
+  // Verify there is exactly one line.
+  EXPECT_EQ(Content.count('\n'), 1u);
+}
+
+TEST(AtomicLineLoggerTest, ConcurrentWritesProduceCompleteLines) {
+  llvm::unittest::TempDir Dir("atomic-logger-concurrent", /*Unique=*/true);
+  SmallString<128> LogPath(Dir.path());
+  llvm::sys::path::append(LogPath, "concurrent.log");
+
+  // Testing concurrent writing of the log file.
+  // Each logged message starts with the string `thread_`, and the message is
+  // always 32 characters long.
+  constexpr unsigned NumThreads = 8;
+  constexpr unsigned LinesPerThread = 100;
+  constexpr unsigned MessageLen = 32;
+
+  {
+    // Creating two loggers based on the same file to make sure
+    // the write is still atomic.
+    AtomicLineLogger LoggerOdd(LogPath);
+    AtomicLineLogger LoggerEven(LogPath);
+
+    std::vector<std::thread> Threads;
+    for (unsigned I = 0; I < NumThreads; ++I) {
+      Threads.emplace_back([&, I] {
+        for (unsigned J = 0; J < LinesPerThread; ++J) {
+          SmallString<64> Msg;
+          llvm::raw_svector_ostream MsgOS(Msg);
+          MsgOS << "thread_" << llvm::format("%02u", I) << "_line_"
+                << llvm::format("%03u", J);
+          // Pad to fixed width.
+          while (Msg.size() < MessageLen)
+            MsgOS << '_';
+          if (I % 2)
+            LoggerOdd.log() << Msg;
+          else
+            LoggerEven.log() << Msg;
+        }
+      });
+    }
+    for (auto &T : Threads)
+      T.join();
+  }
+  // Loggers destroyed here. Log file is written to disk.
+
+  auto BufOrErr = llvm::MemoryBuffer::getFile(LogPath);
+  ASSERT_TRUE(BufOrErr) << "Failed to read log file";
+  StringRef Content = (*BufOrErr)->getBuffer();
+
+  SmallVector<StringRef> Lines;
+  Content.split(Lines, '\n', /*MaxSplit=*/-1, /*KeepEmpty=*/false);
+
+  EXPECT_EQ(Lines.size(), (size_t)(NumThreads * LinesPerThread));
+
+  for (const auto &Line : Lines) {
+    // For each line, we check the separator, message length, message start and
+    // the prefix format to make sure no lines are interleved.
+
+    // Split at ": " to separate prefix from message body.
+    auto [Prefix, Body] = Line.split(": ");
+    ASSERT_FALSE(Body.empty())
+        << "Malformed line (no ': ' separator): " << Line.str();
+
+    // Message body checks.
+    EXPECT_EQ(Body.size(), (size_t)MessageLen)
+        << "Wrong message length (interleaving?): " << Line.str();
+    EXPECT_TRUE(Body.starts_with("thread_"))
+        << "Corrupted message body: " << Line.str();
+
+    // Prefix format: "[<seconds>.<millis>] <pid> <tid>"
+    // Parse timestamp.
+    EXPECT_TRUE(Prefix.starts_with("[")) << "Missing '[': " << Prefix.str();
+    size_t CloseBracket = Prefix.find(']');
+    ASSERT_NE(CloseBracket, StringRef::npos) << "Missing ']': " << Prefix.str();
+
+    StringRef TimestampStr = Prefix.slice(1, CloseBracket);
+    auto [SecStr, MillisStr] = TimestampStr.split('.');
+    uint64_t Seconds, Millis;
+    EXPECT_FALSE(SecStr.getAsInteger(10, Seconds))
+        << "Bad seconds: " << SecStr.str();
+    EXPECT_FALSE(MillisStr.getAsInteger(10, Millis))
+        << "Bad millis: " << MillisStr.str();
+
+    // Parse PID and TID from the rest: " <pid> <tid>"
+    StringRef Rest = Prefix.substr(CloseBracket + 1).ltrim();
+    auto [PidStr, TidStr] = Rest.split(' ');
+    uint64_t Pid, Tid;
+    EXPECT_FALSE(PidStr.getAsInteger(10, Pid)) << "Bad PID: " << PidStr.str();
+    EXPECT_FALSE(TidStr.getAsInteger(10, Tid)) << "Bad TID: " << TidStr.str();
+
+    // PID should match this process.
+    EXPECT_EQ(Pid, (uint64_t)llvm::sys::Process::getProcessId());
+  }
+}
+#endif

clang/unittests/Basic/CMakeLists.txt

@@ -1,6 +1,7 @@
 # Basic tests have few LLVM and Clang dependencies, so linking it as a
 # distinct target enables faster iteration times at low cost.
 add_distinct_clang_unittest(BasicTests
+  AtomicLineLoggerTest.cpp
   CharInfoTest.cpp
   DarwinSDKInfoTest.cpp
   DiagnosticTest.cpp