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

[Adam Czachorowski via Phabricator via cfe-commits]

This revision was landed with ongoing or failed builds.
This revision was automatically updated to reflect the committed changes.
Closed by commit rG6009d0d5801d: [clangd] Track time spent in filesystem ops 
during preamble builds (authored by adamcz).

Repository:
  rG LLVM Github Monorepo

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

https://reviews.llvm.org/D121712

Files:
  clang-tools-extra/clangd/Preamble.cpp
  clang-tools-extra/clangd/Preamble.h
  clang-tools-extra/clangd/TUScheduler.cpp

Index: clang-tools-extra/clangd/TUScheduler.cpp
===
--- clang-tools-extra/clangd/TUScheduler.cpp
+++ clang-tools-extra/clangd/TUScheduler.cpp
@@ -98,6 +98,33 @@
 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 ,
+ 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
 
@@ -975,13 +1002,19 @@
 crashDumpParseInputs(llvm::errs(), Inputs);
   });
 
+  PreambleBuildStats Stats;
+  bool IsFirstPreamble = !LatestBuild;
   LatestBuild = clang::clangd::buildPreamble(
   FileName, *Req.CI, Inputs, StoreInMemory,
   [this, Version(Inputs.Version)](ASTContext , Preprocessor ,
   const CanonicalIncludes ) {
 Callbacks.onPreambleAST(FileName, Version, Ctx, PP, CanonIncludes);
-  });
-  if (LatestBuild && isReliable(LatestBuild->CompileCommand))
+  },
+  );
+  if (!LatestBuild)
+return;
+  reportPreambleBuild(Stats, IsFirstPreamble);
+  if (isReliable(LatestBuild->CompileCommand))
 HeaderIncluders.update(FileName, LatestBuild->Includes.allHeaders());
 }
 
Index: clang-tools-extra/clangd/Preamble.h
===
--- clang-tools-extra/clangd/Preamble.h
+++ clang-tools-extra/clangd/Preamble.h
@@ -75,13 +75,25 @@
 using PreambleParsedCallback = std::function;
 
+/// 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
 buildPreamble(PathRef FileName, CompilerInvocation CI,
   const ParseInputs , 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.
Index: clang-tools-extra/clangd/Preamble.cpp
===
--- clang-tools-extra/clangd/Preamble.cpp
+++ clang-tools-extra/clangd/Preamble.cpp
@@ -312,12 +312,98 @@
   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 

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

[Adam Czachorowski via Phabricator via cfe-commits]

adamcz updated this revision to Diff 417006.
adamcz marked an inline comment as done.
adamcz added a comment.

fix comments


Repository:
  rG LLVM Github Monorepo

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

https://reviews.llvm.org/D121712

Files:
  clang-tools-extra/clangd/Preamble.cpp
  clang-tools-extra/clangd/Preamble.h
  clang-tools-extra/clangd/TUScheduler.cpp

Index: clang-tools-extra/clangd/TUScheduler.cpp
===
--- clang-tools-extra/clangd/TUScheduler.cpp
+++ clang-tools-extra/clangd/TUScheduler.cpp
@@ -98,6 +98,33 @@
 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 ,
+ 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
 
@@ -975,13 +1002,19 @@
 crashDumpParseInputs(llvm::errs(), Inputs);
   });
 
+  PreambleBuildStats Stats;
+  bool IsFirstPreamble = !LatestBuild;
   LatestBuild = clang::clangd::buildPreamble(
   FileName, *Req.CI, Inputs, StoreInMemory,
   [this, Version(Inputs.Version)](ASTContext , Preprocessor ,
   const CanonicalIncludes ) {
 Callbacks.onPreambleAST(FileName, Version, Ctx, PP, CanonIncludes);
-  });
-  if (LatestBuild && isReliable(LatestBuild->CompileCommand))
+  },
+  );
+  if (!LatestBuild)
+return;
+  reportPreambleBuild(Stats, IsFirstPreamble);
+  if (isReliable(LatestBuild->CompileCommand))
 HeaderIncluders.update(FileName, LatestBuild->Includes.allHeaders());
 }
 
