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,11 @@ namespace clangd { namespace { +// Tracks end-to-end latency of high level lsp calls. Measurements are in +// seconds. +constexpr trace::Metric LSPLatency("lsp_latency", trace::Metric::Distribution, + "operation_name"); + // 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 +190,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, LSPLatency); SPAN_ATTACH(Tracer, "Params", Params); ReplyOnce Reply(ID, Method, &Server, Tracer.Args); log("<-- {0}({1})", Method, ID); @@ -297,7 +302,7 @@ elog("Failed to decode {0} request.", Method); return; } - trace::Span Tracer(Method); + trace::Span Tracer(Method, LSPLatency); SPAN_ATTACH(Tracer, "Params", RawParams); (Server.*Handler)(P); }; @@ -1288,7 +1293,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 +1318,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 occurences per invocation. +constexpr trace::Metric RenameOccurrences("rename_occurrences", + 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)); } + RenameOccurrences.record(Edits->size()); return CB(std::move(*Edits)); }; WorkScheduler.runWithAST("Rename", File, std::move(Action)); @@ -420,6 +425,9 @@ return std::move(Result); } +// Tracks number of times a tweak has been offered. +constexpr trace::Metric TweakAvailable("tweak_available", + trace::Metric::Counter, "tweak_id"); void ClangdServer::enumerateTweaks(PathRef File, Range Sel, Callback> CB) { auto Action = [File = File.str(), Sel, CB = std::move(CB), @@ -439,6 +447,7 @@ for (auto &T : prepareTweaks(*Sel, Filter)) { Res.push_back({T->id(), T->title(), T->intent()}); PreparedTweaks.insert(T->id()); + TweakAvailable.record(1, T->id()); } } @@ -449,8 +458,12 @@ TUScheduler::InvalidateOnUpdate); } +// Tracks number of times a tweak has been applied. +constexpr trace::Metric TweakAttempt("tweak_attempt", trace::Metric::Counter, + "tweak_id"); void ClangdServer::applyTweak(PathRef File, Range Sel, StringRef TweakID, Callback CB) { + TweakAttempt.record(1, TweakID); auto Action = [File = File.str(), Sel, TweakID = TweakID.str(), CB = std::move(CB), FS = FSProvider.getFileSystem()](Expected InpAST) mutable { 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,12 @@ return None; } +// Tracks ast cache accesses for read operations. +constexpr trace::Metric ASTAccessForRead("ast_access_read", + trace::Metric::Counter, "result"); +// Tracks ast cache accesses for publishing diags. +constexpr trace::Metric ASTAccessForDiag("ast_access_diag", + trace::Metric::Counter, "result"); /// 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. @@ -142,11 +148,19 @@ /// Returns the cached value for \p K, or llvm::None if the value is not in /// 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) { + /// If \p AccessMetric is set records whether there was a hit or miss. + llvm::Optional> + take(Key K, const trace::Metric *AccessMetric = nullptr) { + // Record metric after unlocking the mutex. std::unique_lock Lock(Mut); auto Existing = findByKey(K); - if (Existing == LRU.end()) + if (Existing == LRU.end()) { + if (AccessMetric) + AccessMetric->record(1, "miss"); return None; + } + if (AccessMetric) + AccessMetric->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 @@ -652,7 +666,8 @@ auto Task = [=, Action = std::move(Action)]() mutable { if (auto Reason = isCancelled()) return Action(llvm::make_error(Reason)); - llvm::Optional> AST = IdleASTs.take(this); + llvm::Optional> AST = + IdleASTs.take(this, &ASTAccessForRead); if (!AST) { StoreDiags CompilerInvocationDiagConsumer; std::unique_ptr Invocation = @@ -801,7 +816,8 @@ // We might be able to reuse the last we've built for a read request. // FIXME: It might be better to not reuse this AST. That way queued AST builds // won't be required for diags. - llvm::Optional> AST = IdleASTs.take(this); + llvm::Optional> AST = + IdleASTs.take(this, &ASTAccessForDiag); if (!AST || !InputsAreLatest) { auto RebuildStartTime = DebouncePolicy::clock::now(); llvm::Optional NewAST = ParsedAST::build( 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,15 +18,58 @@ #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 { -/// A consumer of trace events. The events are produced by Spans and trace::log. +/// Represents measurements of clangd events, e.g. operation latency. Those +/// measurements are recorded per-label, defaulting to an empty one for metrics +/// that don't care about it. This enables aggregation of measurements across +/// labels. For example a metric tracking accesses to a cache can have labels +/// named hit and miss. +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, + llvm::StringLiteral LabelName = "") + : Name(Name), Type(Type), LabelName(LabelName) {} + + /// 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 + /// dots for hierarchy if needed. e.g. method_latency, foo.bar. + const llvm::StringLiteral Name; + const MetricType Type; + /// Indicates what measurement labels represent, e.g. "operation_name" for a + /// metric tracking latencies. If non empty all measurements must also have a + /// non-empty label. + const llvm::StringLiteral LabelName; +}; + +/// A consumer of trace events and measurements. The events are produced by +/// Spans and trace::log, the measurements are produced by Metrics::record. /// Implementations of this interface must be thread-safe. class EventTracer { public: @@ -37,16 +80,20 @@ /// Usually implementations will store an object in the returned context /// whose destructor records the end of the event. /// The args are *Args, only complete when the event ends. - virtual Context beginSpan(llvm::StringRef Name, llvm::json::Object *Args) = 0; + virtual Context beginSpan(llvm::StringRef Name, llvm::json::Object *Args); // Called when a Span is destroyed (it may still be active on other threads). // beginSpan() and endSpan() will always form a proper stack on each thread. // The Context returned by beginSpan is active, but Args is not ready. // Tracers should not override this unless they need to observe strict // per-thread nesting. Instead they should observe context destruction. - virtual void endSpan(){}; + virtual void endSpan() {} /// Called for instant events. - virtual void instant(llvm::StringRef Name, llvm::json::Object &&Args) = 0; + virtual void instant(llvm::StringRef Name, llvm::json::Object &&Args) {} + + /// Called whenever a metrics records 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 @@ -81,6 +128,9 @@ class Span { public: Span(llvm::Twine Name); + /// Records span's duration in seconds to \p LatencyMetric with \p Name as the + /// label. + Span(llvm::Twine Name, const Metric &LatencyMetric); ~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,27 +213,54 @@ } // 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; + 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); } +// Fallback metric that measures latencies for spans without an explicit latency +// metric. Labels are span names. +constexpr Metric SpanLatency("span_latency", Metric::Distribution, "span_name"); + // 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) : Span(Name, SpanLatency) {} +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; + assert((LabelName.empty() == Label.empty()) && + "recording a measurement with inconsistent labeling"); + T->record(*this, Value, Label); +} + +Context EventTracer::beginSpan(llvm::StringRef Name, llvm::json::Object *Args) { + return Context::current().clone(); +} } // 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,47 @@ 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) {} + void record(const trace::Metric &Metric, double Value, + llvm::StringRef Label = "") override { + Metrics.push_back(Metric.Name); + } + + 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, + "label_name"); + { + trace::Span SpanWithLat("op_name", LatMetric); + EXPECT_THAT(Metrics, testing::IsEmpty()); + } + EXPECT_THAT(Metrics, testing::ElementsAre(MetricName)); +} + } // namespace } // namespace clangd } // namespace clang