[clang-tools-extra] 6009d0d - [clangd] Track time spent in filesystem ops during preamble builds
Adam Czachorowski via cfe-commits
cfe-commits at lists.llvm.org
Mon Mar 21 10:34:08 PDT 2022
Author: Adam Czachorowski
Date: 2022-03-21T18:33:01+01:00
New Revision: 6009d0d5801d8f4ff45b425f3fe3792e93aec553
URL: https://github.com/llvm/llvm-project/commit/6009d0d5801d8f4ff45b425f3fe3792e93aec553
DIFF: https://github.com/llvm/llvm-project/commit/6009d0d5801d8f4ff45b425f3fe3792e93aec553.diff
LOG: [clangd] Track time spent in filesystem ops during preamble builds
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.
Differential Revision: https://reviews.llvm.org/D121712
Added:
Modified:
clang-tools-extra/clangd/Preamble.cpp
clang-tools-extra/clangd/Preamble.h
clang-tools-extra/clangd/TUScheduler.cpp
Removed:
################################################################################
diff --git a/clang-tools-extra/clangd/Preamble.cpp b/clang-tools-extra/clangd/Preamble.cpp
index ea518f099689e..aab6dc78092f7 100644
--- a/clang-tools-extra/clangd/Preamble.cpp
+++ b/clang-tools-extra/clangd/Preamble.cpp
@@ -312,12 +312,98 @@ bool isMainFile(llvm::StringRef FileName, const SourceManager &SM) {
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 =
@@ -375,18 +461,25 @@ buildPreamble(PathRef FileName, CompilerInvocation CI,
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;
@@ -398,6 +491,10 @@ buildPreamble(PathRef FileName, CompilerInvocation CI,
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;
}
diff --git a/clang-tools-extra/clangd/Preamble.h b/clang-tools-extra/clangd/Preamble.h
index 75edee5acad56..33a308484c189 100644
--- a/clang-tools-extra/clangd/Preamble.h
+++ b/clang-tools-extra/clangd/Preamble.h
@@ -75,13 +75,25 @@ struct PreambleData {
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.
diff --git a/clang-tools-extra/clangd/TUScheduler.cpp b/clang-tools-extra/clangd/TUScheduler.cpp
index 6aec87d197ed2..d905a58fea50b 100644
--- a/clang-tools-extra/clangd/TUScheduler.cpp
+++ b/clang-tools-extra/clangd/TUScheduler.cpp
@@ -98,6 +98,33 @@ 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
@@ -975,13 +1002,19 @@ void PreambleThread::build(Request Req) {
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());
}
More information about the cfe-commits
mailing list