diff --git a/clang-tools-extra/clangd/ClangdLSPServer.cpp b/clang-tools-extra/clangd/ClangdLSPServer.cpp --- a/clang-tools-extra/clangd/ClangdLSPServer.cpp +++ b/clang-tools-extra/clangd/ClangdLSPServer.cpp @@ -185,6 +185,7 @@ WithContext HandlerContext(handlerContext()); // Calls can be canceled by the client. Add cancellation context. WithContext WithCancel(cancelableRequestContext(ID)); + WithContext LatencyCtx(trace::latencyTrackingContext(Method)); trace::Span Tracer(Method); SPAN_ATTACH(Tracer, "Params", Params); ReplyOnce Reply(ID, Method, &Server, Tracer.Args); @@ -299,6 +300,7 @@ } trace::Span Tracer(Method); SPAN_ATTACH(Tracer, "Params", RawParams); + WithContext LatencyCtx(trace::latencyTrackingContext(Method)); (Server.*Handler)(P); }; } diff --git a/clang-tools-extra/clangd/ClangdServer.cpp b/clang-tools-extra/clangd/ClangdServer.cpp --- a/clang-tools-extra/clangd/ClangdServer.cpp +++ b/clang-tools-extra/clangd/ClangdServer.cpp @@ -43,6 +43,7 @@ #include "llvm/Support/Error.h" #include "llvm/Support/FileSystem.h" #include "llvm/Support/Path.h" +#include "llvm/Support/ScopedPrinter.h" #include "llvm/Support/raw_ostream.h" #include #include @@ -396,6 +397,9 @@ if (Err) return CB(std::move(Err)); } + trace::Metric M("/clangd/rename"); + M.Ty = trace::Metric::Sample; + M.Value = Edits->size(); return CB(std::move(*Edits)); }; WorkScheduler.runWithAST("Rename", File, std::move(Action)); @@ -442,6 +446,10 @@ for (auto &T : prepareTweaks(*Sel, Filter)) { Res.push_back({T->id(), T->title(), T->intent()}); PreparedTweaks.insert(T->id()); + trace::Metric M("/clangd/shown_codeaction"); + M.Ty = trace::Metric::Increment; + M.Value = 1; + M.Labels = {T->id()}; } } @@ -462,6 +470,10 @@ auto Selections = tweakSelection(Sel, *InpAST); if (!Selections) return CB(Selections.takeError()); + trace::Metric M("/clangd/executed_tweaks"); + M.Ty = trace::Metric::Increment; + M.Value = 1; + M.Labels = {TweakID, /*Error=*/""}; llvm::Optional> Effect; // Try each selection, take the first one that prepare()s. // If they all fail, Effect will hold get the last error. @@ -483,8 +495,11 @@ if (llvm::Error Err = reformatEdit(E, Style)) elog("Failed to format {0}: {1}", It.first(), std::move(Err)); } + return CB(std::move(*Effect)); } - return CB(std::move(*Effect)); + auto Err = Effect->takeError(); + M.Labels.back() = llvm::to_string(Err); + return CB(std::move(Err)); }; WorkScheduler.runWithAST("ApplyTweak", File, std::move(Action)); } 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 @@ -143,10 +143,17 @@ /// the cache anymore. If nullptr was cached for \p K, this function will /// return a null unique_ptr wrapped into an optional. llvm::Optional> take(Key K) { + trace::Metric M("/clangd/ast_cache"); + M.Ty = trace::Metric::Increment; + M.Value = 1; + // Record metric after unlocking the mutex. std::unique_lock Lock(Mut); auto Existing = findByKey(K); - if (Existing == LRU.end()) + if (Existing == LRU.end()) { + M.Labels = {"miss"}; return None; + } + M.Labels = {"hit"}; std::unique_ptr V = std::move(Existing->second); LRU.erase(Existing); // GCC 4.8 fails to compile `return V;`, as it tries to call the copy diff --git a/clang-tools-extra/clangd/Trace.h b/clang-tools-extra/clangd/Trace.h --- a/clang-tools-extra/clangd/Trace.h +++ b/clang-tools-extra/clangd/Trace.h @@ -18,14 +18,44 @@ #define LLVM_CLANG_TOOLS_EXTRA_CLANGD_TRACE_H_ #include "Context.h" +#include "llvm/ADT/StringRef.h" #include "llvm/ADT/Twine.h" #include "llvm/Support/JSON.h" #include "llvm/Support/raw_ostream.h" +#include +#include +#include namespace clang { namespace clangd { namespace trace { +/// Represents measurements of clangd events, e.g. operation latency. Reports +/// itself to active tracer on destruction. +struct Metric { + enum Type { + /// Occurence of an event, e.g. cache access. + Increment, + /// Aspect of an event, e.g. number of symbols in an index lookup. + Sample, + }; + /// Uniquely identifies the metric. + const llvm::StringLiteral Name; + /// Divides a metric into meaningful parts. e.g. hit/miss to represent result + /// of a cache access. + std::vector Labels; + double Value = 0; + Type Ty; + + Metric(llvm::StringLiteral Name) : Name(Name) {} + Metric(const Metric &) = delete; + Metric &operator=(const Metric &) = delete; + ~Metric(); +}; + +/// Creates a context that will report its duration as a metric on destruction. +Context latencyTrackingContext(llvm::StringRef OpName); + /// A consumer of trace events. The events are produced by Spans and trace::log. /// Implementations of this interface must be thread-safe. class EventTracer { @@ -47,6 +77,9 @@ /// Called for instant events. virtual void instant(llvm::StringRef Name, llvm::json::Object &&Args) = 0; + + /// Called whenever an event exports a measurement. + virtual void record(const Metric &Metric) {} }; /// Sets up a global EventTracer that consumes events produced by Span and diff --git a/clang-tools-extra/clangd/Trace.cpp b/clang-tools-extra/clangd/Trace.cpp --- a/clang-tools-extra/clangd/Trace.cpp +++ b/clang-tools-extra/clangd/Trace.cpp @@ -10,11 +10,14 @@ #include "Context.h" #include "llvm/ADT/DenseSet.h" #include "llvm/ADT/ScopeExit.h" +#include "llvm/ADT/StringRef.h" #include "llvm/Support/Chrono.h" #include "llvm/Support/FormatProviders.h" #include "llvm/Support/FormatVariadic.h" #include "llvm/Support/Threading.h" #include +#include +#include #include namespace clang { @@ -149,10 +152,10 @@ void rawEvent(llvm::StringRef Phase, const llvm::json::Object &Event) /*REQUIRES(Mu)*/ { // PID 0 represents the clangd process. - Out.object([&]{ + Out.object([&] { Out.attribute("pid", 0); Out.attribute("ph", Phase); - for (const auto& KV : Event) + for (const auto &KV : Event) Out.attribute(KV.first, KV.second); }); } @@ -230,6 +233,25 @@ T->endSpan(); } +Metric::~Metric() { + if (!T) + return; + T->record(*this); +} + +Context latencyTrackingContext(llvm::StringRef OpName) { + using Clock = std::chrono::high_resolution_clock; + return Context::current().derive( + llvm::make_scope_exit([StartTime = Clock::now(), OpName = OpName.str()] { + Metric M("/clangd/latencies"); + M.Value = std::chrono::duration_cast( + Clock::now() - StartTime) + .count(); + M.Labels = {OpName}; + M.Ty = Metric::Sample; + })); +} + } // namespace trace } // namespace clangd } // namespace clang