[clangd] Track time spent in filesystem ops during preamble builds

[adamcz]

Summary

In some deployments, for example when running on FUSE or using some
network-based VFS implementation, the filesystem operations might add up
to a significant fraction of preamble build time. This change allows us
to track time spent in FS operations to better understand the problem.

[Trass3r]

Hmm just a few curious questions from the sidelines.
Why a "custom system" instead of something -ftime-trace based?
How much overhead does this introduce, esp. for normal use-cases?
What's the gain? The information is very coarse and general-purpose system profiling tools should give you much better information regarding file system perf.

[kadircet]

Thanks, LG in general. I suppose the extra timing overhead should be negligible, considering the preamble build times but would be nice to see some numbers if you have any.
Apart from that I've raised the concern around multiple preamble builds finishing in parallel and poisoning the first_build metric, wanted to raise it here again to make sure it isn't lost in details.

clang-tools-extra/clangd/FS.cpp

128 ↗

(On Diff #415467)

nit: Timer(std::move(Timer))

141 ↗

(On Diff #415467)

i guess this is negligible but, timing close operations too shouldn't hurt?

clang-tools-extra/clangd/FS.h

16 ↗

(On Diff #415467)

i don't think we need this one

71 ↗

(On Diff #415467)

I don't think mentioning FS here is worth it. Can we rather emphasize on this being an accumulating timer?

71 ↗

(On Diff #415467)

what about making all of this an implementation detail of Preamble.cpp ? we can lift it up once we have other places that we want to make use of.

73 ↗

(On Diff #415467)

maybe put a FIXME:

78 ↗

(On Diff #415467)

nit: we use /// for public comments.

82 ↗

(On Diff #415467)

what about returning an int with ms granularity ?

86 ↗

(On Diff #415467)

what about just storing double/int ?

91 ↗

(On Diff #415467)

i feel like this deserves the FS specific comment mentioned above. maybe something like:

This will record all time spent on IO operations in \p Timer.

91 ↗

(On Diff #415467)

i don't think we ever want concurrent access to Timer, i.e. startTime should never be called without a matching call to stopTime first. passing it in as a shared_ptr somehow gives the feeling that it might be shared across multiple objects, which might do whatever they want with the object.
maybe just pass in a reference ?

clang-tools-extra/clangd/Preamble.cpp

464

what about only conditionally doing these when Stats is not null?

467

why use an expensive llvm::Timer if all we care is walltime?

470–471

it might be worth leaving some comments around this TimedFS being exposed to outside through PreambleCallbacks. We provide access to Preprocessor, which keeps the underlying FileManager alive.
Today all of this happens in serial hence all is fine, but we were discussing the possibility of performing the indexing and preamble serialization in parallel, it might result in some surprising race conditions if we do that.

clang-tools-extra/clangd/Preamble.h

82

nit: again /// (i see that fields of PreambleData doesn't follow the style here, but it's the outlier)

95

nit: maybe make this the last parameter and default to nullptr to get rid of changes in tests.

clang-tools-extra/clangd/TUScheduler.cpp

100

can we move all of these into an anonymous namespace instead?

109

what about just tracking the total build time here? we can get the ratio afterwards.

113

nit: llvm style doesn't really use const if the parameter is being copied anyway

121

this can still be called in parallel as we have multiple preamble threads. moreover this also makes "first_build" tracking somewhat tricky. do you think this metric would still be useful in the presence of such noise? e.g. a respawning clangd instance might receive addDocument requests for all the previously open files and the first preamble to build might've benefited a lot from cached file IO that was done by other preamble builds.

i suppose we can have something like following to at least address multiple preamble threads accessing FirstReport issue.

static bool ReportedFirstBuild = [&]{
  PreambleBuildFilesystemLatency.record(Stats.FileSystemTime, "first_build"); // I think it's fine to report twice here, as we've both performed a first build for a file, and it was the first build of clangd instance.
  return true;
}();
llvm::StringLiteral Label = IsFirstPreamble ? "first_build_for_file" : "rebuild";
PreambleBuildFilesystemLatency.record(Stats.FileSystemTime, Label);
if (Stats.TotalBuildTime > 0) // Avoid division by zero.
    PreambleBuildFilesystemLatencyRatio.record(
        Stats.FileSystemTime / Stats.TotalBuildTime, Label);

1006

nit: drop the const per style.

1012–1017

nit:

if(!LatestBuild)
  return;
reportPreambleBuild(Stats, IsFirstPreamble);
if(isReliable(LatestBuild->CompileCommand))
  HeaderIncluders.update(FileName, LatestBuild->Includes.allHeaders());

[adamcz]

addressed review comments

[adamcz]

In D121712#3383944, @Trass3r wrote:

Hmm just a few curious questions from the sidelines.
Why a "custom system" instead of something -ftime-trace based?

I'm not sure if I understand. -ftime-trace is a one-off. I want to monitor these values across multiple clangd instances, over time.

How much overhead does this introduce, esp. for normal use-cases?

On my machine it takes about 3.5 milliseconds to do 100k startTimer(); stopTimer(); calls in a loop. Building preamble for SemaOverload.cpp (random file I checked) takes about ~2200 such calls. Basically the impact of this should not be noticeable.

What's the gain? The information is very coarse and general-purpose system profiling tools should give you much better information regarding file system perf.

The idea is to use this to monitor large deployments of clangd on many machines over long period of time. One question to answer is whether some sort of prefetching of header files (with parallel I/O) would be beneficial. That depends on what fraction of the time we spend waiting on the serial file reads and how warm the caches are, on average.
It will also help us catch regressions, like one we had recently (that went unnoticed for quite a while) where adding some -fmodule-map-file flags to do a layering check caused a lot of stat() calls, which can be quite expensive.

Does that make sense? Does it answer your questions?

clang-tools-extra/clangd/FS.h

71 ↗

(On Diff #415467)

Before I make the change, let me clarify: are you suggesting moving the whole TimedFS into Preamble.cpp?

Definitely possible.

73 ↗

(On Diff #415467)

IMHO FIXME should be actionable. This is not - we shouldn't do it unless something changes. It's just a note that if someone ever wonders "could I just move this to support/ and re-use it", the answer is yes.

Does that make sense?

82 ↗

(On Diff #415467)

We could, but why? llvm::Timer returns WallTime as double so this is somewhat consistent with it. Not a strong argument, of course, since that consistency doesn't really matter, but I'm not sure what benefit using int here offers?

86 ↗

(On Diff #415467)

Again, why?

(I'm not strictly against it, just trying to understand why you're asking for this)

91 ↗

(On Diff #415467)

It's not about concurrency, it's about live time. This timer needs to have the same lifetime as the entire VFS, which is also ref-counted.

Alternative would be for the TimerFS to own this timer and expose it's own getTime() method. That means TimerFS must now be visible outside of FS.cpp, but if we're moving it to Preamble.cpp per your other comment that's fine.

clang-tools-extra/clangd/Preamble.cpp

470–471

Hmm...I added a comment, but nothing really changes here, right? VFS in general is not thread safe, so if we add parallelism we need to either make sure no file access happens there or make all VFSs used here thread safe.

clang-tools-extra/clangd/Preamble.h

95

I'd rather not, unless you insist. Besides not having to modify tests (which I already did anyway), what's the benefit of having it be default? Do you think it's more readable?

clang-tools-extra/clangd/TUScheduler.cpp

100

Done. I moved them into anonymous namespace, but I'm not sure what you mean by "instead"?

109

How would you get the ratio then?

113

Right, and I'll never get used to that. Sorry ;-)

121

That's an excellent point. Fixed.

I do believe that this extra information is worth it, even if it's noisy. If the fact that we're building multiple TUs in parallel and thus, essentially, have parallel file reading, significantly improves this metric then perhaps lack of parallel reads is not such a big deal after all.

1006

Hmm...is that actually documented somewhere? There's definitely many cases of "const bool" in LLVM codebase. I think the "const" improves readability.

[kadircet]

clang-tools-extra/clangd/FS.h

71 ↗

(On Diff #415467)

Before I make the change, let me clarify: are you suggesting moving the whole TimedFS into Preamble.cpp?

Yes, exactly. as neither the FS nor the walltimer is needed by anything else (and we probably want to be more cautious when we want to make use of them in other components).

73 ↗

(On Diff #415467)

SG.

82 ↗

(On Diff #415467)

it's mostly personal preference i suppose, it just feels reasoning about discrete durations are easier than doubles. feel free to leave as is.

86 ↗

(On Diff #415467)

it just feels easier to reason about builtin types, than a template alias like std::chrono::steady_clock::duration, at least on the interface level. but again, probably just a personal preference that I don't feel strongly about, so feel free to ignore. (usually with what abouts i try to signal this :D)

91 ↗

(On Diff #415467)

It's not about concurrency, it's about live time. This timer needs to have the same lifetime as the entire VFS, which is also ref-counted.

Right, I've noticed that as I was going through the rest of the review, but forgot to delete these as it was split into two days. sorry for the churn.

Alternative would be for the TimerFS to own this timer and expose it's own getTime() method. That means TimerFS must now be visible outside of FS.cpp, but if we're moving it to Preamble.cpp per your other comment that's fine.

yes, i think that would be a nice simplification.

clang-tools-extra/clangd/Preamble.cpp

470–471

right. in theory we have that more loudly spelled out by having a ThreadSafeFS, but as you pointed out that wouldn't be the only thing to consider when such a shift happens.

474

is this call intentional ?

clang-tools-extra/clangd/Preamble.h

95

right, i think it's more readable, and moreover it will reduce the need for typing that parameter more times in the future (mostly in tests again).
at the very least, what's the reason for not inserting it at the last position but rather before PreambleCallback?

clang-tools-extra/clangd/TUScheduler.cpp

100

instead of having static in front of the void reportPreambleBuild :D (sorry the comment was definitely misplaced).

109

we could just divide the distributions point by point. it isn't as accurate since we won't have the exact association, but something we've been doing in the past.
but no matter what, i forgot that we actually track the total build time through the span in buildPreamble so nvm. no need to give up the accuracy here.

113

we can drop the static now.

115

doesn't this need to be at least static ?

1006

is that actually documented somewhere

nothing that I can find either.

There's definitely many cases of "const bool" in LLVM codebase. I think the "const" improves readability.

yes, but I think the majority is still not having "const" in front of bool. it's at least the convention in clangd.
I also agree that the const improves readability, but for a local variable it carries much less importance and being consistent with the majority of the cases here is a lot more important.
because seeing occurrences of both locals with const and non-const will eventually make the reasoning hard and each case surprising.

if you think there's enough value to having consts for locals for readability, i think we should figure out a way to make the codebase (at least the clangd part) consistent with consts first.

[adamcz]

more review comments

clang-tools-extra/clangd/FS.h

91 ↗

(On Diff #415467)

It's not about concurrency, it's about live time. This timer needs to have the same lifetime as the entire VFS, which is also ref-counted.

Right, I've noticed that as I was going through the rest of the review, but forgot to delete these as it was split into two days. sorry for the churn.

Alternative would be for the TimerFS to own this timer and expose it's own getTime() method. That means TimerFS must now be visible outside of FS.cpp, but if we're moving it to Preamble.cpp per your other comment that's fine.

yes, i think that would be a nice simplification.

Done.

clang-tools-extra/clangd/Preamble.cpp

474

Oops, no, it's not.

clang-tools-extra/clangd/Preamble.h

95

OK, I made it default to nullptr.

The logic behind it not being last was that it's usual (though not a hard rule) for callbacks to be the last argument, probably to make passing lambdas look nicer. Not really important.

clang-tools-extra/clangd/TUScheduler.cpp

1006

OK, I'll drop const for now then.

[kadircet]

thanks, lgtm! sorry for the long round trip.

clang-tools-extra/clangd/Preamble.cpp

315

nit: double slashes instead of triple now (as it's no longer public interface), sorry :(
same for members

[adamcz]

fix comments

clang-tools-extra/clangd/Preamble.h

struct PreambleData {
   // Whether there was a (possibly-incomplete) include-guard on the main file.
   // We need to propagate this information "by hand" to subsequent parses.
   bool MainIsIncludeGuarded = false;
 };
 
 using PreambleParsedCallback = std::function<void(ASTContext &, Preprocessor &,
                                                   const CanonicalIncludes &)>;
 
+/// Timings and statistics from the premble build. Unlike PreambleData, these
+/// do not need to be stored for later, but can be useful for logging, metrics,
+/// etc.
+struct PreambleBuildStats {
+  /// Total wall time it took to build preamble, in seconds.
+  double TotalBuildTime;
+  /// Time spent in filesystem operations during the build, in seconds.
+  double FileSystemTime;
+};
+
 /// Build a preamble for the new inputs unless an old one can be reused.
 /// If \p PreambleCallback is set, it will be run on top of the AST while
 /// building the preamble.
+/// If Stats is not non-null, build statistics will be exported there.
 std::shared_ptr<const PreambleData>
 buildPreamble(PathRef FileName, CompilerInvocation CI,
               const ParseInputs &Inputs, bool StoreInMemory,
-              PreambleParsedCallback PreambleCallback);
+              PreambleParsedCallback PreambleCallback,
+              PreambleBuildStats *Stats = nullptr);
 
 /// Returns true if \p Preamble is reusable for \p Inputs. Note that it will
 /// return true when some missing headers are now available.
 /// FIXME: Should return more information about the delta between \p Preamble
 /// and \p Inputs, e.g. new headers.
 bool isPreambleCompatible(const PreambleData &Preamble,
                           const ParseInputs &Inputs, PathRef FileName,
                           const CompilerInvocation &CI);

clang-tools-extra/clangd/Preamble.cpp

 }
 
 // Checks whether \p FileName is a valid spelling of main file.
 bool isMainFile(llvm::StringRef FileName, const SourceManager &SM) {
   auto FE = SM.getFileManager().getFile(FileName);
   return FE && *FE == SM.getFileEntryForID(SM.getMainFileID());
 }
 
+// Accumulating wall time timer. Similar to llvm::Timer, but much cheaper,
+// it only tracks wall time.
+// Since this is a generic timer, We may want to move this to support/ if we
+// find a use case outside of FS time tracking.
+class WallTimer {
+public:
+  WallTimer() : TotalTime(std::chrono::steady_clock::duration::zero()) {}
+  // [Re-]Start the timer.
+  void startTimer() { StartTime = std::chrono::steady_clock::now(); }
+  // Stop the timer and update total time.
+  void stopTimer() {
+    TotalTime += std::chrono::steady_clock::now() - StartTime;
+  }
+  // Return total time, in seconds.
+  double getTime() { return std::chrono::duration<double>(TotalTime).count(); }
+
+private:
+  std::chrono::steady_clock::duration TotalTime;
+  std::chrono::steady_clock::time_point StartTime;
+};
+
+class WallTimerRegion {
+public:
+  WallTimerRegion(WallTimer &T) : T(T) { T.startTimer(); }
+  ~WallTimerRegion() { T.stopTimer(); }
+
+private:
+  WallTimer &T;
+};
+
+// Used by TimerFS, tracks time spent in status() and getBuffer() calls while
+// proxying to underlying File implementation.
+class TimerFile : public llvm::vfs::File {
+public:
+  TimerFile(WallTimer &Timer, std::unique_ptr<File> InnerFile)
+      : Timer(Timer), InnerFile(std::move(InnerFile)) {}
+
+  llvm::ErrorOr<llvm::vfs::Status> status() override {
+    WallTimerRegion T(Timer);
+    return InnerFile->status();
+  }
+  llvm::ErrorOr<std::unique_ptr<llvm::MemoryBuffer>>
+  getBuffer(const Twine &Name, int64_t FileSize, bool RequiresNullTerminator,
+            bool IsVolatile) override {
+    WallTimerRegion T(Timer);
+    return InnerFile->getBuffer(Name, FileSize, RequiresNullTerminator,
+                                IsVolatile);
+  }
+  std::error_code close() override {
+    WallTimerRegion T(Timer);
+    return InnerFile->close();
+  }
+
+private:
+  WallTimer &Timer;
+  std::unique_ptr<llvm::vfs::File> InnerFile;
+};
+
+// A wrapper for FileSystems that tracks the amount of time spent in status()
+// and openFileForRead() calls.
+class TimerFS : public llvm::vfs::ProxyFileSystem {
+public:
+  TimerFS(llvm::IntrusiveRefCntPtr<llvm::vfs::FileSystem> FS)
+      : ProxyFileSystem(std::move(FS)) {}
+
+  llvm::ErrorOr<std::unique_ptr<llvm::vfs::File>>
+  openFileForRead(const llvm::Twine &Path) override {
+    WallTimerRegion T(Timer);
+    auto FileOr = getUnderlyingFS().openFileForRead(Path);
+    if (!FileOr)
+      return FileOr;
+    return std::make_unique<TimerFile>(Timer, std::move(FileOr.get()));
+  }
+
+  llvm::ErrorOr<llvm::vfs::Status> status(const llvm::Twine &Path) override {
+    WallTimerRegion T(Timer);
+    return getUnderlyingFS().status(Path);
+  }
+
+  double getTime() { return Timer.getTime(); }
+
+private:
+  WallTimer Timer;
+};
+
 } // namespace
 
 std::shared_ptr<const PreambleData>
 buildPreamble(PathRef FileName, CompilerInvocation CI,
               const ParseInputs &Inputs, bool StoreInMemory,
-              PreambleParsedCallback PreambleCallback) {
+              PreambleParsedCallback PreambleCallback,
+              PreambleBuildStats *Stats) {
   // Note that we don't need to copy the input contents, preamble can live
   // without those.
   auto ContentsBuffer =
       llvm::MemoryBuffer::getMemBuffer(Inputs.Contents, FileName);
   auto Bounds = ComputePreambleBounds(*CI.getLangOpts(), *ContentsBuffer, 0);
 
   trace::Span Tracer("BuildPreamble");
   SPAN_ATTACH(Tracer, "File", FileName);
buildPreamble(PathRef FileName, CompilerInvocation CI,
   // to read back. We rely on dynamic index for the comments instead.
   CI.getPreprocessorOpts().WriteCommentListToPCH = false;
 
   CppFilePreambleCallbacks CapturedInfo(FileName, PreambleCallback);
   auto VFS = Inputs.TFS->view(Inputs.CompileCommand.Directory);
   llvm::SmallString<32> AbsFileName(FileName);
   VFS->makeAbsolute(AbsFileName);
   auto StatCache = std::make_unique<PreambleFileStatusCache>(AbsFileName);
+  auto StatCacheFS = StatCache->getProducingFS(VFS);
+  llvm::IntrusiveRefCntPtr<TimerFS> TimedFS(new TimerFS(StatCacheFS));
+
+  WallTimer PreambleTimer;
+  PreambleTimer.startTimer();
   auto BuiltPreamble = PrecompiledPreamble::Build(
       CI, ContentsBuffer.get(), Bounds, *PreambleDiagsEngine,
-      StatCache->getProducingFS(VFS),
-      std::make_shared<PCHContainerOperations>(), StoreInMemory, CapturedInfo);
+      Stats ? TimedFS : StatCacheFS, std::make_shared<PCHContainerOperations>(),
+      StoreInMemory, CapturedInfo);
+  PreambleTimer.stopTimer();
 
   // When building the AST for the main file, we do want the function
   // bodies.
   CI.getFrontendOpts().SkipFunctionBodies = false;
 
   if (BuiltPreamble) {
-    vlog("Built preamble of size {0} for file {1} version {2}",
-         BuiltPreamble->getSize(), FileName, Inputs.Version);
+    vlog("Built preamble of size {0} for file {1} version {2} in {3} seconds",
+         BuiltPreamble->getSize(), FileName, Inputs.Version,
+         PreambleTimer.getTime());
     std::vector<Diag> Diags = PreambleDiagnostics.take();
     auto Result = std::make_shared<PreambleData>(std::move(*BuiltPreamble));
     Result->Version = Inputs.Version;
     Result->CompileCommand = Inputs.CompileCommand;
     Result->Diags = std::move(Diags);
     Result->Includes = CapturedInfo.takeIncludes();
     Result->Macros = CapturedInfo.takeMacros();
     Result->Marks = CapturedInfo.takeMarks();
     Result->CanonIncludes = CapturedInfo.takeCanonicalIncludes();
     Result->StatCache = std::move(StatCache);
     Result->MainIsIncludeGuarded = CapturedInfo.isMainFileIncludeGuarded();
+    if (Stats != nullptr) {
+      Stats->TotalBuildTime = PreambleTimer.getTime();
+      Stats->FileSystemTime = TimedFS->getTime();
+    }
     return Result;
   }
 
   elog("Could not build a preamble for file {0} version {1}: {2}", FileName,
        Inputs.Version, BuiltPreamble.getError().message());
   return nullptr;
 }
 

clang-tools-extra/clangd/TUScheduler.cpp

 #include <type_traits>
 #include <utility>
 #include <vector>
 
 namespace clang {
 namespace clangd {
 using std::chrono::steady_clock;
 
 namespace {
+// Tracks latency (in seconds) of FS operations done during a preamble build.
+// build_type allows to split by expected VFS cache state (cold on first
+// preamble, somewhat warm after that when building first preamble for new file,
+// likely ~everything cached on preamble rebuild.
+constexpr trace::Metric
+    PreambleBuildFilesystemLatency("preamble_fs_latency",
+                                   trace::Metric::Distribution, "build_type");
+// Tracks latency of FS operations done during a preamble build as a ratio of
+// preamble build time. build_type is same as above.
+constexpr trace::Metric PreambleBuildFilesystemLatencyRatio(
+    "preamble_fs_latency_ratio", trace::Metric::Distribution, "build_type");
+
+void reportPreambleBuild(const PreambleBuildStats &Stats,
+                         bool IsFirstPreamble) {
+  static llvm::once_flag OnceFlag;
+  llvm::call_once(OnceFlag, [&] {
+    PreambleBuildFilesystemLatency.record(Stats.FileSystemTime, "first_build");
+  });
+
+  const std::string Label =
+      IsFirstPreamble ? "first_build_for_file" : "rebuild";
+  PreambleBuildFilesystemLatency.record(Stats.FileSystemTime, Label);
+  if (Stats.TotalBuildTime > 0) // Avoid division by zero.
+    PreambleBuildFilesystemLatencyRatio.record(
+        Stats.FileSystemTime / Stats.TotalBuildTime, Label);
+}
+
 class ASTWorker;
 } // namespace
 
 static clang::clangd::Key<std::string> FileBeingProcessed;
 
 llvm::Optional<llvm::StringRef> TUScheduler::getFileBeingProcessedInContext() {
   if (auto *File = Context::current().get(FileBeingProcessed))
     return llvm::StringRef(*File);
vlog("Rebuilding invalidated preamble for {0} version {1} (previous was "
          FileName, Inputs.Version, LatestBuild->Version);
   }
 
   ThreadCrashReporter ScopedReporter([&Inputs]() {
     llvm::errs() << "Signalled while building preamble\n";
     crashDumpParseInputs(llvm::errs(), Inputs);
   });
 
+  PreambleBuildStats Stats;
+  bool IsFirstPreamble = !LatestBuild;
   LatestBuild = clang::clangd::buildPreamble(
       FileName, *Req.CI, Inputs, StoreInMemory,
       [this, Version(Inputs.Version)](ASTContext &Ctx, Preprocessor &PP,
                                       const CanonicalIncludes &CanonIncludes) {
         Callbacks.onPreambleAST(FileName, Version, Ctx, PP, CanonIncludes);
-      });
-  if (LatestBuild && isReliable(LatestBuild->CompileCommand))
+      },
+      &Stats);
+  if (!LatestBuild)
+    return;
+  reportPreambleBuild(Stats, IsFirstPreamble);
+  if (isReliable(LatestBuild->CompileCommand))
     HeaderIncluders.update(FileName, LatestBuild->Includes.allHeaders());
 }
 
 void ASTWorker::updatePreamble(std::unique_ptr<CompilerInvocation> CI,
                                ParseInputs PI,
                                std::shared_ptr<const PreambleData> Preamble,
                                std::vector<Diag> CIDiags,
                                WantDiagnostics WantDiags) {