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,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 &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/Preamble.cpp b/clang-tools-extra/clangd/Preamble.cpp --- a/clang-tools-extra/clangd/Preamble.cpp +++ b/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; + } + /// Return total time, in seconds. + double getTime() { return std::chrono::duration(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 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 { + WallTimerRegion T(Timer); + return InnerFile->close(); + } + +private: + WallTimer &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(llvm::IntrusiveRefCntPtr FS) + : ProxyFileSystem(std::move(FS)) {} + + 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); + } + + double getTime() { return Timer.getTime(); } + +private: + WallTimer Timer; +}; + } // namespace std::shared_ptr 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 @@ llvm::SmallString<32> AbsFileName(FileName); VFS->makeAbsolute(AbsFileName); auto StatCache = std::make_unique(AbsFileName); + auto StatCacheFS = StatCache->getProducingFS(VFS); + llvm::IntrusiveRefCntPtr TimedFS(new TimerFS(StatCacheFS)); + + WallTimer PreambleTimer; + PreambleTimer.startTimer(); auto BuiltPreamble = PrecompiledPreamble::Build( CI, ContentsBuffer.get(), Bounds, *PreambleDiagsEngine, - StatCache->getProducingFS(VFS), - std::make_shared(), StoreInMemory, CapturedInfo); + Stats ? TimedFS : StatCacheFS, std::make_shared(), + 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 Diags = PreambleDiagnostics.take(); auto Result = std::make_shared(std::move(*BuiltPreamble)); Result->Version = Inputs.Version; @@ -398,6 +491,10 @@ 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/TUScheduler.cpp b/clang-tools-extra/clangd/TUScheduler.cpp --- a/clang-tools-extra/clangd/TUScheduler.cpp +++ b/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 &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 @@ 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()); }