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 @@ -43,6 +43,10 @@ namespace clangd { namespace { +// Tracks end-to-end latency of high level lsp calls. +constexpr trace::Metric LSPLatencies("lsp_latencies", + trace::Metric::Distribution); + // LSP defines file versions as numbers that increase. // ClangdServer treats them as opaque and therefore uses strings instead. std::string encodeVersion(int64_t LSPVersion) { @@ -185,7 +189,7 @@ WithContext HandlerContext(handlerContext()); // Calls can be canceled by the client. Add cancellation context. WithContext WithCancel(cancelableRequestContext(ID)); - trace::Span Tracer(Method); + trace::Span Tracer(Method, &LSPLatencies); SPAN_ATTACH(Tracer, "Params", Params); ReplyOnce Reply(ID, Method, &Server, Tracer.Args); log("<-- {0}({1})", Method, ID); @@ -297,7 +301,7 @@ elog("Failed to decode {0} request.", Method); return; } - trace::Span Tracer(Method); + trace::Span Tracer(Method, &LSPLatencies); SPAN_ATTACH(Tracer, "Params", RawParams); (Server.*Handler)(P); }; @@ -1288,7 +1292,7 @@ Result.tokens = toSemanticTokens(*HT); { std::lock_guard Lock(SemanticTokensMutex); - auto& Last = LastSemanticTokens[File]; + auto &Last = LastSemanticTokens[File]; Last.tokens = Result.tokens; increment(Last.resultId); @@ -1313,7 +1317,7 @@ SemanticTokensOrEdits Result; { std::lock_guard Lock(SemanticTokensMutex); - auto& Last = LastSemanticTokens[File]; + auto &Last = LastSemanticTokens[File]; if (PrevResultID == Last.resultId) { Result.edits = diffTokens(Last.tokens, Toks); 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 @@ -361,6 +362,9 @@ WorkScheduler.runWithAST("PrepareRename", File, std::move(Action)); } +// Tracks number of renamed symbols per invocation. +constexpr trace::Metric RenamedSymbolCounts("renamed_symbol_counts", + trace::Metric::Distribution); void ClangdServer::rename(PathRef File, Position Pos, llvm::StringRef NewName, const RenameOptions &Opts, Callback CB) { // A snapshot of all file dirty buffers. @@ -393,6 +397,7 @@ if (Err) return CB(std::move(Err)); } + RenamedSymbolCounts.record(Edits->size()); return CB(std::move(*Edits)); }; WorkScheduler.runWithAST("Rename", File, std::move(Action)); @@ -420,6 +425,10 @@ return std::move(Result); } +// Tracks number of times a tweak has been offered. Label should be set to tweak +// id. +constexpr trace::Metric ShownCodeactions("shown_codeaction_count", + trace::Metric::Counter); void ClangdServer::enumerateTweaks(PathRef File, Range Sel, Callback> CB) { auto Action = [File = File.str(), Sel, CB = std::move(CB), @@ -439,6 +448,7 @@ for (auto &T : prepareTweaks(*Sel, Filter)) { Res.push_back({T->id(), T->title(), T->intent()}); PreparedTweaks.insert(T->id()); + ShownCodeactions.record(1, T->id()); } } @@ -449,6 +459,10 @@ TUScheduler::InvalidateOnUpdate); } +// Tracks number of times a tweak has been applied. Label should be set to tweak +// id. +constexpr trace::Metric ExecutedTweaks("executed_tweaks", + trace::Metric::Counter); void ClangdServer::applyTweak(PathRef File, Range Sel, StringRef TweakID, Callback CB) { auto Action = @@ -480,6 +494,7 @@ if (llvm::Error Err = reformatEdit(E, Style)) elog("Failed to format {0}: {1}", It.first(), std::move(Err)); } + ExecutedTweaks.record(1, TweakID); } return CB(std::move(*Effect)); }; 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 @@ -102,6 +102,9 @@ return None; } +// Used to track ast cache utilization. +constexpr static trace::Metric ASTCacheAccess("ast_cache_access", + trace::Metric::Counter); /// An LRU cache of idle ASTs. /// Because we want to limit the overall number of these we retain, the cache /// owns ASTs (and may evict them) while their workers are idle. @@ -143,10 +146,14 @@ /// 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) { + // Record metric after unlocking the mutex. std::unique_lock Lock(Mut); auto Existing = findByKey(K); - if (Existing == LRU.end()) + if (Existing == LRU.end()) { + ASTCacheAccess.record(1, "miss"); return None; + } + ASTCacheAccess.record(1, "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/support/Trace.h b/clang-tools-extra/clangd/support/Trace.h --- a/clang-tools-extra/clangd/support/Trace.h +++ b/clang-tools-extra/clangd/support/Trace.h @@ -18,14 +18,47 @@ #define LLVM_CLANG_TOOLS_EXTRA_CLANGD_SUPPORT_TRACE_H_ #include "support/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. +struct Metric { + enum MetricType { + /// A number whose value is meaningful, and may vary over time. + /// Each measurement replaces the current value. + Value, + + /// An aggregate number whose rate of change over time is meaningful. + /// Each measurement is an increment for the counter. + Counter, + + /// A distribution of values with a meaningful mean and count. + /// Each measured value is a sample for the distribution. + /// The distribution is assumed not to vary, samples are aggregated over + /// time. + Distribution, + }; + constexpr Metric(llvm::StringLiteral Name, MetricType Type) + : Name(Name), Type(Type) {} + + /// Records a measurement for this metric to active tracer. + void record(double Value, llvm::StringRef Label = "") const; + + /// Uniquely identifies the metric. Should use snake_case identifiers, can use + /// slashes for hierarchy if needed. e.g. method_latency, foo.bar. + const llvm::StringLiteral Name; + const MetricType Type; +}; + /// 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 +80,10 @@ /// 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, double Value, + llvm::StringRef Label = "") {} }; /// Sets up a global EventTracer that consumes events produced by Span and @@ -80,7 +117,9 @@ /// SomeJSONExpr is evaluated and copied only if actually needed. class Span { public: - Span(llvm::Twine Name); + /// If \p LatencyMetric is non-null, it will receive a measurement reflecting + /// the spans lifetime. Label of measurement will be \p Name. + Span(llvm::Twine Name, const Metric *LatencyMetric = nullptr); ~Span(); /// Mutable metadata, if this span is interested. diff --git a/clang-tools-extra/clangd/support/Trace.cpp b/clang-tools-extra/clangd/support/Trace.cpp --- a/clang-tools-extra/clangd/support/Trace.cpp +++ b/clang-tools-extra/clangd/support/Trace.cpp @@ -9,12 +9,16 @@ #include "support/Trace.h" #include "support/Context.h" #include "llvm/ADT/DenseSet.h" +#include "llvm/ADT/Optional.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 { @@ -209,10 +213,23 @@ } // Returned context owns Args. -static Context makeSpanContext(llvm::Twine Name, llvm::json::Object *Args) { +static Context makeSpanContext(llvm::Twine Name, llvm::json::Object *Args, + const Metric *LatencyMetric) { if (!T) return Context::current().clone(); WithContextValue WithArgs{std::unique_ptr(Args)}; + llvm::Optional WithLatency; + if (LatencyMetric) { + using Clock = std::chrono::high_resolution_clock; + WithLatency.emplace(llvm::make_scope_exit( + [StartTime = Clock::now(), Name = Name.str(), LatencyMetric] { + LatencyMetric->record( + std::chrono::duration_cast( + Clock::now() - StartTime) + .count(), + Name); + })); + } return T->beginSpan(Name.isSingleStringRef() ? Name.getSingleStringRef() : llvm::StringRef(Name.str()), Args); @@ -221,15 +238,21 @@ // Span keeps a non-owning pointer to the args, which is how users access them. // The args are owned by the context though. They stick around until the // beginSpan() context is destroyed, when the tracing engine will consume them. -Span::Span(llvm::Twine Name) +Span::Span(llvm::Twine Name, const Metric *LatencyMetric) : Args(T ? new llvm::json::Object() : nullptr), - RestoreCtx(makeSpanContext(Name, Args)) {} + RestoreCtx(makeSpanContext(Name, Args, LatencyMetric)) {} Span::~Span() { if (T) T->endSpan(); } +void Metric::record(double Value, llvm::StringRef Label) const { + if (!T) + return; + T->record(*this, Value, Label); +} + } // namespace trace } // namespace clangd } // namespace clang diff --git a/clang-tools-extra/clangd/unittests/support/TraceTests.cpp b/clang-tools-extra/clangd/unittests/support/TraceTests.cpp --- a/clang-tools-extra/clangd/unittests/support/TraceTests.cpp +++ b/clang-tools-extra/clangd/unittests/support/TraceTests.cpp @@ -6,10 +6,11 @@ // //===----------------------------------------------------------------------===// +#include "support/Context.h" #include "support/Trace.h" - #include "llvm/ADT/DenseMap.h" #include "llvm/ADT/SmallString.h" +#include "llvm/ADT/StringRef.h" #include "llvm/Support/SourceMgr.h" #include "llvm/Support/Threading.h" #include "llvm/Support/YAMLParser.h" @@ -122,6 +123,50 @@ ASSERT_EQ(++Prop, Root->end()); } +class MetricsTracerTest : public ::testing::Test { +public: + MetricsTracerTest() : Tracer(Metrics), Session(Tracer) {} + +protected: + class MetricsTracer : public trace::EventTracer { + public: + MetricsTracer(std::vector &Metrics) + : Metrics(Metrics) {} + Context beginSpan(llvm::StringRef, llvm::json::Object *) override { + return Context::current().clone(); + } + void record(const trace::Metric &Metric, double Value, + llvm::StringRef Label = "") override { + Metrics.push_back(Metric.Name); + } + void instant(llvm::StringRef, llvm::json::Object &&) override {} + + private: + std::vector &Metrics; + }; + std::vector Metrics; + MetricsTracer Tracer; + trace::Session Session; +}; + +TEST_F(MetricsTracerTest, RecordTest) { + constexpr llvm::StringLiteral MetricName = "metric"; + constexpr trace::Metric M(MetricName, trace::Metric::Counter); + EXPECT_THAT(Metrics, testing::IsEmpty()); + M.record(1); + EXPECT_THAT(Metrics, testing::ElementsAre(MetricName)); +} + +TEST_F(MetricsTracerTest, LatencyTest) { + constexpr llvm::StringLiteral MetricName = "latencies"; + constexpr trace::Metric LatMetric(MetricName, trace::Metric::Distribution); + { + trace::Span SpanWithLat("op_name", &LatMetric); + EXPECT_THAT(Metrics, testing::IsEmpty()); + } + EXPECT_THAT(Metrics, testing::ElementsAre(MetricName)); +} + } // namespace } // namespace clangd } // namespace clang