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 <[email protected]> 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 <[email protected]> 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 <[email protected]> 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 <[email protected]> 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(); } _______________________________________________ cfe-commits mailing list [email protected] https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
