diff --git a/clang/include/clang/Basic/AtomicLineLogger.h b/clang/include/clang/Basic/AtomicLineLogger.h index 641a5410617b..3d06ddfce026 100644 --- a/clang/include/clang/Basic/AtomicLineLogger.h +++ b/clang/include/clang/Basic/AtomicLineLogger.h @@ -47,6 +47,15 @@ public: return *this; } + template + void logArray(StringRef Prefix, StringRef Sep, const RangeT &Arr) { + if (FormattingOS) { + *FormattingOS << Prefix; + for (const auto &C : Arr) + *FormattingOS << Sep << C; + } + } + friend class AtomicLineLogger; }; diff --git a/clang/include/clang/DependencyScanning/DependencyScanningService.h b/clang/include/clang/DependencyScanning/DependencyScanningService.h index f626061c267d..b1d304eaf52a 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 @@ 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 diff --git a/clang/include/clang/DependencyScanning/DependencyScanningWorker.h b/clang/include/clang/DependencyScanning/DependencyScanningWorker.h index 1abcacf45fff..04c0868fe322 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" diff --git a/clang/include/clang/DependencyScanning/InProcessModuleCache.h b/clang/include/clang/DependencyScanning/InProcessModuleCache.h index 61b56adaa80a..f7f1d23e7529 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 -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 5484fd59f175..f494251bb1f1 100644 --- a/clang/include/clang/Serialization/InMemoryModuleCache.h +++ b/clang/include/clang/Serialization/InMemoryModuleCache.h @@ -15,6 +15,7 @@ #include namespace clang { +class AtomicLineLogger; /// In-memory cache for modules. /// @@ -51,7 +52,11 @@ class InMemoryModuleCache : public llvm::RefCountedBase { /// Cache of buffers. llvm::StringMap 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 50d643ef36a0..131675f2716b 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,13 @@ class ModuleCache { llvm::DenseMap> 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 diff --git a/clang/lib/DependencyScanning/DependencyScannerImpl.cpp b/clang/lib/DependencyScanning/DependencyScannerImpl.cpp index 143b3038c315..2a264269652c 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(); - 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 AsyncCompiles; if (Service.getOpts().AsyncScanModules) { - auto ModCache = makeInProcessModuleCache(Service.getModuleCacheEntries()); + auto ModCache = makeInProcessModuleCache(Service.getModuleCacheEntries(), + Service.getLogger()); auto ScanInstanceStorage = std::make_unique( std::make_shared(*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 166a61bc4933..f0b90f029b83 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,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; diff --git a/clang/lib/DependencyScanning/InProcessModuleCache.cpp b/clang/lib/DependencyScanning/InProcessModuleCache.cpp index ae858e5d2bda..bc6ff88c5732 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 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 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> read(StringRef FileName, off_t &Size, time_t &ModTime) override { + Logger.log() << "pcm_read_disk: " << FileName; ModuleCacheEntry &Entry = getOrCreateEntry(FileName); std::lock_guard Lock(Entry.Mutex); if (Entry.State == ModuleCacheEntry::S_Unknown) { @@ -191,6 +198,7 @@ public: } // namespace std::shared_ptr -dependencies::makeInProcessModuleCache(ModuleCacheEntries &Entries) { - return std::make_shared(Entries); +dependencies::makeInProcessModuleCache(ModuleCacheEntries &Entries, + AtomicLineLogger &Logger) { + return std::make_shared(Entries, Logger); } diff --git a/clang/lib/Frontend/CompilerInstance.cpp b/clang/lib/Frontend/CompilerInstance.cpp index 941c9e40f0c1..66662a786e6f 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" @@ -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(Buffer); std::unique_ptr Action = diff --git a/clang/lib/Serialization/InMemoryModuleCache.cpp b/clang/lib/Serialization/InMemoryModuleCache.cpp index dcd6395434c1..097e3e4c313a 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 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 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 82c487bf65ec..8cb860074faf 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 getLock(StringRef ModuleFilename) override { return std::make_unique(ModuleFilename); diff --git a/clang/lib/Tooling/DependencyScanningTool.cpp b/clang/lib/Tooling/DependencyScanningTool.cpp index 11b225830c2f..b435e42af28b 100644 --- a/clang/lib/Tooling/DependencyScanningTool.cpp +++ b/clang/lib/Tooling/DependencyScanningTool.cpp @@ -412,6 +412,13 @@ llvm::Expected CompilerInstanceWithContext::initializeOrError( DependencyScanningTool &Tool, StringRef CWD, ArrayRef 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(CommandLine); @@ -428,6 +435,11 @@ llvm::Expected CompilerInstanceWithContext::computeDependenciesByNameOrError( StringRef ModuleName, const llvm::DenseSet &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 ModCache = - makeInProcessModuleCache(Worker.Service.getModuleCacheEntries()); + std::shared_ptr ModCache = makeInProcessModuleCache( + Worker.Service.getModuleCacheEntries(), Worker.Service.getLogger()); CIPtr = std::make_unique( createScanCompilerInvocation(*OriginalInvocation, Worker.Service, Controller), diff --git a/clang/test/ClangScanDeps/logging-drop-pcm.c b/clang/test/ClangScanDeps/logging-drop-pcm.c new file mode 100644 index 000000000000..971469f373c7 --- /dev/null +++ b/clang/test/ClangScanDeps/logging-drop-pcm.c @@ -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(); } 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 000000000000..954d25acdd1f --- /dev/null +++ b/clang/test/ClangScanDeps/logging-simple-by-name.c @@ -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); diff --git a/clang/test/ClangScanDeps/logging-simple.c b/clang/test/ClangScanDeps/logging-simple.c new file mode 100644 index 000000000000..d85d660317c7 --- /dev/null +++ b/clang/test/ClangScanDeps/logging-simple.c @@ -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(); } diff --git a/clang/test/ClangScanDeps/logging-two-threads.c b/clang/test/ClangScanDeps/logging-two-threads.c new file mode 100644 index 000000000000..a56117f67ba0 --- /dev/null +++ b/clang/test/ClangScanDeps/logging-two-threads.c @@ -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(); } diff --git a/clang/tools/clang-scan-deps/ClangScanDeps.cpp b/clang/tools/clang-scan-deps/ClangScanDeps.cpp index 1270f6f05a6c..2b35d54349f3 100644 --- a/clang/tools/clang-scan-deps/ClangScanDeps.cpp +++ b/clang/tools/clang-scan-deps/ClangScanDeps.cpp @@ -110,6 +110,7 @@ static std::optional ModuleNames; static std::vector 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 e4de994530e6..9cf3b7857bec 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/Basic/AtomicLineLoggerTest.cpp b/clang/unittests/Basic/AtomicLineLoggerTest.cpp index 9135d5a36275..b1dfb616d08c 100644 --- a/clang/unittests/Basic/AtomicLineLoggerTest.cpp +++ b/clang/unittests/Basic/AtomicLineLoggerTest.cpp @@ -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 Args = {"clang", "-cc1", "-x", "c"}; + Logger.log().logArray("cmd:", " ", ArrayRef(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()); diff --git a/clang/unittests/DependencyScanning/InProcessModuleCacheTest.cpp b/clang/unittests/DependencyScanning/InProcessModuleCacheTest.cpp index e239ae1e6282..5b667a4989f5 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 ModCache = makeInProcessModuleCache(Entries); + AtomicLineLogger Logger; + std::shared_ptr 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 ModCache = makeInProcessModuleCache(Entries); + AtomicLineLogger Logger; + std::shared_ptr 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 f0cfa2f8f0c3..25c3b48b556c 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 getBuffer(int I) { SmallVector Bytes; raw_svector_ostream(Bytes) << "data:" << I; @@ -23,7 +27,7 @@ std::unique_ptr 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));