[clang][deps] Print tracing VFS data (llvm#108056)

jansvoboda11 · jansvoboda11 · commit 96a972f782ce · 2024-11-04T11:36:20.000-08:00
Clang's `-cc1 -print-stats` shows lots of useful internal data including basic `FileManager` stats. Since this layer caches some results, it is unclear how that information translates to actual filesystem accesses. This PR uses `llvm::vfs::TracingFileSystem` to provide that missing information. Similar mechanism is implemented for `clang-scan-deps`'s verbose mode (`-v`). IO contention proved to be a real bottleneck a couple of times already and this new feature should make those easier to detect in the future. The tracing VFS is inserted below the caching FS and above the real FS. (cherry picked from commit 6e4dcbb)
diff --git a/clang/include/clang/Tooling/DependencyScanning/DependencyScanningService.h b/clang/include/clang/Tooling/DependencyScanning/DependencyScanningService.h
@@ -96,7 +96,7 @@ class DependencyScanningService {
       std::shared_ptr<llvm::cas::ActionCache> Cache,
       IntrusiveRefCntPtr<llvm::cas::CachingOnDiskFileSystem> SharedFS,
       ScanningOptimizations OptimizeArgs = ScanningOptimizations::Default,
-      bool EagerLoadModules = false);
+      bool EagerLoadModules = false, bool TraceVFS = false);
 
   ScanningMode getMode() const { return Mode; }
 
