diff --git a/clang-tools-extra/clangd/FS.h b/clang-tools-extra/clangd/FS.h --- a/clang-tools-extra/clangd/FS.h +++ b/clang-tools-extra/clangd/FS.h @@ -13,6 +13,7 @@ #include "clang/Basic/LLVM.h" #include "llvm/ADT/Optional.h" #include "llvm/ADT/StringMap.h" +#include "llvm/Support/Timer.h" #include "llvm/Support/VirtualFileSystem.h" namespace clang { @@ -67,6 +68,29 @@ llvm::StringMap StatCache; }; +/// Used for tracking time spent in FS operations. Like llvm::Timer, but only +/// 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. +class WallTimer { +public: + WallTimer(); + // [Re-]Start the timer. + void startTime(); + // Stop the timer and update total time. + void stopTime(); + // Return total time, in seconds. + double getTime(); + +private: + std::chrono::steady_clock::duration TotalTime; + std::chrono::steady_clock::time_point StartTime; +}; + +IntrusiveRefCntPtr +getTimeTrackingFS(std::shared_ptr Timer, + IntrusiveRefCntPtr FS); + /// Returns a version of \p File that doesn't contain dots and dot dots. /// e.g /a/b/../c -> /a/c /// /a/b/./c -> /a/b/c diff --git a/clang-tools-extra/clangd/FS.cpp b/clang-tools-extra/clangd/FS.cpp --- a/clang-tools-extra/clangd/FS.cpp +++ b/clang-tools-extra/clangd/FS.cpp @@ -111,6 +111,86 @@ return llvm::IntrusiveRefCntPtr(new CacheVFS(std::move(FS), *this)); } +class WallTimerRegion { +public: + WallTimerRegion(WallTimer &T) : T(T) { T.startTime(); } + ~WallTimerRegion() { T.stopTime(); } + +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(std::shared_ptr Timer, std::unique_ptr InnerFile) + : Timer(Timer), InnerFile(std::move(InnerFile)) {} + + llvm::ErrorOr status() override { + WallTimerRegion T(*Timer); + return InnerFile->status(); + } + llvm::ErrorOr> + 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 { return InnerFile->close(); } + +private: + std::shared_ptr Timer; + std::unique_ptr 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(std::shared_ptr Timer, + llvm::IntrusiveRefCntPtr FS) + : ProxyFileSystem(std::move(FS)), Timer(Timer) {} + + llvm::ErrorOr> + openFileForRead(const llvm::Twine &Path) override { + WallTimerRegion T(*Timer); + auto FileOr = getUnderlyingFS().openFileForRead(Path); + if (!FileOr) + return FileOr; + return std::make_unique(Timer, std::move(FileOr.get())); + } + + llvm::ErrorOr status(const llvm::Twine &Path) override { + WallTimerRegion T(*Timer); + return getUnderlyingFS().status(Path); + } + +private: + std::shared_ptr Timer; +}; + +WallTimer::WallTimer() { + TotalTime = std::chrono::steady_clock::duration::zero(); +} + +void WallTimer::startTime() { StartTime = std::chrono::steady_clock::now(); } + +void WallTimer::stopTime() { + TotalTime += std::chrono::steady_clock::now() - StartTime; +} + +double WallTimer::getTime() { + return std::chrono::duration(TotalTime).count(); +} + +IntrusiveRefCntPtr +getTimeTrackingFS(std::shared_ptr Timer, + IntrusiveRefCntPtr FS) { + return IntrusiveRefCntPtr(new TimerFS(Timer, FS)); +} + Path removeDots(PathRef File) { llvm::SmallString<128> CanonPath(File); llvm::sys::path::remove_dots(CanonPath, /*remove_dot_dot=*/true); diff --git a/clang-tools-extra/clangd/Preamble.h b/clang-tools-extra/clangd/Preamble.h --- a/clang-tools-extra/clangd/Preamble.h +++ b/clang-tools-extra/clangd/Preamble.h @@ -75,12 +75,24 @@ 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 &Inputs, bool StoreInMemory, + PreambleBuildStats *Stats, PreambleParsedCallback PreambleCallback); /// Returns true if \p Preamble is reusable for \p Inputs. Note that it will diff --git a/clang-tools-extra/clangd/Preamble.cpp b/clang-tools-extra/clangd/Preamble.cpp --- a/clang-tools-extra/clangd/Preamble.cpp +++ b/clang-tools-extra/clangd/Preamble.cpp @@ -317,6 +317,7 @@ std::shared_ptr buildPreamble(PathRef FileName, CompilerInvocation CI, const ParseInputs &Inputs, bool StoreInMemory, + PreambleBuildStats *Stats, PreambleParsedCallback PreambleCallback) { // Note that we don't need to copy the input contents, preamble can live // without those. @@ -375,18 +376,24 @@ llvm::SmallString<32> AbsFileName(FileName); VFS->makeAbsolute(AbsFileName); auto StatCache = std::make_unique(AbsFileName); + auto FSTimer = std::make_shared(); + auto TimedFS = getTimeTrackingFS(FSTimer, StatCache->getProducingFS(VFS)); + + llvm::Timer PreambleTimer; + PreambleTimer.startTimer(); auto BuiltPreamble = PrecompiledPreamble::Build( - CI, ContentsBuffer.get(), Bounds, *PreambleDiagsEngine, - StatCache->getProducingFS(VFS), + CI, ContentsBuffer.get(), Bounds, *PreambleDiagsEngine, TimedFS, std::make_shared(), StoreInMemory, CapturedInfo); + PreambleTimer.stopTimer(); + auto PreambleTime = PreambleTimer.getTotalTime().getWallTime(); // 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, PreambleTime); std::vector Diags = PreambleDiagnostics.take(); auto Result = std::make_shared(std::move(*BuiltPreamble)); Result->Version = Inputs.Version; @@ -398,6 +405,10 @@ Result->CanonIncludes = CapturedInfo.takeCanonicalIncludes(); Result->StatCache = std::move(StatCache); Result->MainIsIncludeGuarded = CapturedInfo.isMainFileIncludeGuarded(); + if (Stats != nullptr) { + Stats->TotalBuildTime = PreambleTime; + Stats->FileSystemTime = FSTimer->getTime(); + } return Result; } diff --git a/clang-tools-extra/clangd/TUScheduler.cpp b/clang-tools-extra/clangd/TUScheduler.cpp --- a/clang-tools-extra/clangd/TUScheduler.cpp +++ b/clang-tools-extra/clangd/TUScheduler.cpp @@ -97,6 +97,35 @@ namespace clangd { using std::chrono::steady_clock; +// 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"); + +static void reportPreambleBuild(const PreambleBuildStats &Stats, + const bool IsFirstPreamble) { + // The first preamble we build in a clangd instance gets a different metric + // label so we can separate it from later first preambles, which likely have + // at least some caches warmed up. + static bool FirstReport = true; + const std::string Label = + FirstReport ? "first_build" + : (IsFirstPreamble ? "first_build_for_file" : "rebuild"); + FirstReport = false; + + PreambleBuildFilesystemLatency.record(Stats.FileSystemTime, Label); + if (Stats.TotalBuildTime > 0) // Avoid division by zero. + PreambleBuildFilesystemLatencyRatio.record( + Stats.FileSystemTime / Stats.TotalBuildTime, Label); +} + namespace { class ASTWorker; } // namespace @@ -975,14 +1004,18 @@ crashDumpParseInputs(llvm::errs(), Inputs); }); + PreambleBuildStats Stats; + const bool IsFirstPreamble = !LatestBuild; LatestBuild = clang::clangd::buildPreamble( - FileName, *Req.CI, Inputs, StoreInMemory, + FileName, *Req.CI, Inputs, StoreInMemory, &Stats, [this, Version(Inputs.Version)](ASTContext &Ctx, Preprocessor &PP, const CanonicalIncludes &CanonIncludes) { Callbacks.onPreambleAST(FileName, Version, Ctx, PP, CanonIncludes); }); if (LatestBuild && isReliable(LatestBuild->CompileCommand)) HeaderIncluders.update(FileName, LatestBuild->Includes.allHeaders()); + if (LatestBuild) + reportPreambleBuild(Stats, IsFirstPreamble); } void ASTWorker::updatePreamble(std::unique_ptr CI, diff --git a/clang-tools-extra/clangd/tool/Check.cpp b/clang-tools-extra/clangd/tool/Check.cpp --- a/clang-tools-extra/clangd/tool/Check.cpp +++ b/clang-tools-extra/clangd/tool/Check.cpp @@ -159,6 +159,7 @@ bool buildAST() { log("Building preamble..."); Preamble = buildPreamble(File, *Invocation, Inputs, /*StoreInMemory=*/true, + /*Stats=*/nullptr, [&](ASTContext &Ctx, Preprocessor &PP, const CanonicalIncludes &Includes) { if (!Opts.BuildDynamicSymbolIndex) diff --git a/clang-tools-extra/clangd/unittests/CodeCompleteTests.cpp b/clang-tools-extra/clangd/unittests/CodeCompleteTests.cpp --- a/clang-tools-extra/clangd/unittests/CodeCompleteTests.cpp +++ b/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, /*Callback=*/nullptr); + auto Preamble = + buildPreamble(testPath(TU.Filename), *CI, Inputs, + /*InMemory=*/true, /*Stats=*/nullptr, /*Callback=*/nullptr); return codeComplete(testPath(TU.Filename), Point, Preamble.get(), Inputs, Opts); } @@ -1191,8 +1192,9 @@ ADD_FAILURE() << "Couldn't build CompilerInvocation"; return {}; } - auto Preamble = buildPreamble(testPath(TU.Filename), *CI, Inputs, - /*InMemory=*/true, /*Callback=*/nullptr); + auto Preamble = + buildPreamble(testPath(TU.Filename), *CI, Inputs, + /*InMemory=*/true, /*Stats=*/nullptr, /*Callback=*/nullptr); if (!Preamble) { ADD_FAILURE() << "Couldn't build Preamble"; return {}; @@ -1439,8 +1441,9 @@ auto Inputs = TU.inputs(FS); auto CI = buildCompilerInvocation(Inputs, Diags); ASSERT_TRUE(CI); - auto EmptyPreamble = buildPreamble(testPath(TU.Filename), *CI, Inputs, - /*InMemory=*/true, /*Callback=*/nullptr); + auto EmptyPreamble = + buildPreamble(testPath(TU.Filename), *CI, Inputs, + /*InMemory=*/true, /*Stats=*/nullptr, /*Callback=*/nullptr); ASSERT_TRUE(EmptyPreamble); TU.AdditionalFiles["a.h"] = "int foo(int x);"; diff --git a/clang-tools-extra/clangd/unittests/FileIndexTests.cpp b/clang-tools-extra/clangd/unittests/FileIndexTests.cpp --- a/clang-tools-extra/clangd/unittests/FileIndexTests.cpp +++ b/clang-tools-extra/clangd/unittests/FileIndexTests.cpp @@ -307,6 +307,7 @@ bool IndexUpdated = false; buildPreamble(FooCpp, *CI, PI, /*StoreInMemory=*/true, + /*Stats=*/nullptr, [&](ASTContext &Ctx, Preprocessor &PP, const CanonicalIncludes &CanonIncludes) { EXPECT_FALSE(IndexUpdated) diff --git a/clang-tools-extra/clangd/unittests/ParsedASTTests.cpp b/clang-tools-extra/clangd/unittests/ParsedASTTests.cpp --- a/clang-tools-extra/clangd/unittests/ParsedASTTests.cpp +++ b/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(&Inclusion::Written, ""))); diff --git a/clang-tools-extra/clangd/unittests/PreambleTests.cpp b/clang-tools-extra/clangd/unittests/PreambleTests.cpp --- a/clang-tools-extra/clangd/unittests/PreambleTests.cpp +++ b/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( diff --git a/clang-tools-extra/clangd/unittests/TestTU.cpp b/clang-tools-extra/clangd/unittests/TestTU.cpp --- a/clang-tools-extra/clangd/unittests/TestTU.cpp +++ b/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);