Index: clang-tools-extra/clangd/Preamble.h
===
--- clang-tools-extra/clangd/Preamble.h
+++ clang-tools-extra/clangd/Preamble.h
@@ -75,13 +75,25 @@
 using PreambleParsedCallback = std::function;
 
+/// 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
 buildPreamble(PathRef FileName, CompilerInvocation CI,
   const ParseInputs , 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.
Index: clang-tools-extra/clangd/Preamble.cpp
===
--- clang-tools-extra/clangd/Preamble.cpp
+++ clang-tools-extra/clangd/Preamble.cpp
@@ -312,12 +312,98 @@
   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;
+  }
+  // 

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

[Kadir Cetinkaya via Phabricator via cfe-commits]

kadircet accepted this revision.
kadircet added a comment.
This revision is now accepted and ready to land.

thanks, lgtm! sorry for the long round trip.




Comment at: clang-tools-extra/clangd/Preamble.cpp:315
 
+/// Accumulating wall time timer. Similar to llvm::Timer, but much cheaper,
+/// it only tracks wall time.

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


Repository:
  rG LLVM Github Monorepo

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

https://reviews.llvm.org/D121712

___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

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

[Adam Czachorowski via Phabricator via cfe-commits]

adamcz added inline comments.



Comment at: clang-tools-extra/clangd/FS.h:91
+IntrusiveRefCntPtr
+getTimeTrackingFS(std::shared_ptr Timer,
+  IntrusiveRefCntPtr FS);

kadircet wrote:
> adamcz wrote:
> > 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.
> > 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.
> > 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.



Comment at: clang-tools-extra/clangd/Preamble.cpp:389
+  Stats != nullptr ? getTimeTrackingFS(FSTimer, StatCacheFS) : StatCacheFS;
+  FSTimer->stopTimer();
+

kadircet wrote:
> is this call intentional ?
Oops, no, it's not.




Comment at: clang-tools-extra/clangd/Preamble.h:95
   const ParseInputs , bool StoreInMemory,
+  PreambleBuildStats *Stats,
   PreambleParsedCallback PreambleCallback);

kadircet wrote:
> adamcz wrote:
> > 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?
> 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?
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.



Comment at: clang-tools-extra/clangd/TUScheduler.cpp:1008
+  PreambleBuildStats Stats;
+  const bool IsFirstPreamble = !LatestBuild;
   LatestBuild = clang::clangd::buildPreamble(

kadircet wrote:
> adamcz wrote:
> > 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.
> > 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 

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

[Adam Czachorowski via Phabricator via cfe-commits]

adamcz updated this revision to Diff 416964.
adamcz marked 3 inline comments as done.
adamcz added a comment.

more review comments


Repository:
  rG LLVM Github Monorepo

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

https://reviews.llvm.org/D121712

Files:
  clang-tools-extra/clangd/Preamble.cpp
  clang-tools-extra/clangd/Preamble.h
  clang-tools-extra/clangd/TUScheduler.cpp

Index: clang-tools-extra/clangd/TUScheduler.cpp
===
--- clang-tools-extra/clangd/TUScheduler.cpp
+++ clang-tools-extra/clangd/TUScheduler.cpp
@@ -98,6 +98,33 @@
 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 ,
+ 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
 
@@ -975,13 +1002,19 @@
 crashDumpParseInputs(llvm::errs(), Inputs);
   });
 
+  PreambleBuildStats Stats;
+  bool IsFirstPreamble = !LatestBuild;
   LatestBuild = clang::clangd::buildPreamble(
   FileName, *Req.CI, Inputs, StoreInMemory,
   [this, Version(Inputs.Version)](ASTContext , Preprocessor ,
   const CanonicalIncludes ) {
 Callbacks.onPreambleAST(FileName, Version, Ctx, PP, CanonIncludes);
-  });
-  if (LatestBuild && isReliable(LatestBuild->CompileCommand))
+  },
+  );
+  if (!LatestBuild)
+return;
+  reportPreambleBuild(Stats, IsFirstPreamble);
+  if (isReliable(LatestBuild->CompileCommand))
 HeaderIncluders.update(FileName, LatestBuild->Includes.allHeaders());
 }
 
