[clang] [clang][DependencyScanning] Logging Dependency Scanning Events (PR #195896)
Qiongsi Wu via cfe-commits
cfe-commits at lists.llvm.org
Thu Jul 2 11:55:25 PDT 2026
https://github.com/qiongsiwu updated https://github.com/llvm/llvm-project/pull/195896
>From ac03996367d0d74ceb75866c559be38d1b2b00bb Mon Sep 17 00:00:00 2001
From: Qiongsi Wu <qiongsiwu at gmail.com>
Date: Thu, 11 Jun 2026 08:27:47 -0700
Subject: [PATCH 1/4] [clang] Reland Adding an Atomic Line Logger (#195885)
(#202428)
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](https://github.com/llvm/llvm-project/blob/09abee845d2136630fc3f50524148daa55a740a8/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 | 67 ++++++
clang/lib/Basic/AtomicLineLogger.cpp | 77 +++++++
clang/lib/Basic/CMakeLists.txt | 1 +
.../unittests/Basic/AtomicLineLoggerTest.cpp | 212 ++++++++++++++++++
clang/unittests/Basic/CMakeLists.txt | 1 +
5 files changed, 358 insertions(+)
create mode 100644 clang/include/clang/Basic/AtomicLineLogger.h
create mode 100644 clang/lib/Basic/AtomicLineLogger.cpp
create mode 100644 clang/unittests/Basic/AtomicLineLoggerTest.cpp
diff --git a/clang/include/clang/Basic/AtomicLineLogger.h b/clang/include/clang/Basic/AtomicLineLogger.h
new file mode 100644
index 0000000000000..4ede0bea98b50
--- /dev/null
+++ b/clang/include/clang/Basic/AtomicLineLogger.h
@@ -0,0 +1,67 @@
+//===- 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 <memory>
+
+namespace clang {
+
+class LogLine {
+ SmallString<128> Buffer;
+ std::optional<llvm::raw_svector_ostream> FormattingOS;
+ raw_ostream *Dest = nullptr;
+
+public:
+ explicit LogLine(raw_ostream &Dest);
+ LogLine() {}
+ LogLine(LogLine &&Other);
+ LogLine(const LogLine &) = delete;
+ LogLine &operator=(const LogLine &) = delete;
+ LogLine &operator=(LogLine &&) = delete;
+
+ ~LogLine() {
+ if (Dest) {
+ assert(FormattingOS && "Cannot have uninitialized FormattingOS");
+ *FormattingOS << '\n';
+ Dest->write(Buffer.data(), Buffer.size());
+ }
+ }
+
+ template <typename T> LogLine &operator<<(const T &Val) {
+ if (Dest) {
+ assert(FormattingOS && "Cannot have uninitialized FormattingOS");
+ *FormattingOS << Val;
+ }
+ return *this;
+ }
+};
+
+class AtomicLineLogger {
+ std::unique_ptr<llvm::raw_fd_ostream> OS;
+
+public:
+ AtomicLineLogger() {}
+ AtomicLineLogger(StringRef LogFilePath);
+
+ LogLine log();
+};
+
+} // namespace clang
+
+#endif
diff --git a/clang/lib/Basic/AtomicLineLogger.cpp b/clang/lib/Basic/AtomicLineLogger.cpp
new file mode 100644
index 0000000000000..bee79e7c00b6f
--- /dev/null
+++ b/clang/lib/Basic/AtomicLineLogger.cpp
@@ -0,0 +1,77 @@
+//===- 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/Process.h"
+#include "llvm/Support/Threading.h"
+#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
+}
+
+LogLine::LogLine(raw_ostream &Dest) : FormattingOS(Buffer), Dest(&Dest) {
+ auto Millis = getTimestampMillis();
+ assert(FormattingOS && "Cannot have unintialized FormattingOS");
+ *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)), Dest(Other.Dest) {
+ if (Dest)
+ FormattingOS.emplace(Buffer);
+ Other.Dest = nullptr;
+}
+
+AtomicLineLogger::AtomicLineLogger(StringRef LogFilePath) {
+ if (LogFilePath.empty())
+ return;
+
+ std::error_code EC;
+ OS = std::make_unique<llvm::raw_fd_ostream>(
+ LogFilePath, EC, llvm::sys::fs::CD_OpenAlways, llvm::sys::fs::FA_Write,
+ llvm::sys::fs::OF_Append);
+ if (EC) {
+ llvm::errs() << "warning: unable to open log file '" << LogFilePath
+ << "': " << EC.message() << "\n";
+ OS.reset();
+ return;
+ }
+
+ // We need to set the OS to unbuffered, so LogLine's destructor can write
+ // a single line as an atomic operation.
+ OS->SetUnbuffered();
+}
+
+LogLine AtomicLineLogger::log() {
+ if (OS)
+ return LogLine(*OS);
+ return LogLine();
+}
diff --git a/clang/lib/Basic/CMakeLists.txt b/clang/lib/Basic/CMakeLists.txt
index 350c77696bcc4..21851e79b9d15 100644
--- a/clang/lib/Basic/CMakeLists.txt
+++ b/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
diff --git a/clang/unittests/Basic/AtomicLineLoggerTest.cpp b/clang/unittests/Basic/AtomicLineLoggerTest.cpp
new file mode 100644
index 0000000000000..169d16bd4b8a3
--- /dev/null
+++ b/clang/unittests/Basic/AtomicLineLoggerTest.cpp
@@ -0,0 +1,212 @@
+//===- 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(LogLineTest, NoOpLogLineProducesNoOutput) {
+ LogLine() << "stream to empty line";
+ // Check to make sure streaming into Empty does not lead to crashes.
+ EXPECT_TRUE(true);
+}
+
+TEST(LogLineTest, MoveConstructor) {
+ SmallString<128> Buffer;
+ llvm::raw_svector_ostream OS(Buffer);
+
+ {
+ LogLine Original(OS);
+ LogLine Moved(std::move(Original));
+ Moved << "after_move";
+ }
+
+ StringRef Output = OS.str();
+
+ // Only one line should be written (from Moved, not from Original).
+ EXPECT_EQ(Output.count('\n'), 1u);
+ EXPECT_TRUE(Output.contains("after_move"));
+}
+
+TEST(LogLineTest, ActiveLogLinePIDTIDMsg) {
+ SmallString<128> Buffer;
+ llvm::raw_svector_ostream OS(Buffer);
+ LogLine(OS) << "test_event: " << "some_file.pcm";
+
+ StringRef Output = OS.str();
+
+ // Ends with message + newline.
+ EXPECT_TRUE(Output.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(Output.contains(ExpectedPID));
+
+ // Verify TID is present.
+ std::string ExpectedTID = std::to_string(llvm::get_threadid());
+ EXPECT_TRUE(Output.contains(ExpectedTID));
+}
+
+TEST(LogLineTest, ActiveLogLineTimestamp) {
+ SmallString<128> Buffer;
+ llvm::raw_svector_ostream OS(Buffer);
+ // 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();
+
+ LogLine(OS) << "test_event";
+
+ auto After = std::chrono::duration_cast<std::chrono::milliseconds>(
+ std::chrono::system_clock::now().time_since_epoch())
+ .count();
+
+ StringRef Output = OS.str();
+
+ // Extract timestamp from "[<seconds>.<millis>]" prefix.
+ ASSERT_TRUE(Output.starts_with("["));
+ size_t CloseBracket = Output.find(']');
+ ASSERT_NE(CloseBracket, StringRef::npos);
+ StringRef TimestampStr = Output.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, DisabledLoggerDoesNotCrash) {
+ AtomicLineLogger Logger;
+ Logger.log() << "this goes nowhere";
+
+ // An empty logger should not crash.
+ EXPECT_TRUE(true);
+}
+
+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;
+
+ {
+ AtomicLineLogger Logger(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 << '_';
+ Logger.log() << Msg;
+ }
+ });
+ }
+ for (auto &T : Threads)
+ T.join();
+ }
+ // Logger 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());
+ }
+}
diff --git a/clang/unittests/Basic/CMakeLists.txt b/clang/unittests/Basic/CMakeLists.txt
index 016b6d5ddcb7b..9fbd97c43de66 100644
--- a/clang/unittests/Basic/CMakeLists.txt
+++ b/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
>From 7dbf4ff2dc1cdbcf25eaf14f6351125c08eae6b1 Mon Sep 17 00:00:00 2001
From: Qiongsi Wu <qiongsi_wu at apple.com>
Date: Wed, 1 Jul 2026 15:56:51 -0700
Subject: [PATCH 2/4] Fix race condition when the LogLine writes to the output
stream.
---
clang/include/clang/Basic/AtomicLineLogger.h | 35 ++++---
clang/lib/Basic/AtomicLineLogger.cpp | 76 +++++++++++----
.../unittests/Basic/AtomicLineLoggerTest.cpp | 94 +++++++++++--------
3 files changed, 137 insertions(+), 68 deletions(-)
diff --git a/clang/include/clang/Basic/AtomicLineLogger.h b/clang/include/clang/Basic/AtomicLineLogger.h
index 4ede0bea98b50..641a5410617b2 100644
--- a/clang/include/clang/Basic/AtomicLineLogger.h
+++ b/clang/include/clang/Basic/AtomicLineLogger.h
@@ -18,47 +18,54 @@
#include "clang/Basic/LLVM.h"
#include "llvm/ADT/SmallString.h"
#include "llvm/Support/raw_ostream.h"
-#include <memory>
+#include <atomic>
+#include <optional>
+#include <string>
namespace clang {
class LogLine {
SmallString<128> Buffer;
std::optional<llvm::raw_svector_ostream> FormattingOS;
- raw_ostream *Dest = nullptr;
+ int FD = -1;
+ std::atomic<uint64_t> *DroppedLines = nullptr;
+
+ explicit LogLine(int FD, std::atomic<uint64_t> *DroppedLines);
public:
- explicit LogLine(raw_ostream &Dest);
LogLine() {}
LogLine(LogLine &&Other);
LogLine(const LogLine &) = delete;
LogLine &operator=(const LogLine &) = delete;
LogLine &operator=(LogLine &&) = delete;
- ~LogLine() {
- if (Dest) {
- assert(FormattingOS && "Cannot have uninitialized FormattingOS");
- *FormattingOS << '\n';
- Dest->write(Buffer.data(), Buffer.size());
- }
- }
+ ~LogLine();
template <typename T> LogLine &operator<<(const T &Val) {
- if (Dest) {
- assert(FormattingOS && "Cannot have uninitialized FormattingOS");
+ if (FormattingOS)
*FormattingOS << Val;
- }
return *this;
}
+
+ friend class AtomicLineLogger;
};
class AtomicLineLogger {
- std::unique_ptr<llvm::raw_fd_ostream> OS;
+ 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();
};
diff --git a/clang/lib/Basic/AtomicLineLogger.cpp b/clang/lib/Basic/AtomicLineLogger.cpp
index bee79e7c00b6f..dc0f2bf5adc6c 100644
--- a/clang/lib/Basic/AtomicLineLogger.cpp
+++ b/clang/lib/Basic/AtomicLineLogger.cpp
@@ -13,8 +13,14 @@
#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
@@ -35,43 +41,79 @@ static uint64_t getTimestampMillis() {
#endif
}
-LogLine::LogLine(raw_ostream &Dest) : FormattingOS(Buffer), Dest(&Dest) {
+// 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();
- assert(FormattingOS && "Cannot have unintialized FormattingOS");
*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)), Dest(Other.Dest) {
- if (Dest)
+ : Buffer(std::move(Other.Buffer)), FD(Other.FD),
+ DroppedLines(Other.DroppedLines) {
+ if (Other.FormattingOS)
FormattingOS.emplace(Buffer);
- Other.Dest = nullptr;
+
+ // 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) {
+AtomicLineLogger::AtomicLineLogger(StringRef LogFilePath)
+ : LogPath(LogFilePath.str()) {
+#ifndef _WIN32
if (LogFilePath.empty())
return;
- std::error_code EC;
- OS = std::make_unique<llvm::raw_fd_ostream>(
- LogFilePath, EC, llvm::sys::fs::CD_OpenAlways, llvm::sys::fs::FA_Write,
- llvm::sys::fs::OF_Append);
+ 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";
- OS.reset();
+ FD = -1;
return;
}
-
- // We need to set the OS to unbuffered, so LogLine's destructor can write
- // a single line as an atomic operation.
- OS->SetUnbuffered();
+#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 (OS)
- return LogLine(*OS);
+ 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);
+}
diff --git a/clang/unittests/Basic/AtomicLineLoggerTest.cpp b/clang/unittests/Basic/AtomicLineLoggerTest.cpp
index 169d16bd4b8a3..9135d5a362758 100644
--- a/clang/unittests/Basic/AtomicLineLoggerTest.cpp
+++ b/clang/unittests/Basic/AtomicLineLoggerTest.cpp
@@ -16,71 +16,92 @@
using namespace clang;
-TEST(LogLineTest, NoOpLogLineProducesNoOutput) {
- LogLine() << "stream to empty line";
- // Check to make sure streaming into Empty does not lead to crashes.
+TEST(AtomicLineLoggerTest, DisabledLoggerDoesNotCrash) {
+ AtomicLineLogger Logger;
+ Logger.log() << "this goes nowhere";
+
+ // An empty logger should not crash.
EXPECT_TRUE(true);
}
-TEST(LogLineTest, MoveConstructor) {
- SmallString<128> Buffer;
- llvm::raw_svector_ostream OS(Buffer);
+#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");
{
- LogLine Original(OS);
+ AtomicLineLogger Logger(LogPath);
+ LogLine Original = Logger.log();
LogLine Moved(std::move(Original));
Moved << "after_move";
}
- StringRef Output = OS.str();
+ 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(Output.count('\n'), 1u);
- EXPECT_TRUE(Output.contains("after_move"));
+ EXPECT_EQ(Content.count('\n'), 1u);
+ EXPECT_TRUE(Content.contains("after_move"));
}
-TEST(LogLineTest, ActiveLogLinePIDTIDMsg) {
- SmallString<128> Buffer;
- llvm::raw_svector_ostream OS(Buffer);
- LogLine(OS) << "test_event: " << "some_file.pcm";
+TEST(AtomicLineLoggerTest, LogLinePIDTIDMsg) {
+ llvm::unittest::TempDir Dir("atomic-logger-test", /*Unique=*/true);
+ SmallString<128> LogPath(Dir.path());
+ llvm::sys::path::append(LogPath, "test.log");
- StringRef Output = OS.str();
+ {
+ 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(Output.ends_with("test_event: some_file.pcm\n"));
+ 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(Output.contains(ExpectedPID));
+ EXPECT_TRUE(Content.contains(ExpectedPID));
// Verify TID is present.
std::string ExpectedTID = std::to_string(llvm::get_threadid());
- EXPECT_TRUE(Output.contains(ExpectedTID));
+ EXPECT_TRUE(Content.contains(ExpectedTID));
}
-TEST(LogLineTest, ActiveLogLineTimestamp) {
- SmallString<128> Buffer;
- llvm::raw_svector_ostream OS(Buffer);
+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();
- LogLine(OS) << "test_event";
+ {
+ 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();
- StringRef Output = OS.str();
+ 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(Output.starts_with("["));
- size_t CloseBracket = Output.find(']');
+ ASSERT_TRUE(Content.starts_with("["));
+ size_t CloseBracket = Content.find(']');
ASSERT_NE(CloseBracket, StringRef::npos);
- StringRef TimestampStr = Output.slice(1, CloseBracket);
+ StringRef TimestampStr = Content.slice(1, CloseBracket);
// Parse "<seconds>.<millis>".
auto [SecStr, MillisStr] = TimestampStr.split('.');
@@ -93,14 +114,6 @@ TEST(LogLineTest, ActiveLogLineTimestamp) {
EXPECT_LE(LoggedMillis, (uint64_t)After);
}
-TEST(AtomicLineLoggerTest, DisabledLoggerDoesNotCrash) {
- AtomicLineLogger Logger;
- Logger.log() << "this goes nowhere";
-
- // An empty logger should not crash.
- EXPECT_TRUE(true);
-}
-
TEST(AtomicLineLoggerTest, SingleLineWrittenToFile) {
// Create a temp directory and build a log file path inside it.
llvm::unittest::TempDir Dir("atomic-logger-test", /*Unique=*/true);
@@ -139,7 +152,10 @@ TEST(AtomicLineLoggerTest, ConcurrentWritesProduceCompleteLines) {
constexpr unsigned MessageLen = 32;
{
- AtomicLineLogger Logger(LogPath);
+ // 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) {
@@ -152,14 +168,17 @@ TEST(AtomicLineLoggerTest, ConcurrentWritesProduceCompleteLines) {
// Pad to fixed width.
while (Msg.size() < MessageLen)
MsgOS << '_';
- Logger.log() << Msg;
+ if (I % 2)
+ LoggerOdd.log() << Msg;
+ else
+ LoggerEven.log() << Msg;
}
});
}
for (auto &T : Threads)
T.join();
}
- // Logger destroyed here. Log file is written to disk.
+ // Loggers destroyed here. Log file is written to disk.
auto BufOrErr = llvm::MemoryBuffer::getFile(LogPath);
ASSERT_TRUE(BufOrErr) << "Failed to read log file";
@@ -210,3 +229,4 @@ TEST(AtomicLineLoggerTest, ConcurrentWritesProduceCompleteLines) {
EXPECT_EQ(Pid, (uint64_t)llvm::sys::Process::getProcessId());
}
}
+#endif
>From f37d59ae7ffac8e0cabc4df8a86cce8d5e7ff221 Mon Sep 17 00:00:00 2001
From: Qiongsi Wu <qiongsi_wu at apple.com>
Date: Tue, 5 May 2026 10:01:32 -0700
Subject: [PATCH 3/4] Logging dependency scanning events.
---
.../DependencyScanningService.h | 10 ++-
.../DependencyScanningWorker.h | 2 +
.../DependencyScanning/InProcessModuleCache.h | 3 +-
.../clang/Serialization/InMemoryModuleCache.h | 5 ++
.../include/clang/Serialization/ModuleCache.h | 8 ++
.../DependencyScannerImpl.cpp | 9 ++-
.../DependencyScanningWorker.cpp | 17 ++++
.../InProcessModuleCache.cpp | 15 +++-
.../lib/Serialization/InMemoryModuleCache.cpp | 11 ++-
clang/lib/Serialization/ModuleCache.cpp | 6 ++
clang/lib/Tooling/DependencyScanningTool.cpp | 16 +++-
.../ClangScanDeps/logging-simple-by-name.c | 58 ++++++++++++++
clang/test/ClangScanDeps/logging-simple.c | 40 ++++++++++
.../test/ClangScanDeps/logging-two-threads.c | 79 +++++++++++++++++++
clang/tools/clang-scan-deps/ClangScanDeps.cpp | 5 ++
clang/tools/clang-scan-deps/Opts.td | 2 +
.../InProcessModuleCacheTest.cpp | 9 ++-
.../Serialization/InMemoryModuleCacheTest.cpp | 14 ++--
18 files changed, 291 insertions(+), 18 deletions(-)
create mode 100644 clang/test/ClangScanDeps/logging-simple-by-name.c
create mode 100644 clang/test/ClangScanDeps/logging-simple.c
create mode 100644 clang/test/ClangScanDeps/logging-two-threads.c
diff --git a/clang/include/clang/DependencyScanning/DependencyScanningService.h b/clang/include/clang/DependencyScanning/DependencyScanningService.h
index f626061c267dd..b1d304eaf52aa 100644
--- a/clang/include/clang/DependencyScanning/DependencyScanningService.h
+++ b/clang/include/clang/DependencyScanning/DependencyScanningService.h
@@ -9,6 +9,7 @@
#ifndef LLVM_CLANG_DEPENDENCYSCANNING_DEPENDENCYSCANNINGSERVICE_H
#define LLVM_CLANG_DEPENDENCYSCANNING_DEPENDENCYSCANNINGSERVICE_H
+#include "clang/Basic/AtomicLineLogger.h"
#include "clang/DependencyScanning/DependencyScanningFilesystem.h"
#include "clang/DependencyScanning/InProcessModuleCache.h"
#include "llvm/ADT/BitmaskEnum.h"
@@ -98,6 +99,9 @@ struct DependencyScanningServiceOptions {
bool FlushModuleCache = true;
/// Whether the caching VFS should cache missing filesystem entries.
bool CacheNegativeStats = shouldCacheNegativeStatsDefault();
+ /// The path to a log file, which logs timing of actions performed by
+ /// the dependency scanner.
+ std::string LogPath;
};
/// The dependency scanning service contains shared configuration and state that
@@ -105,7 +109,7 @@ struct DependencyScanningServiceOptions {
class DependencyScanningService {
public:
explicit DependencyScanningService(DependencyScanningServiceOptions Opts)
- : Opts(std::move(Opts)) {}
+ : Opts(std::move(Opts)), Logger(this->Opts.LogPath) {}
~DependencyScanningService() {
if (Opts.FlushModuleCache)
@@ -120,6 +124,8 @@ class DependencyScanningService {
ModuleCacheEntries &getModuleCacheEntries() { return ModCacheEntries; }
+ AtomicLineLogger &getLogger() { return Logger; }
+
private:
/// The options customizing dependency scanning behavior.
DependencyScanningServiceOptions Opts;
@@ -127,6 +133,8 @@ class DependencyScanningService {
DependencyScanningFilesystemSharedCache SharedCache;
/// The global module cache entries.
ModuleCacheEntries ModCacheEntries;
+ /// The logger of dependency scanning actions.
+ AtomicLineLogger Logger;
};
} // end namespace dependencies
diff --git a/clang/include/clang/DependencyScanning/DependencyScanningWorker.h b/clang/include/clang/DependencyScanning/DependencyScanningWorker.h
index 1abcacf45fffd..c4a868c21434c 100644
--- a/clang/include/clang/DependencyScanning/DependencyScanningWorker.h
+++ b/clang/include/clang/DependencyScanning/DependencyScanningWorker.h
@@ -9,6 +9,7 @@
#ifndef LLVM_CLANG_DEPENDENCYSCANNING_DEPENDENCYSCANNINGWORKER_H
#define LLVM_CLANG_DEPENDENCYSCANNING_DEPENDENCYSCANNINGWORKER_H
+#include "clang/Basic/AtomicLineLogger.h"
#include "clang/Basic/DiagnosticOptions.h"
#include "clang/Basic/FileManager.h"
#include "clang/Basic/LLVM.h"
@@ -26,6 +27,7 @@
namespace clang {
class DependencyOutputOptions;
+class AtomicLineLogger;
namespace tooling {
class CompilerInstanceWithContext;
diff --git a/clang/include/clang/DependencyScanning/InProcessModuleCache.h b/clang/include/clang/DependencyScanning/InProcessModuleCache.h
index 61b56adaa80a0..f7f1d23e7529d 100644
--- a/clang/include/clang/DependencyScanning/InProcessModuleCache.h
+++ b/clang/include/clang/DependencyScanning/InProcessModuleCache.h
@@ -9,6 +9,7 @@
#ifndef LLVM_CLANG_DEPENDENCYSCANNING_INPROCESSMODULECACHE_H
#define LLVM_CLANG_DEPENDENCYSCANNING_INPROCESSMODULECACHE_H
+#include "clang/Basic/AtomicLineLogger.h"
#include "clang/Serialization/ModuleCache.h"
#include "llvm/ADT/StringMap.h"
@@ -54,7 +55,7 @@ struct ModuleCacheEntries {
};
std::shared_ptr<ModuleCache>
-makeInProcessModuleCache(ModuleCacheEntries &Entries);
+makeInProcessModuleCache(ModuleCacheEntries &Entries, AtomicLineLogger &Logger);
} // namespace dependencies
} // namespace clang
diff --git a/clang/include/clang/Serialization/InMemoryModuleCache.h b/clang/include/clang/Serialization/InMemoryModuleCache.h
index 5484fd59f1757..f494251bb1f17 100644
--- a/clang/include/clang/Serialization/InMemoryModuleCache.h
+++ b/clang/include/clang/Serialization/InMemoryModuleCache.h
@@ -15,6 +15,7 @@
#include <memory>
namespace clang {
+class AtomicLineLogger;
/// In-memory cache for modules.
///
@@ -51,7 +52,11 @@ class InMemoryModuleCache : public llvm::RefCountedBase<InMemoryModuleCache> {
/// Cache of buffers.
llvm::StringMap<PCM> PCMs;
+ AtomicLineLogger &Logger;
+
public:
+ explicit InMemoryModuleCache(AtomicLineLogger &Logger) : Logger(Logger) {}
+
/// There are four states for a PCM. It must monotonically increase.
///
/// 1. Unknown: the PCM has neither been read from disk nor built.
diff --git a/clang/include/clang/Serialization/ModuleCache.h b/clang/include/clang/Serialization/ModuleCache.h
index 50d643ef36a05..f35f078e38cdc 100644
--- a/clang/include/clang/Serialization/ModuleCache.h
+++ b/clang/include/clang/Serialization/ModuleCache.h
@@ -27,6 +27,7 @@ class MemoryBufferRef;
} // namespace llvm
namespace clang {
+class AtomicLineLogger;
class InMemoryModuleCache;
/// The address of an instance of this class represents the identity of a module
@@ -43,7 +44,14 @@ class ModuleCache {
llvm::DenseMap<llvm::sys::fs::UniqueID, std::unique_ptr<ModuleCacheDirectory>>
ByUID;
+protected:
+ /// A logger to record timestamp read/write and file read/write.
+ AtomicLineLogger &Logger;
+
public:
+
+ explicit ModuleCache(AtomicLineLogger &Logger) : Logger(Logger) {}
+
/// Returns an opaque pointer representing the module cache directory. This
/// returns the same pointer regardless of the path spelling, as long as it
/// resolves to the same file system entity. This also resolves links in the
diff --git a/clang/lib/DependencyScanning/DependencyScannerImpl.cpp b/clang/lib/DependencyScanning/DependencyScannerImpl.cpp
index 143b3038c315d..2a264269652ca 100644
--- a/clang/lib/DependencyScanning/DependencyScannerImpl.cpp
+++ b/clang/lib/DependencyScanning/DependencyScannerImpl.cpp
@@ -637,7 +637,8 @@ struct AsyncModuleCompile : PPCallbacks {
VFS = createVFSFromCompilerInvocation(CI.getInvocation(),
CI.getDiagnostics(), std::move(VFS));
auto DC = std::make_unique<DiagnosticConsumer>();
- auto MC = makeInProcessModuleCache(Service.getModuleCacheEntries());
+ auto MC = makeInProcessModuleCache(Service.getModuleCacheEntries(),
+ Service.getLogger());
CompilerInstance::ThreadSafeCloneConfig CloneConfig(std::move(VFS), *DC,
std::move(MC));
auto ModCI1 = CI.cloneForModuleCompile(SourceLocation(), M, ModuleFileName,
@@ -739,7 +740,8 @@ bool DependencyScanningAction::runInvocation(
// Quickly discovers and compiles modules for the real scan below.
std::optional<AsyncModuleCompiles> AsyncCompiles;
if (Service.getOpts().AsyncScanModules) {
- auto ModCache = makeInProcessModuleCache(Service.getModuleCacheEntries());
+ auto ModCache = makeInProcessModuleCache(Service.getModuleCacheEntries(),
+ Service.getLogger());
auto ScanInstanceStorage = std::make_unique<CompilerInstance>(
std::make_shared<CompilerInvocation>(*ScanInvocation), PCHContainerOps,
std::move(ModCache));
@@ -765,7 +767,8 @@ bool DependencyScanningAction::runInvocation(
(void)ScanInstance.ExecuteAction(Action);
}
- auto ModCache = makeInProcessModuleCache(Service.getModuleCacheEntries());
+ auto ModCache = makeInProcessModuleCache(Service.getModuleCacheEntries(),
+ Service.getLogger());
ScanInstanceStorage.emplace(std::move(ScanInvocation),
std::move(PCHContainerOps), std::move(ModCache));
CompilerInstance &ScanInstance = *ScanInstanceStorage;
diff --git a/clang/lib/DependencyScanning/DependencyScanningWorker.cpp b/clang/lib/DependencyScanning/DependencyScanningWorker.cpp
index 166a61bc4933c..260ea7e64d72c 100644
--- a/clang/lib/DependencyScanning/DependencyScanningWorker.cpp
+++ b/clang/lib/DependencyScanning/DependencyScanningWorker.cpp
@@ -13,6 +13,7 @@
#include "clang/DependencyScanning/DependencyScannerImpl.h"
#include "clang/Serialization/ObjectFilePCHContainerReader.h"
#include "llvm/ADT/IntrusiveRefCntPtr.h"
+#include "llvm/ADT/ScopeExit.h"
#include "llvm/Support/VirtualFileSystem.h"
using namespace clang;
@@ -89,6 +90,22 @@ bool DependencyScanningWorker::computeDependencies(
return true;
}
+ {
+ auto LogLine = Service.getLogger().log();
+ LogLine << "starting scanning command:";
+ for (const auto &C : Cmd) {
+ LogLine << " " << C;
+ }
+ }
+
+ llvm::scope_exit ExitLogging([&] {
+ auto LogLine = Service.getLogger().log();
+ LogLine << "finished scanning command:";
+ for (const auto &C : Cmd) {
+ LogLine << " " << C;
+ }
+ });
+
auto DiagEngineWithDiagOpts =
DiagnosticsEngineWithDiagOpts(Cmd, FS, DiagConsumer);
auto &Diags = *DiagEngineWithDiagOpts.DiagEngine;
diff --git a/clang/lib/DependencyScanning/InProcessModuleCache.cpp b/clang/lib/DependencyScanning/InProcessModuleCache.cpp
index ae858e5d2bda4..89f7099f38a2b 100644
--- a/clang/lib/DependencyScanning/InProcessModuleCache.cpp
+++ b/clang/lib/DependencyScanning/InProcessModuleCache.cpp
@@ -8,7 +8,9 @@
#include "clang/DependencyScanning/InProcessModuleCache.h"
+#include "clang/Basic/AtomicLineLogger.h"
#include "clang/Serialization/InMemoryModuleCache.h"
+#include "clang/Serialization/ModuleCache.h"
#include "llvm/Support/AdvisoryLock.h"
#include "llvm/Support/Chrono.h"
#include "llvm/Support/Error.h"
@@ -109,7 +111,8 @@ class InProcessModuleCache : public ModuleCache {
}
public:
- InProcessModuleCache(ModuleCacheEntries &Entries) : Entries(Entries) {}
+ InProcessModuleCache(ModuleCacheEntries &Entries, AtomicLineLogger &Logger)
+ : ModuleCache(Logger), Entries(Entries), InMemory(Logger) {}
std::unique_ptr<llvm::AdvisoryLock> getLock(StringRef Filename) override {
auto &Entry = getOrCreateEntry(Filename);
@@ -119,6 +122,7 @@ class InProcessModuleCache : public ModuleCache {
std::time_t getModuleTimestamp(StringRef Filename) override {
auto &Timestamp = getOrCreateEntry(Filename).Timestamp;
+ Logger.log() << "timestamp_read: " << Filename;
return Timestamp.load();
}
@@ -126,6 +130,7 @@ class InProcessModuleCache : public ModuleCache {
// Note: This essentially replaces FS contention with mutex contention.
auto &Timestamp = getOrCreateEntry(Filename).Timestamp;
+ Logger.log() << "timestamp_write: " << Filename;
Timestamp.store(llvm::sys::toTimeT(std::chrono::system_clock::now()));
}
@@ -143,8 +148,10 @@ class InProcessModuleCache : public ModuleCache {
std::error_code write(StringRef Path, llvm::MemoryBufferRef Buffer,
off_t &Size, time_t &ModTime) override {
+ Logger.log() << "pcm_write: " << Path;
ModuleCacheEntry &Entry = getOrCreateEntry(Path);
std::lock_guard<std::mutex> Lock(Entry.Mutex);
+ Logger.log() << "pcm_write: " << Path;
if (Entry.State == ModuleCacheEntry::S_Written) {
assert(Entry.WrittenBuffer && "Wrote PCM with no contents");
assert(Entry.WrittenBuffer->getBuffer() == Buffer.getBuffer() &&
@@ -164,6 +171,7 @@ class InProcessModuleCache : public ModuleCache {
Expected<std::unique_ptr<llvm::MemoryBuffer>>
read(StringRef FileName, off_t &Size, time_t &ModTime) override {
+ Logger.log() << "pcm_read_disk: " << FileName;
ModuleCacheEntry &Entry = getOrCreateEntry(FileName);
std::lock_guard<std::mutex> Lock(Entry.Mutex);
if (Entry.State == ModuleCacheEntry::S_Unknown) {
@@ -191,6 +199,7 @@ class InProcessModuleCache : public ModuleCache {
} // namespace
std::shared_ptr<ModuleCache>
-dependencies::makeInProcessModuleCache(ModuleCacheEntries &Entries) {
- return std::make_shared<InProcessModuleCache>(Entries);
+dependencies::makeInProcessModuleCache(ModuleCacheEntries &Entries,
+ AtomicLineLogger &Logger) {
+ return std::make_shared<InProcessModuleCache>(Entries, Logger);
}
diff --git a/clang/lib/Serialization/InMemoryModuleCache.cpp b/clang/lib/Serialization/InMemoryModuleCache.cpp
index dcd6395434c16..097e3e4c313a6 100644
--- a/clang/lib/Serialization/InMemoryModuleCache.cpp
+++ b/clang/lib/Serialization/InMemoryModuleCache.cpp
@@ -7,6 +7,7 @@
//===----------------------------------------------------------------------===//
#include "clang/Serialization/InMemoryModuleCache.h"
+#include "clang/Basic/AtomicLineLogger.h"
#include "llvm/Support/MemoryBuffer.h"
using namespace clang;
@@ -25,6 +26,7 @@ llvm::MemoryBuffer &
InMemoryModuleCache::addPCM(llvm::StringRef Filename,
std::unique_ptr<llvm::MemoryBuffer> Buffer,
off_t Size, time_t ModTime) {
+ Logger.log() << "pcm_add: " << Filename;
auto Insertion = PCMs.insert(
std::make_pair(Filename, PCM(std::move(Buffer), Size, ModTime)));
assert(Insertion.second && "Already has a PCM");
@@ -35,6 +37,7 @@ llvm::MemoryBuffer &
InMemoryModuleCache::addBuiltPCM(llvm::StringRef Filename,
std::unique_ptr<llvm::MemoryBuffer> Buffer,
off_t Size, time_t ModTime) {
+ Logger.log() << "pcm_add_built: " << Filename;
auto &PCM = PCMs[Filename];
assert(!PCM.IsFinal && "Trying to override finalized PCM?");
assert(!PCM.Buffer && "Trying to override tentative PCM?");
@@ -48,6 +51,7 @@ InMemoryModuleCache::addBuiltPCM(llvm::StringRef Filename,
llvm::MemoryBuffer *InMemoryModuleCache::lookupPCM(llvm::StringRef Filename,
off_t &Size,
time_t &ModTime) const {
+ Logger.log() << "pcm_read_cached: " << Filename;
auto I = PCMs.find(Filename);
if (I == PCMs.end())
return nullptr;
@@ -71,14 +75,19 @@ bool InMemoryModuleCache::tryToDropPCM(llvm::StringRef Filename) {
auto &PCM = I->second;
assert(PCM.Buffer && "PCM to remove is scheduled to be built...");
- if (PCM.IsFinal)
+ if (PCM.IsFinal) {
+ Logger.log() << "pcm_not_dropped: " << Filename;
return true;
+ }
+ Logger.log() << "pcm_dropped: " << Filename;
PCM.Buffer.reset();
return false;
}
void InMemoryModuleCache::finalizePCM(llvm::StringRef Filename) {
+ Logger.log() << "pcm_finalized: " << Filename;
+
auto I = PCMs.find(Filename);
assert(I != PCMs.end() && "PCM to finalize is unknown...");
diff --git a/clang/lib/Serialization/ModuleCache.cpp b/clang/lib/Serialization/ModuleCache.cpp
index 82c487bf65ecd..8cb860074faf9 100644
--- a/clang/lib/Serialization/ModuleCache.cpp
+++ b/clang/lib/Serialization/ModuleCache.cpp
@@ -8,6 +8,7 @@
#include "clang/Serialization/ModuleCache.h"
+#include "clang/Basic/AtomicLineLogger.h"
#include "clang/Serialization/InMemoryModuleCache.h"
#include "clang/Serialization/ModuleFile.h"
#include "llvm/ADT/ScopeExit.h"
@@ -220,10 +221,15 @@ clang::readImpl(StringRef FileName, off_t &Size, time_t &ModTime) {
}
namespace {
+
+static AtomicLineLogger NoOpLogger;
class CrossProcessModuleCache : public ModuleCache {
InMemoryModuleCache InMemory;
public:
+ explicit CrossProcessModuleCache()
+ : ModuleCache(NoOpLogger), InMemory(NoOpLogger) {}
+
std::unique_ptr<llvm::AdvisoryLock>
getLock(StringRef ModuleFilename) override {
return std::make_unique<llvm::LockFileManager>(ModuleFilename);
diff --git a/clang/lib/Tooling/DependencyScanningTool.cpp b/clang/lib/Tooling/DependencyScanningTool.cpp
index 11b225830c2fc..b435e42af28b4 100644
--- a/clang/lib/Tooling/DependencyScanningTool.cpp
+++ b/clang/lib/Tooling/DependencyScanningTool.cpp
@@ -412,6 +412,13 @@ llvm::Expected<CompilerInstanceWithContext>
CompilerInstanceWithContext::initializeOrError(
DependencyScanningTool &Tool, StringRef CWD,
ArrayRef<std::string> CommandLine, DependencyActionController &Controller) {
+ {
+ auto LogLine = Tool.Worker.Service.getLogger().log();
+ LogLine << "init_compiler_instance_with_context:";
+ for (const auto &C : CommandLine) {
+ LogLine << " " << C;
+ }
+ }
auto DiagPrinterWithOS =
std::make_unique<TextDiagnosticsPrinterWithOutput>(CommandLine);
@@ -428,6 +435,11 @@ llvm::Expected<TranslationUnitDeps>
CompilerInstanceWithContext::computeDependenciesByNameOrError(
StringRef ModuleName, const llvm::DenseSet<ModuleID> &AlreadySeen,
DependencyActionController &Controller) {
+ Worker.Service.getLogger().log() << "start scan_by_name: " << ModuleName;
+ llvm::scope_exit ExitLogging([&] {
+ Worker.Service.getLogger().log() << "finish scan_by_name: " << ModuleName;
+ });
+
FullDependencyConsumer Consumer(AlreadySeen);
// We need to clear the DiagnosticOutput so that each by-name lookup
// has a clean diagnostics buffer.
@@ -462,8 +474,8 @@ bool CompilerInstanceWithContext::initialize(
canonicalizeDefines(OriginalInvocation->getPreprocessorOpts());
// Create the CompilerInstance.
- std::shared_ptr<ModuleCache> ModCache =
- makeInProcessModuleCache(Worker.Service.getModuleCacheEntries());
+ std::shared_ptr<ModuleCache> ModCache = makeInProcessModuleCache(
+ Worker.Service.getModuleCacheEntries(), Worker.Service.getLogger());
CIPtr = std::make_unique<CompilerInstance>(
createScanCompilerInvocation(*OriginalInvocation, Worker.Service,
Controller),
diff --git a/clang/test/ClangScanDeps/logging-simple-by-name.c b/clang/test/ClangScanDeps/logging-simple-by-name.c
new file mode 100644
index 0000000000000..1e2b7393c7377
--- /dev/null
+++ b/clang/test/ClangScanDeps/logging-simple-by-name.c
@@ -0,0 +1,58 @@
+// Test logging events for the scan-by-name path using CompilerInstanceWithContext.
+// This test also covers the case where the compiler spawns a new thread to scan
+// an included module.
+// Specifically, when the compiler scans dependency for module N on thread TID1,
+// it creates a different thread TID2 to scan for M. TID2 discovers that M has
+// been built, picks up the up-to-date pcm, and returns back to TID1.
+// RUN: rm -rf %t
+// RUN: split-file %s %t
+// RUN: sed -e "s|DIR|%/t|g" %t/cdb.json.template > %t/cdb.json
+
+// RUN: clang-scan-deps -compilation-database %t/cdb.json \
+// RUN: -format experimental-full -log-path=%t/scan.log -j 1 \
+// RUN: -module-names=M,N -o %t/deps.json
+// RUN: FileCheck %s < %t/scan.log
+
+// CHECK: [{{[0-9]+\.[0-9]+}}] [[#PID:]] [[#TID1:]]: init_compiler_instance_with_context:{{.*}}
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: start scan_by_name: M
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_read: {{.*}}[[MPCMFILE:.*\.pcm]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_write: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_write: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_add_built: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_read: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_read_cached: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_finalized: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: finish scan_by_name: M
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: start scan_by_name: N
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_read: {{.*}}[[NPCMFILE:.*\.pcm]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_read_cached: {{.*}}[[NPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_read_disk: {{.*}}[[NPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID2:]]: timestamp_read: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID2]]: pcm_read_cached: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID2]]: pcm_finalized: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_write: {{.*}}[[NPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_write: {{.*}}[[NPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_add_built: {{.*}}[[NPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_read: {{.*}}[[NPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_read_cached: {{.*}}[[NPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_read: {{.*}}[[NPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_finalized: {{.*}}[[NPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: finish scan_by_name: N
+
+//--- cdb.json.template
+[{
+ "file": "",
+ "directory": "DIR",
+ "command": "clang -fmodules -fimplicit-module-maps -fmodules-cache-path=DIR/cache -I DIR -fsyntax-only -x c -fbuild-session-timestamp=1 -fmodules-validate-once-per-build-session"
+}]
+
+//--- module.modulemap
+module M { header "M.h" }
+module N { header "N.h" }
+
+//--- M.h
+void m(void);
+
+//--- N.h
+#include "M.h"
+void n(void);
\ No newline at end of file
diff --git a/clang/test/ClangScanDeps/logging-simple.c b/clang/test/ClangScanDeps/logging-simple.c
new file mode 100644
index 0000000000000..81ab6fd8abb87
--- /dev/null
+++ b/clang/test/ClangScanDeps/logging-simple.c
@@ -0,0 +1,40 @@
+// Test the strict sequence of events when building a single scanning pcm.
+
+// RUN: rm -rf %t
+// RUN: split-file %s %t
+// RUN: sed -e "s|DIR|%/t|g" %t/cdb.json.template > %t/cdb.json
+
+// RUN: clang-scan-deps -compilation-database %t/cdb.json \
+// RUN: -format experimental-full -log-path=%t/scan.log -j 1 -o %t/deps.json
+// RUN: FileCheck %s < %t/scan.log
+
+// The check lines below form a strict sequence of events logged when we only
+// build a single scanning pcm. We should only log these events, no more and no
+// less, strictly in this order. Changes to this list should be intentional.
+
+// CHECK: [{{[0-9]+\.[0-9]+}}] [[#PID:]] [[#TID:]]: starting scanning command:{{.*}}tu.c
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: timestamp_read: {{.*}}[[PCMFILE:.*\.pcm]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: pcm_write: {{.*}}[[PCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: timestamp_write: {{.*}}[[PCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: pcm_add_built: {{.*}}[[PCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: timestamp_read: {{.*}}[[PCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: pcm_read_cached: {{.*}}[[PCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: pcm_finalized: {{.*}}[[PCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: finished scanning command:{{.*}}tu.c
+
+//--- cdb.json.template
+[{
+ "directory": "DIR",
+ "command": "clang -fsyntax-only DIR/tu.c -fmodules -fimplicit-module-maps -fmodules-cache-path=DIR/cache -fbuild-session-timestamp=1 -fmodules-validate-once-per-build-session",
+ "file": "DIR/tu.c"
+}]
+
+//--- module.modulemap
+module M { header "M.h" }
+
+//--- M.h
+void m(void);
+
+//--- tu.c
+#include "M.h"
+void foo(void) { m(); }
\ No newline at end of file
diff --git a/clang/test/ClangScanDeps/logging-two-threads.c b/clang/test/ClangScanDeps/logging-two-threads.c
new file mode 100644
index 0000000000000..7b033f132ca63
--- /dev/null
+++ b/clang/test/ClangScanDeps/logging-two-threads.c
@@ -0,0 +1,79 @@
+// Test that when two threads are scanning two different TUs, we log an expected
+// number of events (26 in this case), and for each pcm file, the sequence
+// of events is expected.
+// RUN: rm -rf %t
+// RUN: split-file %s %t
+// RUN: sed -e "s|DIR|%/t|g" %t/cdb.json.template > %t/cdb.json
+
+// RUN: clang-scan-deps -compilation-database %t/cdb.json \
+// RUN: -format experimental-full -log-path=%t/scan.log -j 2 -o %t/deps.json
+
+// Verify both TUs were scanned.
+// RUN: FileCheck %s --check-prefix=TU1 < %t/scan.log
+// RUN: FileCheck %s --check-prefix=TU2 < %t/scan.log
+
+// TU1: starting scanning command:{{.*}}tu1.c
+// TU1: finished scanning command:{{.*}}tu1.c
+
+// TU2: starting scanning command:{{.*}}tu2.c
+// TU2: finished scanning command:{{.*}}tu2.c
+
+// Verify the total number of logged events.
+// RUN: wc -l < %t/scan.log | FileCheck %s --check-prefix=LINECOUNT
+// LINECOUNT: {{^ *26$}}
+
+// Verify exactly two pcm_writes.
+// RUN: grep -c "pcm_write:" %t/scan.log | FileCheck %s --check-prefix=PCMWRITES
+// PCMWRITES: 2
+
+// Verify A's pcm is written before B's pcm.
+// RUN: grep "pcm_write:" %t/scan.log | FileCheck %s --check-prefix=WRITEORDER
+// WRITEORDER: pcm_write: {{.*}}A-{{.*}}.pcm
+// WRITEORDER-NEXT: pcm_write: {{.*}}B-{{.*}}.pcm
+
+// Check the correct sequence for building module A.
+// RUN: grep "A-" %t/scan.log | FileCheck %s --check-prefix=ASEQ
+// ASEQ: timestamp_read: {{.*}}A-{{.*}}.pcm
+// ASEQ: pcm_write: {{.*}}A-{{.*}}.pcm
+// ASEQ: timestamp_write: {{.*}}A-{{.*}}.pcm
+// ASEQ: pcm_add_built: {{.*}}A-{{.*}}.pcm
+// ASEQ: pcm_finalized: {{.*}}A-{{.*}}.pcm
+
+// Check the correct sequence for building module B.
+// RUN: grep "B-" %t/scan.log | FileCheck %s --check-prefix=BSEQ
+// BSEQ: timestamp_read: {{.*}}B-{{.*}}.pcm
+// BSEQ: pcm_write: {{.*}}B-{{.*}}.pcm
+// BSEQ: timestamp_write: {{.*}}B-{{.*}}.pcm
+// BSEQ: pcm_add_built: {{.*}}B-{{.*}}.pcm
+// BSEQ: pcm_finalized: {{.*}}B-{{.*}}.pcm
+
+//--- cdb.json.template
+[{
+ "directory": "DIR",
+ "command": "clang -fsyntax-only DIR/tu1.c -fmodules -fimplicit-module-maps -fmodules-cache-path=DIR/cache -fbuild-session-timestamp=1 -fmodules-validate-once-per-build-session",
+ "file": "DIR/tu1.c"
+},
+{
+ "directory": "DIR",
+ "command": "clang -fsyntax-only DIR/tu2.c -fmodules -fimplicit-module-maps -fmodules-cache-path=DIR/cache -fbuild-session-timestamp=1 -fmodules-validate-once-per-build-session",
+ "file": "DIR/tu2.c"
+}]
+
+//--- module.modulemap
+module A { header "A.h" }
+module B { header "B.h" }
+
+//--- A.h
+void a(void);
+
+//--- B.h
+void b(void);
+
+//--- tu1.c
+#include "A.h"
+void foo(void) { a(); }
+
+//--- tu2.c
+#include "A.h"
+#include "B.h"
+void bar(void) { b(); }
\ No newline at end of file
diff --git a/clang/tools/clang-scan-deps/ClangScanDeps.cpp b/clang/tools/clang-scan-deps/ClangScanDeps.cpp
index 1270f6f05a6c7..2b35d54349f3c 100644
--- a/clang/tools/clang-scan-deps/ClangScanDeps.cpp
+++ b/clang/tools/clang-scan-deps/ClangScanDeps.cpp
@@ -110,6 +110,7 @@ static std::optional<std::string> ModuleNames;
static std::vector<std::string> ModuleDepTargets;
static std::string TranslationUnitFile;
static ResourceDirRecipeKind ResourceDirRecipe;
+static std::string LogPath;
static bool Verbose;
static bool AsyncScanModules;
static bool PrintTiming;
@@ -266,6 +267,9 @@ static void ParseArgs(int argc, char **argv) {
VerbatimArgs = Args.hasArg(OPT_verbatim_args);
+ if (const llvm::opt::Arg *A = Args.getLastArg(OPT_log_path_EQ))
+ LogPath = A->getValue();
+
if (const llvm::opt::Arg *A = Args.getLastArgNoClaim(OPT_DASH_DASH))
CommandLine.assign(A->getValues().begin(), A->getValues().end());
}
@@ -1188,6 +1192,7 @@ int clang_scan_deps_main(int argc, char **argv, const llvm::ToolContext &) {
Opts.AsyncScanModules = AsyncScanModules;
Opts.FlushModuleCache = !NoFlushModuleCache;
Opts.CacheNegativeStats = CacheNegativeStats;
+ Opts.LogPath = LogPath;
llvm::Timer T;
T.startTimer();
diff --git a/clang/tools/clang-scan-deps/Opts.td b/clang/tools/clang-scan-deps/Opts.td
index e4de994530e63..9cf3b7857bec9 100644
--- a/clang/tools/clang-scan-deps/Opts.td
+++ b/clang/tools/clang-scan-deps/Opts.td
@@ -53,4 +53,6 @@ def no_flush_module_cache : F<"no-flush-module-cache", "do not flush the module
def verbatim_args : F<"verbatim-args", "Pass commands to the scanner verbatim without adjustments">;
+defm log_path : Eq<"log-path", "Write dependency scanning log to file">;
+
def DASH_DASH : Option<["--"], "", KIND_REMAINING_ARGS>;
diff --git a/clang/unittests/DependencyScanning/InProcessModuleCacheTest.cpp b/clang/unittests/DependencyScanning/InProcessModuleCacheTest.cpp
index e239ae1e6282c..5b667a4989f50 100644
--- a/clang/unittests/DependencyScanning/InProcessModuleCacheTest.cpp
+++ b/clang/unittests/DependencyScanning/InProcessModuleCacheTest.cpp
@@ -1,5 +1,6 @@
#include "clang/DependencyScanning/InProcessModuleCache.h"
+#include "clang/Basic/AtomicLineLogger.h"
#include "llvm/Support/FileSystem.h"
#include "llvm/Support/MemoryBuffer.h"
#include "llvm/Testing/Support/Error.h"
@@ -11,7 +12,9 @@ using namespace clang::dependencies;
TEST(InProcessModuleCache, ReadWriteInvalidation) {
ModuleCacheEntries Entries;
- std::shared_ptr<ModuleCache> ModCache = makeInProcessModuleCache(Entries);
+ AtomicLineLogger Logger;
+ std::shared_ptr<ModuleCache> ModCache =
+ makeInProcessModuleCache(Entries, Logger);
int FD;
llvm::SmallString<256> Path;
@@ -38,7 +41,9 @@ TEST(InProcessModuleCache, ReadWriteInvalidation) {
TEST(InProcessModuleCache, ReadReadInvalidation) {
ModuleCacheEntries Entries;
- std::shared_ptr<ModuleCache> ModCache = makeInProcessModuleCache(Entries);
+ AtomicLineLogger Logger;
+ std::shared_ptr<ModuleCache> ModCache =
+ makeInProcessModuleCache(Entries, Logger);
int FD;
llvm::SmallString<256> Path;
diff --git a/clang/unittests/Serialization/InMemoryModuleCacheTest.cpp b/clang/unittests/Serialization/InMemoryModuleCacheTest.cpp
index f0cfa2f8f0c3d..25c3b48b556c5 100644
--- a/clang/unittests/Serialization/InMemoryModuleCacheTest.cpp
+++ b/clang/unittests/Serialization/InMemoryModuleCacheTest.cpp
@@ -7,6 +7,7 @@
//===----------------------------------------------------------------------===//
#include "clang/Serialization/InMemoryModuleCache.h"
+#include "clang/Basic/AtomicLineLogger.h"
#include "llvm/Support/MemoryBuffer.h"
#include "gtest/gtest.h"
@@ -15,6 +16,9 @@ using namespace clang;
namespace {
+// A logger instances to satisfy InMemoryModuleCache.
+AtomicLineLogger NoOpLogger;
+
std::unique_ptr<MemoryBuffer> getBuffer(int I) {
SmallVector<char, 8> Bytes;
raw_svector_ostream(Bytes) << "data:" << I;
@@ -23,7 +27,7 @@ std::unique_ptr<MemoryBuffer> getBuffer(int I) {
}
TEST(InMemoryModuleCacheTest, initialState) {
- InMemoryModuleCache Cache;
+ InMemoryModuleCache Cache(NoOpLogger);
EXPECT_EQ(InMemoryModuleCache::Unknown, Cache.getPCMState("B"));
EXPECT_FALSE(Cache.isPCMFinal("B"));
EXPECT_FALSE(Cache.shouldBuildPCM("B"));
@@ -38,7 +42,7 @@ TEST(InMemoryModuleCacheTest, addPCM) {
auto B = getBuffer(1);
auto *RawB = B.get();
- InMemoryModuleCache Cache;
+ InMemoryModuleCache Cache(NoOpLogger);
EXPECT_EQ(RawB, &Cache.addPCM("B", std::move(B), 0, 0));
EXPECT_EQ(InMemoryModuleCache::Tentative, Cache.getPCMState("B"));
off_t Size;
@@ -58,7 +62,7 @@ TEST(InMemoryModuleCacheTest, addBuiltPCM) {
auto B = getBuffer(1);
auto *RawB = B.get();
- InMemoryModuleCache Cache;
+ InMemoryModuleCache Cache(NoOpLogger);
EXPECT_EQ(RawB, &Cache.addBuiltPCM("B", std::move(B), 0, 0));
EXPECT_EQ(InMemoryModuleCache::Final, Cache.getPCMState("B"));
off_t Size;
@@ -81,7 +85,7 @@ TEST(InMemoryModuleCacheTest, tryToDropPCM) {
auto *RawB2 = B2.get();
ASSERT_NE(RawB1, RawB2);
- InMemoryModuleCache Cache;
+ InMemoryModuleCache Cache(NoOpLogger);
EXPECT_EQ(InMemoryModuleCache::Unknown, Cache.getPCMState("B"));
EXPECT_EQ(RawB1, &Cache.addPCM("B", std::move(B1), 0, 0));
EXPECT_FALSE(Cache.tryToDropPCM("B"));
@@ -114,7 +118,7 @@ TEST(InMemoryModuleCacheTest, finalizePCM) {
auto B = getBuffer(1);
auto *RawB = B.get();
- InMemoryModuleCache Cache;
+ InMemoryModuleCache Cache(NoOpLogger);
EXPECT_EQ(InMemoryModuleCache::Unknown, Cache.getPCMState("B"));
EXPECT_EQ(RawB, &Cache.addPCM("B", std::move(B), 0, 0));
>From 71a839ace86afcf3e0624d8b81c683ae611a23c5 Mon Sep 17 00:00:00 2001
From: Qiongsi Wu <qiongsi_wu at apple.com>
Date: Thu, 2 Jul 2026 11:36:31 -0700
Subject: [PATCH 4/4] Address review comments.
---
.../DependencyScanningWorker.h | 1 -
.../include/clang/Serialization/ModuleCache.h | 3 ++-
.../InProcessModuleCache.cpp | 1 -
clang/lib/Frontend/CompilerInstance.cpp | 7 +++++++
.../ClangScanDeps/logging-simple-by-name.c | 20 ++++++++++++-------
clang/test/ClangScanDeps/logging-simple.c | 5 ++++-
.../test/ClangScanDeps/logging-two-threads.c | 7 +++----
7 files changed, 29 insertions(+), 15 deletions(-)
diff --git a/clang/include/clang/DependencyScanning/DependencyScanningWorker.h b/clang/include/clang/DependencyScanning/DependencyScanningWorker.h
index c4a868c21434c..04c0868fe3225 100644
--- a/clang/include/clang/DependencyScanning/DependencyScanningWorker.h
+++ b/clang/include/clang/DependencyScanning/DependencyScanningWorker.h
@@ -27,7 +27,6 @@
namespace clang {
class DependencyOutputOptions;
-class AtomicLineLogger;
namespace tooling {
class CompilerInstanceWithContext;
diff --git a/clang/include/clang/Serialization/ModuleCache.h b/clang/include/clang/Serialization/ModuleCache.h
index f35f078e38cdc..131675f2716bf 100644
--- a/clang/include/clang/Serialization/ModuleCache.h
+++ b/clang/include/clang/Serialization/ModuleCache.h
@@ -49,7 +49,6 @@ class ModuleCache {
AtomicLineLogger &Logger;
public:
-
explicit ModuleCache(AtomicLineLogger &Logger) : Logger(Logger) {}
/// Returns an opaque pointer representing the module cache directory. This
@@ -90,6 +89,8 @@ class ModuleCache {
read(StringRef FileName, off_t &Size, time_t &ModTime) = 0;
virtual ~ModuleCache() = default;
+
+ AtomicLineLogger &getLogger() { return Logger; }
};
/// Creates new \c ModuleCache backed by a file system directory that may be
diff --git a/clang/lib/DependencyScanning/InProcessModuleCache.cpp b/clang/lib/DependencyScanning/InProcessModuleCache.cpp
index 89f7099f38a2b..bc6ff88c57323 100644
--- a/clang/lib/DependencyScanning/InProcessModuleCache.cpp
+++ b/clang/lib/DependencyScanning/InProcessModuleCache.cpp
@@ -148,7 +148,6 @@ class InProcessModuleCache : public ModuleCache {
std::error_code write(StringRef Path, llvm::MemoryBufferRef Buffer,
off_t &Size, time_t &ModTime) override {
- Logger.log() << "pcm_write: " << Path;
ModuleCacheEntry &Entry = getOrCreateEntry(Path);
std::lock_guard<std::mutex> Lock(Entry.Mutex);
Logger.log() << "pcm_write: " << Path;
diff --git a/clang/lib/Frontend/CompilerInstance.cpp b/clang/lib/Frontend/CompilerInstance.cpp
index 8aee45b5dc644..53010e2a51f52 100644
--- a/clang/lib/Frontend/CompilerInstance.cpp
+++ b/clang/lib/Frontend/CompilerInstance.cpp
@@ -10,6 +10,7 @@
#include "clang/AST/ASTConsumer.h"
#include "clang/AST/ASTContext.h"
#include "clang/AST/Decl.h"
+#include "clang/Basic/AtomicLineLogger.h"
#include "clang/Basic/CharInfo.h"
#include "clang/Basic/Diagnostic.h"
#include "clang/Basic/DiagnosticFrontend.h"
@@ -58,6 +59,7 @@
#include "llvm/Support/Path.h"
#include "llvm/Support/Signals.h"
#include "llvm/Support/SmallVectorMemoryBuffer.h"
+#include "llvm/Support/Threading.h"
#include "llvm/Support/TimeProfiler.h"
#include "llvm/Support/Timer.h"
#include "llvm/Support/VirtualFileSystem.h"
@@ -1296,8 +1298,13 @@ CompilerInstance::compileModule(SourceLocation ImportLoc, StringRef ModuleName,
// Execute the action to actually build the module in-place. Use a separate
// thread so that we get a stack large enough.
+ uint64_t ParentTID = llvm::get_threadid();
bool Crashed = !llvm::CrashRecoveryContext().RunSafelyOnNewStack(
[&]() {
+ getModuleCache().getLogger().log()
+ << "module_compile_thread: parent=" << ParentTID
+ << " pcm_compile: " << ModuleFileName;
+
auto OS = std::make_unique<llvm::raw_svector_ostream>(Buffer);
std::unique_ptr<FrontendAction> Action =
diff --git a/clang/test/ClangScanDeps/logging-simple-by-name.c b/clang/test/ClangScanDeps/logging-simple-by-name.c
index 1e2b7393c7377..980fc5af6e187 100644
--- a/clang/test/ClangScanDeps/logging-simple-by-name.c
+++ b/clang/test/ClangScanDeps/logging-simple-by-name.c
@@ -1,9 +1,11 @@
// Test logging events for the scan-by-name path using CompilerInstanceWithContext.
// This test also covers the case where the compiler spawns a new thread to scan
// an included module.
-// Specifically, when the compiler scans dependency for module N on thread TID1,
-// it creates a different thread TID2 to scan for M. TID2 discovers that M has
-// been built, picks up the up-to-date pcm, and returns back to TID1.
+// Specifically, the compiler always creates a new thread to compile the module.
+// In the example below, the compiler starts on TID1. Once it discovers that
+// it needs to compile a PCM for module M, it creates a new thread with TID2 to
+// to do the module compilation. Similarly, the compiler creates a new thread
+// with TID3 to compile module N.
// RUN: rm -rf %t
// RUN: split-file %s %t
// RUN: sed -e "s|DIR|%/t|g" %t/cdb.json.template > %t/cdb.json
@@ -16,6 +18,9 @@
// CHECK: [{{[0-9]+\.[0-9]+}}] [[#PID:]] [[#TID1:]]: init_compiler_instance_with_context:{{.*}}
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: start scan_by_name: M
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_read: {{.*}}[[MPCMFILE:.*\.pcm]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_read_cached: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_read_disk: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID2:]]: module_compile_thread: parent=[[#TID1]] pcm_compile: {{.*}}[[MPCMFILE]]
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_write: {{.*}}[[MPCMFILE]]
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_write: {{.*}}[[MPCMFILE]]
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_add_built: {{.*}}[[MPCMFILE]]
@@ -27,9 +32,10 @@
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_read: {{.*}}[[NPCMFILE:.*\.pcm]]
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_read_cached: {{.*}}[[NPCMFILE]]
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_read_disk: {{.*}}[[NPCMFILE]]
-// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID2:]]: timestamp_read: {{.*}}[[MPCMFILE]]
-// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID2]]: pcm_read_cached: {{.*}}[[MPCMFILE]]
-// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID2]]: pcm_finalized: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID3:]]: module_compile_thread: parent=[[#TID1]] pcm_compile: {{.*}}[[NPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID3]]: timestamp_read: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID3]]: pcm_read_cached: {{.*}}[[MPCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID3]]: pcm_finalized: {{.*}}[[MPCMFILE]]
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_write: {{.*}}[[NPCMFILE]]
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: timestamp_write: {{.*}}[[NPCMFILE]]
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID1]]: pcm_add_built: {{.*}}[[NPCMFILE]]
@@ -55,4 +61,4 @@ void m(void);
//--- N.h
#include "M.h"
-void n(void);
\ No newline at end of file
+void n(void);
diff --git a/clang/test/ClangScanDeps/logging-simple.c b/clang/test/ClangScanDeps/logging-simple.c
index 81ab6fd8abb87..c6dab27bd6af5 100644
--- a/clang/test/ClangScanDeps/logging-simple.c
+++ b/clang/test/ClangScanDeps/logging-simple.c
@@ -14,6 +14,9 @@
// CHECK: [{{[0-9]+\.[0-9]+}}] [[#PID:]] [[#TID:]]: starting scanning command:{{.*}}tu.c
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: timestamp_read: {{.*}}[[PCMFILE:.*\.pcm]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: pcm_read_cached: {{.*}}[[PCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: pcm_read_disk: {{.*}}[[PCMFILE]]
+// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID2:]]: module_compile_thread: parent=[[#TID]] pcm_compile: {{.*}}[[PCMFILE]]
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: pcm_write: {{.*}}[[PCMFILE]]
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: timestamp_write: {{.*}}[[PCMFILE]]
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: pcm_add_built: {{.*}}[[PCMFILE]]
@@ -37,4 +40,4 @@ void m(void);
//--- tu.c
#include "M.h"
-void foo(void) { m(); }
\ No newline at end of file
+void foo(void) { m(); }
diff --git a/clang/test/ClangScanDeps/logging-two-threads.c b/clang/test/ClangScanDeps/logging-two-threads.c
index 7b033f132ca63..ed16ed305b6a9 100644
--- a/clang/test/ClangScanDeps/logging-two-threads.c
+++ b/clang/test/ClangScanDeps/logging-two-threads.c
@@ -1,6 +1,5 @@
// Test that when two threads are scanning two different TUs, we log an expected
-// number of events (26 in this case), and for each pcm file, the sequence
-// of events is expected.
+// number of events, and for each pcm file, the sequence of events is expected.
// RUN: rm -rf %t
// RUN: split-file %s %t
// RUN: sed -e "s|DIR|%/t|g" %t/cdb.json.template > %t/cdb.json
@@ -20,7 +19,7 @@
// Verify the total number of logged events.
// RUN: wc -l < %t/scan.log | FileCheck %s --check-prefix=LINECOUNT
-// LINECOUNT: {{^ *26$}}
+// LINECOUNT: {{^ *32$}}
// Verify exactly two pcm_writes.
// RUN: grep -c "pcm_write:" %t/scan.log | FileCheck %s --check-prefix=PCMWRITES
@@ -76,4 +75,4 @@ void foo(void) { a(); }
//--- tu2.c
#include "A.h"
#include "B.h"
-void bar(void) { b(); }
\ No newline at end of file
+void bar(void) { b(); }
More information about the cfe-commits
mailing list