@@ -106,6 +106,8 @@ class DependencyScanningService {
 
   bool shouldEagerLoadModules() const { return EagerLoadModules; }
 
+  bool shouldTraceVFS() const { return TraceVFS; }
+
   DependencyScanningFilesystemSharedCache &getSharedCache() {
     assert(!SharedFS && "Expected not to have a CASFS");
     assert(SharedCache && "Expected a shared cache");
@@ -131,6 +133,8 @@ class DependencyScanningService {
   const ScanningOptimizations OptimizeArgs;
   /// Whether to set up command-lines to load PCM files eagerly.
   const bool EagerLoadModules;
+  /// Whether to trace VFS accesses.
+  const bool TraceVFS;
   /// Shared CachingOnDiskFileSystem. Set to nullptr to not use CAS dependency
   /// scanning.
   IntrusiveRefCntPtr<llvm::cas::CachingOnDiskFileSystem> SharedFS;
diff --git a/clang/include/clang/Tooling/DependencyScanning/DependencyScanningTool.h b/clang/include/clang/Tooling/DependencyScanning/DependencyScanningTool.h
@@ -191,6 +191,8 @@ class DependencyScanningTool {
       StringRef CWD, const llvm::DenseSet<ModuleID> &AlreadySeen,
       LookupModuleOutputCallback LookupModuleOutput);
 
+  llvm::vfs::FileSystem &getWorkerVFS() const { return Worker.getVFS(); }
+
   ScanningOutputFormat getScanningFormat() const {
     return Worker.getScanningFormat();
   }
diff --git a/clang/include/clang/Tooling/DependencyScanning/DependencyScanningWorker.h b/clang/include/clang/Tooling/DependencyScanning/DependencyScanningWorker.h
@@ -162,6 +162,8 @@ class DependencyScanningWorker {
 
   bool shouldEagerLoadModules() const { return EagerLoadModules; }
 
+  llvm::vfs::FileSystem &getVFS() const { return *BaseFS; }
+
 private:
   std::shared_ptr<PCHContainerOperations> PCHContainerOps;
   /// The file system to be used during the scan.
diff --git a/clang/lib/Basic/FileManager.cpp b/clang/lib/Basic/FileManager.cpp
@@ -711,5 +711,16 @@ void FileManager::PrintStats() const {
   llvm::errs() << NumFileLookups << " file lookups, "
                << NumFileCacheMisses << " file cache misses.\n";
 
+  getVirtualFileSystem().visit([](llvm::vfs::FileSystem &VFS) {
+    if (auto *T = dyn_cast_or_null<llvm::vfs::TracingFileSystem>(&VFS))
+      llvm::errs() << "\n*** Virtual File System Stats:\n"
+                   << T->NumStatusCalls << " status() calls\n"
+                   << T->NumOpenFileForReadCalls << " openFileForRead() calls\n"
+                   << T->NumDirBeginCalls << " dir_begin() calls\n"
+                   << T->NumGetRealPathCalls << " getRealPath() calls\n"
+                   << T->NumExistsCalls << " exists() calls\n"
+                   << T->NumIsLocalCalls << " isLocal() calls\n";
+  });
+
   //llvm::errs() << PagesMapped << BytesOfPagesMapped << FSLookups;
 }
diff --git a/clang/lib/Frontend/CompilerInstance.cpp b/clang/lib/Frontend/CompilerInstance.cpp
@@ -397,6 +397,9 @@ FileManager *CompilerInstance::createFileManager(
                   : createVFSFromCompilerInvocation(getInvocation(),
                                                     getDiagnostics(), CAS);
   assert(VFS && "FileManager has no VFS?");
+  if (getFrontendOpts().ShowStats)
+    VFS =
+        llvm::makeIntrusiveRefCnt<llvm::vfs::TracingFileSystem>(std::move(VFS));
   FileMgr = new FileManager(getFileSystemOpts(), std::move(VFS));
   return FileMgr.get();
 }
diff --git a/clang/lib/Tooling/DependencyScanning/DependencyScanningService.cpp b/clang/lib/Tooling/DependencyScanning/DependencyScanningService.cpp
@@ -21,9 +21,9 @@ DependencyScanningService::DependencyScanningService(
     std::shared_ptr<llvm::cas::ObjectStore> CAS,
     std::shared_ptr<llvm::cas::ActionCache> Cache,
     IntrusiveRefCntPtr<llvm::cas::CachingOnDiskFileSystem> SharedFS,
-    ScanningOptimizations OptimizeArgs, bool EagerLoadModules)
+    ScanningOptimizations OptimizeArgs, bool EagerLoadModules, bool TraceVFS)
     : Mode(Mode), Format(Format), CASOpts(std::move(CASOpts)), CAS(std::move(CAS)), Cache(std::move(Cache)),
-      OptimizeArgs(OptimizeArgs), EagerLoadModules(EagerLoadModules),
+      OptimizeArgs(OptimizeArgs), EagerLoadModules(EagerLoadModules), TraceVFS(TraceVFS),
       SharedFS(std::move(SharedFS)) {
   if (!this->SharedFS)
     SharedCache.emplace();
diff --git a/clang/lib/Tooling/DependencyScanning/DependencyScanningWorker.cpp b/clang/lib/Tooling/DependencyScanning/DependencyScanningWorker.cpp
@@ -711,6 +711,9 @@ DependencyScanningWorker::DependencyScanningWorker(
   // The scanner itself writes only raw ast files.
   PCHContainerOps->registerWriter(std::make_unique<RawPCHContainerWriter>());
 
+  if (Service.shouldTraceVFS())
+    FS = llvm::makeIntrusiveRefCnt<llvm::vfs::TracingFileSystem>(std::move(FS));
+
   if (Service.useCASFS()) {
     CacheFS = Service.getSharedFS().createProxyFS();
     DepCASFS = new DependencyScanningCASFilesystem(CacheFS, *Service.getCache());
diff --git a/clang/test/ClangScanDeps/verbose.test b/clang/test/ClangScanDeps/verbose.test
@@ -0,0 +1,28 @@
+// RUN: rm -rf %t
+// RUN: split-file %s %t
+// RUN: sed -e "s|DIR|%/t|g" %t/cdb.json.in > %t/cdb.json
+
+// RUN: clang-scan-deps -compilation-database %t/cdb.json -v -o %t/result.json 2>&1 | FileCheck %s
+// CHECK:      *** Virtual File System Stats:
+// CHECK-NEXT: {{[[:digit:]]+}} status() calls
+// CHECK-NEXT: {{[[:digit:]]+}} openFileForRead() calls
+// CHECK-NEXT: {{[[:digit:]]+}} dir_begin() calls
+// CHECK-NEXT: {{[[:digit:]]+}} getRealPath() calls
+// CHECK-NEXT: {{[[:digit:]]+}} exists() calls
+// CHECK-NEXT: {{[[:digit:]]+}} isLocal() calls
+
+//--- tu.c
+
+//--- cdb.json.in
+[
+  {
+    "file": "DIR/tu.c"
+    "directory": "DIR",
+    "command": "clang -c DIR/tu.c -o DIR/tu.o"
+  },
+  {
+    "file": "DIR/tu.c"
+    "directory": "DIR",
+    "command": "clang -c DIR/tu.c -o DIR/tu.o"
+  }
+]
diff --git a/clang/test/Misc/print-stats-vfs.test b/clang/test/Misc/print-stats-vfs.test
@@ -0,0 +1,17 @@
+// RUN: rm -rf %t
+// RUN: split-file %s %t
+
+// RUN: %clang_cc1 -fsyntax-only %t/tu.c -I %t/dir1 -I %t/dir2 -print-stats 2>&1 | FileCheck %s
+
+//--- tu.c
+#include "header.h"
+//--- dir1/other.h
+//--- dir2/header.h
+
+// CHECK:      *** Virtual File System Stats:
+// CHECK-NEXT: {{[[:digit:]]+}} status() calls
+// CHECK-NEXT: {{[[:digit:]]+}} openFileForRead() calls
+// CHECK-NEXT: {{[[:digit:]]+}} dir_begin() calls
+// CHECK-NEXT: {{[[:digit:]]+}} getRealPath() calls
+// CHECK-NEXT: {{[[:digit:]]+}} exists() calls
+// CHECK-NEXT: {{[[:digit:]]+}} isLocal() calls
diff --git a/clang/tools/clang-scan-deps/ClangScanDeps.cpp b/clang/tools/clang-scan-deps/ClangScanDeps.cpp
@@ -1275,6 +1275,13 @@ int clang_scan_deps_main(int argc, char **argv, const llvm::ToolContext &) {
       Format == ScanningOutputFormat::FullTree)
     FD.emplace(ModuleName.empty() ? Inputs.size() : 0);
 
+  std::atomic<size_t> NumStatusCalls = 0;
+  std::atomic<size_t> NumOpenFileForReadCalls = 0;
+  std::atomic<size_t> NumDirBeginCalls = 0;
+  std::atomic<size_t> NumGetRealPathCalls = 0;
+  std::atomic<size_t> NumExistsCalls = 0;
+  std::atomic<size_t> NumIsLocalCalls = 0;
+
   auto ScanningTask = [&](DependencyScanningService &Service) {
     std::unique_ptr<llvm::vfs::FileSystem> FS = llvm::vfs::createPhysicalFileSystem();
     if (CAS)
@@ -1373,10 +1380,21 @@ int clang_scan_deps_main(int argc, char **argv, const llvm::ToolContext &) {
           HadErrors = true;
       }
     }
+
+    WorkerTool.getWorkerVFS().visit([&](llvm::vfs::FileSystem &VFS) {
+      if (auto *T = dyn_cast_or_null<llvm::vfs::TracingFileSystem>(&VFS)) {
+        NumStatusCalls += T->NumStatusCalls;
+        NumOpenFileForReadCalls += T->NumOpenFileForReadCalls;
+        NumDirBeginCalls += T->NumDirBeginCalls;
+        NumGetRealPathCalls += T->NumGetRealPathCalls;
+        NumExistsCalls += T->NumExistsCalls;
+        NumIsLocalCalls += T->NumIsLocalCalls;
+      }
+    });
   };
 
   DependencyScanningService Service(ScanMode, Format, CASOpts, CAS, Cache, FS,
-                                  OptimizeArgs, EagerLoadModules);
+                                  OptimizeArgs, EagerLoadModules, /*TraceVFS=*/Verbose);
 
   llvm::Timer T;
   T.startTimer();
@@ -1398,6 +1416,16 @@ int clang_scan_deps_main(int argc, char **argv, const llvm::ToolContext &) {
   }
 
   T.stopTimer();
+
+  if (Verbose)
+    llvm::errs() << "\n*** Virtual File System Stats:\n"
+                 << NumStatusCalls << " status() calls\n"
+                 << NumOpenFileForReadCalls << " openFileForRead() calls\n"
+                 << NumDirBeginCalls << " dir_begin() calls\n"
+                 << NumGetRealPathCalls << " getRealPath() calls\n"
+                 << NumExistsCalls << " exists() calls\n"
+                 << NumIsLocalCalls << " isLocal() calls\n";
+
   if (PrintTiming) {
     llvm::errs() << "wall time [s]\t"
                  << "process time [s]\t"

Original file line number	Diff line number	Diff line change
`@@ -191,6 +191,8 @@ class DependencyScanningTool {`
`191`	`191`	`StringRef CWD, const llvm::DenseSet<ModuleID> &AlreadySeen,`
`192`	`192`	`LookupModuleOutputCallback LookupModuleOutput);`
`193`	`193`
	`194`	`+ llvm::vfs::FileSystem &getWorkerVFS() const { return Worker.getVFS(); }`
	`195`	`+`
`194`	`196`	`ScanningOutputFormat getScanningFormat() const {`
`195`	`197`	`return Worker.getScanningFormat();`
`196`	`198`	`}`