Index: clang-tools-extra/clangd/Preamble.h
===
--- clang-tools-extra/clangd/Preamble.h
+++ clang-tools-extra/clangd/Preamble.h
@@ -75,13 +75,25 @@
 using PreambleParsedCallback = std::function;
 
+/// 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
 buildPreamble(PathRef FileName, CompilerInvocation CI,
   const ParseInputs , 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.
Index: clang-tools-extra/clangd/Preamble.cpp
===
--- clang-tools-extra/clangd/Preamble.cpp
+++ clang-tools-extra/clangd/Preamble.cpp
@@ -312,12 +312,98 @@
   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;
+ 

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

[Kadir Cetinkaya via Phabricator via cfe-commits]

kadircet added inline comments.



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.

adamcz wrote:
> 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.
> 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).



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.

adamcz wrote:
> 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?
SG.



Comment at: clang-tools-extra/clangd/FS.h:82
+  void stopTime();
+  // Return total time, in seconds.
+  double getTime();

adamcz wrote:
> 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?
it's mostly personal preference i suppose, it just feels reasoning about 
discrete durations are easier than doubles. feel free to leave as is.



Comment at: clang-tools-extra/clangd/FS.h:86
+private:
+  std::chrono::steady_clock::duration TotalTime;
+  std::chrono::steady_clock::time_point StartTime;

