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

[Adam Czachorowski via Phabricator via cfe-commits]

adamcz added a comment.

In D121712#3383944 <https://reviews.llvm.org/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?



================
Comment at: clang-tools-extra/clangd/FS.h:71
 
+/// Used for tracking time spent in FS operations. Like llvm::Timer, but only
+/// tracks wall time, which is much cheaper.
----------------
kadircet wrote:
> kadircet wrote:
> > I don't think mentioning `FS` here is worth it. Can we rather emphasize on this being an accumulating timer?
> 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.
Before I make the change, let me clarify: are you suggesting moving the whole TimedFS into Preamble.cpp?

Definitely possible.


================
Comment at: clang-tools-extra/clangd/FS.h:73
+/// tracks wall time, which is much cheaper.
+/// 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.
----------------
kadircet wrote:
> maybe put a `FIXME:`
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?


================
Comment at: clang-tools-extra/clangd/FS.h:82
+  void stopTime();
+  // Return total time, in seconds.
+  double getTime();
----------------
kadircet wrote:
> what about returning an `int` with `ms` granularity ?
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?


================
Comment at: clang-tools-extra/clangd/FS.h:86
+private:
+  std::chrono::steady_clock::duration TotalTime;
+  std::chrono::steady_clock::time_point StartTime;
----------------
kadircet wrote:
> what about just storing double/int ?
Again, why?

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


================
Comment at: clang-tools-extra/clangd/FS.h:91
+IntrusiveRefCntPtr<llvm::vfs::FileSystem>
+getTimeTrackingFS(std::shared_ptr<WallTimer> Timer,
+                  IntrusiveRefCntPtr<llvm::vfs::FileSystem> FS);
----------------
kadircet wrote:
> kadircet wrote:
> > 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.
> > ```
> 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 ?
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.


================
Comment at: clang-tools-extra/clangd/Preamble.cpp:385
   auto BuiltPreamble = PrecompiledPreamble::Build(
-      CI, ContentsBuffer.get(), Bounds, *PreambleDiagsEngine,
-      StatCache->getProducingFS(VFS),
+      CI, ContentsBuffer.get(), Bounds, *PreambleDiagsEngine, TimedFS,
       std::make_shared<PCHContainerOperations>(), StoreInMemory, CapturedInfo);
----------------
kadircet wrote:
> 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.
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.


================
Comment at: clang-tools-extra/clangd/Preamble.h:95
               const ParseInputs &Inputs, bool StoreInMemory,
+              PreambleBuildStats *Stats,
               PreambleParsedCallback PreambleCallback);
----------------
kadircet wrote:
> nit: maybe make this the last parameter and default to `nullptr` to get rid of changes in tests.
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?


================
Comment at: clang-tools-extra/clangd/TUScheduler.cpp:100
 
+// 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
----------------
kadircet wrote:
> can we move all of these into an anonymous namespace instead?
Done. I moved them into anonymous namespace, but I'm not sure what you mean by "instead"?


================
Comment at: clang-tools-extra/clangd/TUScheduler.cpp:109
+// preamble build time. build_type is same as above.
+constexpr trace::Metric PreambleBuildFilesystemLatencyRatio(
+    "preamble_fs_latency_ratio", trace::Metric::Distribution, "build_type");
----------------
kadircet wrote:
> what about just tracking the total build time here? we can get the ratio afterwards.
How would you get the ratio then?


================
Comment at: clang-tools-extra/clangd/TUScheduler.cpp:113
+static void reportPreambleBuild(const PreambleBuildStats &Stats,
+                                const bool IsFirstPreamble) {
+  // The first preamble we build in a clangd instance gets a different metric
----------------
kadircet wrote:
> nit: llvm style doesn't really use `const` if the parameter is being copied anyway
Right, and I'll never get used to that. Sorry ;-)


================
Comment at: clang-tools-extra/clangd/TUScheduler.cpp:121
+                  : (IsFirstPreamble ? "first_build_for_file" : "rebuild");
+  FirstReport = false;
+
----------------
kadircet wrote:
> 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);
> ```
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.


================
Comment at: clang-tools-extra/clangd/TUScheduler.cpp:1008
+  PreambleBuildStats Stats;
+  const bool IsFirstPreamble = !LatestBuild;
   LatestBuild = clang::clangd::buildPreamble(
----------------
kadircet wrote:
> nit: drop the const per style.
Hmm...is that actually documented somewhere? There's definitely many cases of "const bool" in LLVM codebase. I think the "const" improves readability.


Repository:
  rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D121712/new/

https://reviews.llvm.org/D121712