[clang][DependencyScanning] Logging Dependency Scanning Events (#195896)

This PR sets up an `AtomicLineLogger` (added by
https://github.com/llvm/llvm-project/pull/205395) to log the sequence of
dependency scanning events. The logging is triggered by a new `LogPath`
option in `DependencyScanningServiceOptions`. This PR adds an option
`-log-path=` to `clang-scan-deps` to trigger the log.

We are logging 16 events during dependency scanning. 

| Event | Logged In | When |
|-------|-----------|------|
| `starting scanning command: <args>` | `DependencyScanningWorker.cpp` |
Start of each TU scan |
| `finished scanning command: <args>` | `DependencyScanningWorker.cpp` |
End of each TU scan |
| `init_compiler_instance_with_context: <args>` |
`DependencyScanningTool.cpp` | CompilerInstanceWithContext created for
by-name scanning |
| `start scan_by_name: <module name>` | `DependencyScanningTool.cpp` |
Start of a by-name module query |
| `finish scan_by_name: <module name>` | `DependencyScanningTool.cpp` |
End of a by-name module query |
| `module_compile_thread: parent=<TID> pcm_compile: <pcm path>` |
`CompilerInstance::compileModule` | A new thread is created to compile a
pcm |
| `timestamp_read: <pcm path>` |
`InProcessModuleCache::getModuleTimestamp` | Validation timestamp read |
| `timestamp_write: <pcm path>` |
`InProcessModuleCache::updateModuleTimestamp` | Validation timestamp
update |
| `pcm_write: <pcm path>` | `InProcessModuleCache::write` | PCM write to
disk attempted |
| `pcm_read_disk: <pcm path>` | `InProcessModuleCache::read` | PCM read
from disk attempted |
| `pcm_read_cached: <pcm path>` | `InMemoryModuleCache::lookupPCM` | PCM
looked up in in-memory cache |
| `pcm_add: <pcm path>` | `InMemoryModuleCache::addPCM` | PCM added to
cache (not validated) |
| `pcm_add_built: <pcm path>` | `InMemoryModuleCache::addBuiltPCM` | PCM
added to cache (final) |
| `pcm_finalized: <pcm path>` | `InMemoryModuleCache::finalizePCM` | PCM
marked as validated/final |
| `pcm_dropped: <pcm path>` | `InMemoryModuleCache::tryToDropPCM` | PCM
dropped (validation failed) |
| `pcm_not_dropped: <pcm path>` | `InMemoryModuleCache::tryToDropPCM` |
PCM not dropped (validation failed, but already final) |

In addition to checking the logger's functionality,
`clang/test/ClangScanDeps/logging-simple.c` checks against the change
committed by https://github.com/llvm/llvm-project/pull/177062. Without
https://github.com/llvm/llvm-project/pull/177062,
`clang/test/ClangScanDeps/logging-simple.c` fails.

This implementation adds a single instance of `AtomicLineLogger` to the
`DependencyScanningService`. Most of the plumbing goes into the
`ModuleCache` and its derived classes.

Assisted-by: claude-opus-4.6

rdar://39907408
This commit is contained in:
Qiongsi Wu 2026-07-16 10:41:22 -07:00 committed by GitHub
parent 202cb24d24
commit a730dda7d5
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
22 changed files with 368 additions and 18 deletions

View file

@ -47,6 +47,15 @@ public:
return *this;
}
template <typename RangeT>
void logArray(StringRef Prefix, StringRef Sep, const RangeT &Arr) {
if (FormattingOS) {
*FormattingOS << Prefix;
for (const auto &C : Arr)
*FormattingOS << Sep << C;
}
}
friend class AtomicLineLogger;
};

View file

@ -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 @@ public:
ModuleCacheEntries &getModuleCacheEntries() { return ModCacheEntries; }
AtomicLineLogger &getLogger() { return Logger; }
private:
/// The options customizing dependency scanning behavior.
DependencyScanningServiceOptions Opts;
@ -127,6 +133,8 @@ private:
DependencyScanningFilesystemSharedCache SharedCache;
/// The global module cache entries.
ModuleCacheEntries ModCacheEntries;
/// The logger of dependency scanning actions.
AtomicLineLogger Logger;
};
} // end namespace dependencies

View file

@ -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"

View file

@ -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

View file

@ -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.

View file

@ -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,13 @@ 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
@ -82,6 +89,8 @@ public:
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

View file

@ -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;

View file

@ -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,12 @@ bool DependencyScanningWorker::computeDependencies(
return true;
}
Service.getLogger().log().logArray("starting scanning command:", " ", Cmd);
llvm::scope_exit ExitLogging([&] {
Service.getLogger().log().logArray("finished scanning command:", " ",
Cmd);
});
auto DiagEngineWithDiagOpts =
DiagnosticsEngineWithDiagOpts(Cmd, FS, DiagConsumer);
auto &Diags = *DiagEngineWithDiagOpts.DiagEngine;