adamcz wrote:
> 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)
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 about`s i try to signal this :D)



Comment at: clang-tools-extra/clangd/FS.h:91
+IntrusiveRefCntPtr
+getTimeTrackingFS(std::shared_ptr Timer,
+  IntrusiveRefCntPtr FS);

adamcz wrote:
> 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.
> 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.



Comment at: clang-tools-extra/clangd/Preamble.cpp:389
+  Stats != nullptr ? getTimeTrackingFS(FSTimer, StatCacheFS) : StatCacheFS;
+  FSTimer->stopTimer();
+

is this call intentional ?



Comment at: clang-tools-extra/clangd/Preamble.cpp:385
   auto BuiltPreamble = PrecompiledPreamble::Build(
-  CI, ContentsBuffer.get(), 

[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 , @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
+getTimeTrackingFS(std::shared_ptr Timer,
+  IntrusiveRefCntPtr 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(), StoreInMemory, CapturedInfo);

kadircet wrote:
> it might be worth leaving 

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

[Adam Czachorowski via Phabricator via cfe-commits]

adamcz updated this revision to Diff 415919.
adamcz marked 12 inline comments as done.
adamcz added a comment.

addressed review comments


Repository:
  rG LLVM Github Monorepo

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

https://reviews.llvm.org/D121712

Files:
  clang-tools-extra/clangd/FS.cpp
  clang-tools-extra/clangd/FS.h
  clang-tools-extra/clangd/Preamble.cpp
  clang-tools-extra/clangd/Preamble.h
  clang-tools-extra/clangd/TUScheduler.cpp
  clang-tools-extra/clangd/tool/Check.cpp
  clang-tools-extra/clangd/unittests/CodeCompleteTests.cpp
  clang-tools-extra/clangd/unittests/FileIndexTests.cpp
  clang-tools-extra/clangd/unittests/ParsedASTTests.cpp
  clang-tools-extra/clangd/unittests/PreambleTests.cpp
  clang-tools-extra/clangd/unittests/TestTU.cpp

Index: clang-tools-extra/clangd/unittests/TestTU.cpp
===
--- clang-tools-extra/clangd/unittests/TestTU.cpp
+++ clang-tools-extra/clangd/unittests/TestTU.cpp
@@ -101,7 +101,8 @@
   auto ModuleCacheDeleter = llvm::make_scope_exit(
   std::bind(deleteModuleCache, CI->getHeaderSearchOpts().ModuleCachePath));
   return clang::clangd::buildPreamble(testPath(Filename), *CI, Inputs,
-  /*StoreInMemory=*/true, PreambleCallback);
+  /*StoreInMemory=*/true, /*Stats=*/nullptr,
+  PreambleCallback);
 }
 
 ParsedAST TestTU::build() const {
@@ -117,6 +118,7 @@
 
   auto Preamble = clang::clangd::buildPreamble(testPath(Filename), *CI, Inputs,
/*StoreInMemory=*/true,
+   /*Stats=*/nullptr,
/*PreambleCallback=*/nullptr);
   auto AST = ParsedAST::build(testPath(Filename), Inputs, std::move(CI),
   Diags.take(), Preamble);
Index: clang-tools-extra/clangd/unittests/PreambleTests.cpp
===
--- clang-tools-extra/clangd/unittests/PreambleTests.cpp
+++ clang-tools-extra/clangd/unittests/PreambleTests.cpp
@@ -172,8 +172,9 @@
   TU.AdditionalFiles["b.h"] = "";
   TU.AdditionalFiles["c.h"] = "";
   auto PI = TU.inputs(FS);
-  auto BaselinePreamble = buildPreamble(
-  TU.Filename, *buildCompilerInvocation(PI, Diags), PI, true, nullptr);
+  auto BaselinePreamble =
+  buildPreamble(TU.Filename, *buildCompilerInvocation(PI, Diags), PI, true,
+/*Stats=*/nullptr, nullptr);
   // We drop c.h from modified and add a new header. Since the latter is patched
   // we should only get a.h in preamble includes.
   TU.Code = R"cpp(
Index: clang-tools-extra/clangd/unittests/ParsedASTTests.cpp
===
--- clang-tools-extra/clangd/unittests/ParsedASTTests.cpp
+++ clang-tools-extra/clangd/unittests/ParsedASTTests.cpp
@@ -494,8 +494,8 @@
   MockFS FS;
   auto Inputs = TU.inputs(FS);
   auto CI = buildCompilerInvocation(Inputs, Diags);
-  auto EmptyPreamble =
-  buildPreamble(testPath("foo.cpp"), *CI, Inputs, true, nullptr);
+  auto EmptyPreamble = buildPreamble(testPath("foo.cpp"), *CI, Inputs, true,
+ /*Stats=*/nullptr, nullptr);
   ASSERT_TRUE(EmptyPreamble);
   EXPECT_THAT(EmptyPreamble->Includes.MainFileIncludes, IsEmpty());
 
@@ -537,8 +537,8 @@
   MockFS FS;
   auto Inputs = TU.inputs(FS);
   auto CI = buildCompilerInvocation(Inputs, Diags);
-  auto BaselinePreamble =
-  buildPreamble(testPath("foo.cpp"), *CI, Inputs, true, nullptr);
+  auto BaselinePreamble = buildPreamble(testPath("foo.cpp"), *CI, Inputs, true,
+/*Stats=*/nullptr, nullptr);
   ASSERT_TRUE(BaselinePreamble);
   EXPECT_THAT(BaselinePreamble->Includes.MainFileIncludes,
   ElementsAre(testing::Field(::Written, "")));
Index: clang-tools-extra/clangd/unittests/FileIndexTests.cpp
===
--- clang-tools-extra/clangd/unittests/FileIndexTests.cpp
+++ clang-tools-extra/clangd/unittests/FileIndexTests.cpp
@@ -307,6 +307,7 @@
   bool IndexUpdated = false;
   buildPreamble(FooCpp, *CI, PI,
 /*StoreInMemory=*/true,
+/*Stats=*/nullptr,
 [&](ASTContext , Preprocessor ,
 const CanonicalIncludes ) {
   EXPECT_FALSE(IndexUpdated)
Index: clang-tools-extra/clangd/unittests/CodeCompleteTests.cpp
===
--- clang-tools-extra/clangd/unittests/CodeCompleteTests.cpp
+++ clang-tools-extra/clangd/unittests/CodeCompleteTests.cpp
@@ -121,8 +121,9 @@
 ADD_FAILURE() << "Couldn't build CompilerInvocation";
 return {};
   }
-  auto Preamble = buildPreamble(testPath(TU.Filename), *CI, Inputs,
-/*InMemory=*/true, 

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

[Kadir Cetinkaya via Phabricator via cfe-commits]

kadircet added a comment.

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.




Comment at: clang-tools-extra/clangd/FS.cpp:128
+  TimerFile(std::shared_ptr Timer, std::unique_ptr InnerFile)
+  : Timer(Timer), InnerFile(std::move(InnerFile)) {}
+

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



Comment at: clang-tools-extra/clangd/FS.cpp:141
+  }
+  std::error_code close() override { return InnerFile->close(); }
+

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



Comment at: clang-tools-extra/clangd/FS.h:16
 #include "llvm/ADT/StringMap.h"
+#include "llvm/Support/Timer.h"
 #include "llvm/Support/VirtualFileSystem.h"

i don't think we need this one



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.

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



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:
> 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.



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.

maybe put a `FIXME:`



Comment at: clang-tools-extra/clangd/FS.h:78
+  WallTimer();
+  // [Re-]Start the timer.
+  void startTime();

nit: we use `///` for public comments.



