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

jansvoboda11 · web-flow · commit 6e4dcbb21dab · 2024-09-11T16:04:56.000-07: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.
diff --git a/clang/include/clang/Tooling/DependencyScanning/DependencyScanningService.h b/clang/include/clang/Tooling/DependencyScanning/DependencyScanningService.h
@@ -76,7 +76,7 @@ class DependencyScanningService {
   DependencyScanningService(
       ScanningMode Mode, ScanningOutputFormat Format,
       ScanningOptimizations OptimizeArgs = ScanningOptimizations::Default,
-      bool EagerLoadModules = false);
+      bool EagerLoadModules = false, bool TraceVFS = false);
 
   ScanningMode getMode() const { return Mode; }
 
@@ -86,6 +86,8 @@ class DependencyScanningService {
 
   bool shouldEagerLoadModules() const { return EagerLoadModules; }
 
+  bool shouldTraceVFS() const { return TraceVFS; }
+
   DependencyScanningFilesystemSharedCache &getSharedCache() {
     return SharedCache;
   }
@@ -97,6 +99,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;
   /// The global file system cache.
   DependencyScanningFilesystemSharedCache SharedCache;
 };
diff --git a/clang/include/clang/Tooling/DependencyScanning/DependencyScanningTool.h b/clang/include/clang/Tooling/DependencyScanning/DependencyScanningTool.h
@@ -144,6 +144,8 @@ class DependencyScanningTool {
       StringRef CWD, const llvm::DenseSet<ModuleID> &AlreadySeen,
       LookupModuleOutputCallback LookupModuleOutput);
 
+  llvm::vfs::FileSystem &getWorkerVFS() const { return Worker.getVFS(); }
+
 private:
   DependencyScanningWorker Worker;
 };
diff --git a/clang/include/clang/Tooling/DependencyScanning/DependencyScanningWorker.h b/clang/include/clang/Tooling/DependencyScanning/DependencyScanningWorker.h
@@ -104,6 +104,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
@@ -692,5 +692,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
@@ -381,6 +381,9 @@ FileManager *CompilerInstance::createFileManager(
                   : createVFSFromCompilerInvocation(getInvocation(),
                                                     getDiagnostics());
   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
@@ -15,9 +15,9 @@ using namespace dependencies;
 
 DependencyScanningService::DependencyScanningService(
     ScanningMode Mode, ScanningOutputFormat Format,
-    ScanningOptimizations OptimizeArgs, bool EagerLoadModules)
+    ScanningOptimizations OptimizeArgs, bool EagerLoadModules, bool TraceVFS)
     : Mode(Mode), Format(Format), OptimizeArgs(OptimizeArgs),
-      EagerLoadModules(EagerLoadModules) {
+      EagerLoadModules(EagerLoadModules), TraceVFS(TraceVFS) {
   // Initialize targets for object file support.
   llvm::InitializeAllTargets();
   llvm::InitializeAllTargetMCs();
diff --git a/clang/lib/Tooling/DependencyScanning/DependencyScanningWorker.cpp b/clang/lib/Tooling/DependencyScanning/DependencyScanningWorker.cpp
@@ -501,6 +501,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));
+
   switch (Service.getMode()) {
   case ScanningMode::DependencyDirectivesScan:
     DepFS =
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
@@ -915,6 +915,13 @@ int clang_scan_deps_main(int argc, char **argv, const llvm::ToolContext &) {
   if (Format == ScanningOutputFormat::Full)
     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) {
     DependencyScanningTool WorkerTool(Service);
 
@@ -999,10 +1006,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, OptimizeArgs,
-                                    EagerLoadModules);
+                                    EagerLoadModules, /*TraceVFS=*/Verbose);
 
   llvm::Timer T;
   T.startTimer();
@@ -1025,6 +1043,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() << llvm::format(
         "clang-scan-deps timing: %0.2fs wall, %0.2fs process\n",