View file

@ -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 @@ public:
std::time_t getModuleTimestamp(StringRef Filename) override {
auto &Timestamp = getOrCreateEntry(Filename).Timestamp;
Logger.log() << "timestamp_read: " << Filename;
return Timestamp.load();
}
@ -126,6 +130,7 @@ public:
// 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()));
}
@ -145,6 +150,7 @@ public:
off_t &Size, time_t &ModTime) override {
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 +170,7 @@ public:
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 +198,7 @@ public:
} // 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);
}

View file

@ -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"
@ -59,6 +60,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"
@ -1302,8 +1304,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 =

View file

@ -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...");

View file

@ -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);

View file

@ -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),

View file

@ -0,0 +1,41 @@
// Test "pcm_dropped" event logging.
// The test performs the same dependency scanning twice, with a change in the
// the header content in between.
// UNSUPPORTED: system-windows
// 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/scan1.log -j 1 -o %t/deps1.json
// RUN: echo "void a2(void);" >> %t/A.h
// RUN: clang-scan-deps -compilation-database %t/cdb.json \
// RUN: -format experimental-full -log-path=%t/scan2.log -j 1 -o %t/deps2.json
// RUN: FileCheck %s < %t/scan2.log
// The stale PCM is loaded as tentative (pcm_add) and dropped (pcm_dropped) on
// the same thread.
// CHECK: [{{[0-9]+\.[0-9]+}}] [[#PID:]] [[#TID:]]: pcm_add: {{.*}}[[PCM:A-.*\.pcm]]
// CHECK-NEXT: [{{[0-9]+\.[0-9]+}}] [[#PID]] [[#TID]]: pcm_dropped: {{.*}}[[PCM]]
// CHECK: pcm_add_built: {{.*}}[[PCM]]
// CHECK: pcm_finalized: {{.*}}[[PCM]]
//--- cdb.json.template
[{
"directory": "DIR",
"command": "clang -fsyntax-only DIR/tu.c -fmodules -fimplicit-module-maps -fmodules-cache-path=DIR/cache",
"file": "DIR/tu.c"
}]
//--- module.modulemap
module A { header "A.h" }
//--- A.h
void a(void);
//--- tu.c
#include "A.h"
void foo(void) { a(); }

View file

@ -0,0 +1,66 @@
// 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, 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.
// UNSUPPORTED: system-windows
// 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_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]]
// 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]] [[#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]]
// 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);

View file

@ -0,0 +1,44 @@
// Test the strict sequence of events when building a single scanning pcm.
// UNSUPPORTED: system-windows
// 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_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]]
// 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(); }

View file

@ -0,0 +1,81 @@
// Test that when two threads are scanning two different TUs, we log an expected
// number of events, and for each pcm file, the sequence of events is expected.
// UNSUPPORTED: system-windows
// 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
// Each module is compiled once, its pcm written once, and its timestamp written
// once, regardless of which thread wins the race to build the shared module A.
// RUN: grep -c "pcm_compile:" %t/scan.log | FileCheck %s --check-prefix=COMPILES
// RUN: grep -c "pcm_write:" %t/scan.log | FileCheck %s --check-prefix=PCMWRITES
// RUN: grep -c "timestamp_write:" %t/scan.log | FileCheck %s --check-prefix=TSWRITES
// COMPILES: {{^2$}}
// PCMWRITES: {{^2$}}
// TSWRITES: {{^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(); }

View file

@ -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();

View file

@ -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>;

View file

@ -73,6 +73,23 @@ TEST(AtomicLineLoggerTest, LogLinePIDTIDMsg) {
EXPECT_TRUE(Content.contains(ExpectedTID));
}
TEST(AtomicLineLoggerTest, LogLineLogArray) {
llvm::unittest::TempDir Dir("atomic-logger-test", /*Unique=*/true);
SmallString<128> LogPath(Dir.path());
llvm::sys::path::append(LogPath, "test.log");
{
AtomicLineLogger Logger(LogPath);
SmallVector<std::string> Args = {"clang", "-cc1", "-x", "c"};
Logger.log().logArray("cmd:", " ", ArrayRef<std::string>(Args));
}
auto BufOrErr = llvm::MemoryBuffer::getFile(LogPath);
ASSERT_TRUE(BufOrErr) << "Failed to read log file";
StringRef Content = (*BufOrErr)->getBuffer();
EXPECT_TRUE(Content.contains("cmd: clang -cc1 -x c"));
}
TEST(AtomicLineLoggerTest, LogLineTimestamp) {
llvm::unittest::TempDir Dir("atomic-logger-test", /*Unique=*/true);
SmallString<128> LogPath(Dir.path());

View file

@ -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;

View file

@ -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));