Comment at: clang-tools-extra/clangd/FS.h:82
+  void stopTime();
+  // Return total time, in seconds.
+  double getTime();

what about returning an `int` with `ms` granularity ?



Comment at: clang-tools-extra/clangd/FS.h:86
+private:
+  std::chrono::steady_clock::duration TotalTime;
+  std::chrono::steady_clock::time_point StartTime;

what about just storing double/int ?



Comment at: clang-tools-extra/clangd/FS.h:91
+IntrusiveRefCntPtr
+getTimeTrackingFS(std::shared_ptr Timer,
+  IntrusiveRefCntPtr FS);

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.
```



Comment at: clang-tools-extra/clangd/FS.h:91
+IntrusiveRefCntPtr
+getTimeTrackingFS(std::shared_ptr Timer,
+  IntrusiveRefCntPtr FS);

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 ?



Comment at: clang-tools-extra/clangd/Preamble.cpp:379
   auto StatCache = std::make_unique(AbsFileName);
+  auto FSTimer = std::make_shared();
+  auto TimedFS = getTimeTrackingFS(FSTimer, StatCache->getProducingFS(VFS));

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



Comment at: clang-tools-extra/clangd/Preamble.cpp:382
+
+  llvm::Timer PreambleTimer;
+  PreambleTimer.startTimer();

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



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(), StoreInMemory, CapturedInfo);

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 

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

[Trass3r via Phabricator via cfe-commits]

Trass3r added a comment.

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.


Repository:
  rG LLVM Github Monorepo

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

https://reviews.llvm.org/D121712

___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

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

[Adam Czachorowski via Phabricator via cfe-commits]

adamcz created this revision.
adamcz added a reviewer: kadircet.
Herald added subscribers: usaxena95, arphaman, javed.absar.
Herald added a project: All.
adamcz requested review of this revision.
Herald added subscribers: cfe-commits, MaskRay, ilya-biryukov.
Herald added a project: clang-tools-extra.

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.


Repository:
  rG LLVM Github Monorepo

https://reviews.llvm.org/D121712

Files:
  clang-tools-extra/clangd/FS.cpp
  clang-tools-extra/clangd/FS.h
  clang-tools-extra/clangd/Preamble.cpp
  clang-tools-extra/clangd/Preamble.h
  clang-tools-extra/clangd/TUScheduler.cpp
  clang-tools-extra/clangd/tool/Check.cpp
  clang-tools-extra/clangd/unittests/CodeCompleteTests.cpp
  clang-tools-extra/clangd/unittests/FileIndexTests.cpp
  clang-tools-extra/clangd/unittests/ParsedASTTests.cpp
  clang-tools-extra/clangd/unittests/PreambleTests.cpp
  clang-tools-extra/clangd/unittests/TestTU.cpp

Index: clang-tools-extra/clangd/unittests/TestTU.cpp
===
--- clang-tools-extra/clangd/unittests/TestTU.cpp
+++ clang-tools-extra/clangd/unittests/TestTU.cpp
@@ -101,7 +101,8 @@
   auto ModuleCacheDeleter = llvm::make_scope_exit(
   std::bind(deleteModuleCache, CI->getHeaderSearchOpts().ModuleCachePath));
   return clang::clangd::buildPreamble(testPath(Filename), *CI, Inputs,
-  /*StoreInMemory=*/true, PreambleCallback);
+  /*StoreInMemory=*/true, /*Stats=*/nullptr,
+  PreambleCallback);
 }
 
 ParsedAST TestTU::build() const {
@@ -117,6 +118,7 @@
 
   auto Preamble = clang::clangd::buildPreamble(testPath(Filename), *CI, Inputs,
/*StoreInMemory=*/true,
+   /*Stats=*/nullptr,
/*PreambleCallback=*/nullptr);
   auto AST = ParsedAST::build(testPath(Filename), Inputs, std::move(CI),
   Diags.take(), Preamble);
Index: clang-tools-extra/clangd/unittests/PreambleTests.cpp
===
--- clang-tools-extra/clangd/unittests/PreambleTests.cpp
+++ clang-tools-extra/clangd/unittests/PreambleTests.cpp
@@ -172,8 +172,9 @@
   TU.AdditionalFiles["b.h"] = "";
   TU.AdditionalFiles["c.h"] = "";
   auto PI = TU.inputs(FS);
-  auto BaselinePreamble = buildPreamble(
-  TU.Filename, *buildCompilerInvocation(PI, Diags), PI, true, nullptr);
+  auto BaselinePreamble =
+  buildPreamble(TU.Filename, *buildCompilerInvocation(PI, Diags), PI, true,
+/*Stats=*/nullptr, nullptr);
   // We drop c.h from modified and add a new header. Since the latter is patched
   // we should only get a.h in preamble includes.
   TU.Code = R"cpp(
Index: clang-tools-extra/clangd/unittests/ParsedASTTests.cpp
===
--- clang-tools-extra/clangd/unittests/ParsedASTTests.cpp
+++ clang-tools-extra/clangd/unittests/ParsedASTTests.cpp
@@ -494,8 +494,8 @@
   MockFS FS;
   auto Inputs = TU.inputs(FS);
   auto CI = buildCompilerInvocation(Inputs, Diags);
-  auto EmptyPreamble =
-  buildPreamble(testPath("foo.cpp"), *CI, Inputs, true, nullptr);
+  auto EmptyPreamble = buildPreamble(testPath("foo.cpp"), *CI, Inputs, true,
+ /*Stats=*/nullptr, nullptr);
   ASSERT_TRUE(EmptyPreamble);
   EXPECT_THAT(EmptyPreamble->Includes.MainFileIncludes, IsEmpty());
 
@@ -537,8 +537,8 @@
   MockFS FS;
   auto Inputs = TU.inputs(FS);
   auto CI = buildCompilerInvocation(Inputs, Diags);
-  auto BaselinePreamble =
-  buildPreamble(testPath("foo.cpp"), *CI, Inputs, true, nullptr);
+  auto BaselinePreamble = buildPreamble(testPath("foo.cpp"), *CI, Inputs, true,
+/*Stats=*/nullptr, nullptr);
   ASSERT_TRUE(BaselinePreamble);
   EXPECT_THAT(BaselinePreamble->Includes.MainFileIncludes,
   ElementsAre(testing::Field(::Written, "")));
Index: clang-tools-extra/clangd/unittests/FileIndexTests.cpp
===
--- clang-tools-extra/clangd/unittests/FileIndexTests.cpp
+++ clang-tools-extra/clangd/unittests/FileIndexTests.cpp
@@ -307,6 +307,7 @@
   bool IndexUpdated = false;
   buildPreamble(FooCpp, *CI, PI,
 /*StoreInMemory=*/true,
+/*Stats=*/nullptr,
 [&](ASTContext , Preprocessor ,
 const CanonicalIncludes ) {
   EXPECT_FALSE(IndexUpdated)
Index: clang-tools-extra/clangd/unittests/CodeCompleteTests.cpp