[clangd] Metric tracking through Tracer

Summary: Introduces an endpoint to Tracer for tracking metrics on
internal events.

Reviewers: sammccall

Subscribers: ilya-biryukov, javed.absar, MaskRay, jkorous, arphaman, usaxena95, cfe-commits

Tags: #clang

Differential Revision: https://reviews.llvm.org/D78429

clang-tools-extra/clangd/ClangdLSPServer.cpp

@@ -42,6 +42,11 @@ namespace clang {
 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,
+                                   "method_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) {
@@ -184,7 +189,7 @@ public:
     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);
@@ -296,7 +301,7 @@ public:
         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);
     };
@@ -1289,7 +1294,7 @@ void ClangdLSPServer::onSemanticTokens(const SemanticTokensParams &Params,
         Result.tokens = toSemanticTokens(*HT);
         {
           std::lock_guard<std::mutex> Lock(SemanticTokensMutex);
-          auto& Last = LastSemanticTokens[File];
+          auto &Last = LastSemanticTokens[File];
 
           Last.tokens = Result.tokens;
           increment(Last.resultId);
@@ -1314,7 +1319,7 @@ void ClangdLSPServer::onSemanticTokensEdits(
         SemanticTokensOrEdits Result;
         {
           std::lock_guard<std::mutex> Lock(SemanticTokensMutex);
-          auto& Last = LastSemanticTokens[File];
+          auto &Last = LastSemanticTokens[File];
 
           if (PrevResultID == Last.resultId) {
             Result.edits = diffTokens(Last.tokens, Toks);

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 <algorithm>
 #include <future>
@@ -368,6 +369,9 @@ void ClangdServer::rename(PathRef File, Position Pos, llvm::StringRef NewName,
   auto Action = [File = File.str(), NewName = NewName.str(), Pos, Opts,
                  CB = std::move(CB), Snapshot = std::move(Snapshot),
                  this](llvm::Expected<InputsAndAST> InpAST) mutable {
+    // Tracks number of files edited per invocation.
+    static constexpr trace::Metric RenameFiles("rename_files",
+                                               trace::Metric::Distribution);
     if (!InpAST)
       return CB(InpAST.takeError());
     auto GetDirtyBuffer =
@@ -393,6 +397,7 @@ void ClangdServer::rename(PathRef File, Position Pos, llvm::StringRef NewName,
       if (Err)
         return CB(std::move(Err));
     }
+    RenameFiles.record(Edits->size());
     return CB(std::move(*Edits));
   };
   WorkScheduler.runWithAST("Rename", File, std::move(Action));
@@ -422,6 +427,9 @@ tweakSelection(const Range &Sel, const InputsAndAST &AST) {
 
 void ClangdServer::enumerateTweaks(PathRef File, Range Sel,
                                    Callback<std::vector<TweakRef>> CB) {
+  // Tracks number of times a tweak has been offered.
+  static constexpr trace::Metric TweakAvailable(
+      "tweak_available", trace::Metric::Counter, "tweak_id");
   auto Action = [File = File.str(), Sel, CB = std::move(CB),
                  this](Expected<InputsAndAST> InpAST) mutable {
     if (!InpAST)
@@ -439,6 +447,7 @@ void ClangdServer::enumerateTweaks(PathRef File, Range Sel,
       for (auto &T : prepareTweaks(*Sel, Filter)) {
         Res.push_back({T->id(), T->title(), T->intent()});
         PreparedTweaks.insert(T->id());
+        TweakAvailable.record(1, T->id());
       }
     }
 
@@ -451,6 +460,10 @@ void ClangdServer::enumerateTweaks(PathRef File, Range Sel,
 
 void ClangdServer::applyTweak(PathRef File, Range Sel, StringRef TweakID,
                               Callback<Tweak::Effect> CB) {
+  // Tracks number of times a tweak has been applied.
+  static constexpr trace::Metric TweakAttempt(
+      "tweak_attempt", trace::Metric::Counter, "tweak_id");
+  TweakAttempt.record(1, TweakID);
   auto Action =
       [File = File.str(), Sel, TweakID = TweakID.str(), CB = std::move(CB),
        FS = FSProvider.getFileSystem()](Expected<InputsAndAST> InpAST) mutable {

clang-tools-extra/clangd/TUScheduler.cpp

@@ -142,11 +142,19 @@ public:
   /// 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<std::unique_ptr<ParsedAST>> take(Key K) {
+  /// If \p AccessMetric is set records whether there was a hit or miss.
+  llvm::Optional<std::unique_ptr<ParsedAST>>
+  take(Key K, const trace::Metric *AccessMetric = nullptr) {
+    // Record metric after unlocking the mutex.
     std::unique_lock<std::mutex> 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<ParsedAST> V = std::move(Existing->second);
     LRU.erase(Existing);
     // GCC 4.8 fails to compile `return V;`, as it tries to call the copy
@@ -649,10 +657,14 @@ void ASTWorker::runWithAST(
     llvm::StringRef Name,
     llvm::unique_function<void(llvm::Expected<InputsAndAST>)> Action,
     TUScheduler::ASTActionInvalidation Invalidation) {
+  // Tracks ast cache accesses for read operations.
+  static constexpr trace::Metric ASTAccessForRead(
+      "ast_access_read", trace::Metric::Counter, "result");
   auto Task = [=, Action = std::move(Action)]() mutable {
     if (auto Reason = isCancelled())
       return Action(llvm::make_error<CancelledError>(Reason));
-    llvm::Optional<std::unique_ptr<ParsedAST>> AST = IdleASTs.take(this);
+    llvm::Optional<std::unique_ptr<ParsedAST>> AST =
+        IdleASTs.take(this, &ASTAccessForRead);
     if (!AST) {
       StoreDiags CompilerInvocationDiagConsumer;
       std::unique_ptr<CompilerInvocation> Invocation =
@@ -773,6 +785,9 @@ void ASTWorker::updatePreamble(std::unique_ptr<CompilerInvocation> CI,
 void ASTWorker::generateDiagnostics(
     std::unique_ptr<CompilerInvocation> Invocation, ParseInputs Inputs,
     std::vector<Diag> CIDiags) {
+  // Tracks ast cache accesses for publishing diags.
+  static constexpr trace::Metric ASTAccessForDiag(
+      "ast_access_diag", trace::Metric::Counter, "result");
   assert(Invocation);
   // No need to rebuild the AST if we won't send the diagnostics.
   {
@@ -801,7 +816,8 @@ void ASTWorker::generateDiagnostics(
   // 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<std::unique_ptr<ParsedAST>> AST = IdleASTs.take(this);
+  llvm::Optional<std::unique_ptr<ParsedAST>> AST =
+      IdleASTs.take(this, &ASTAccessForDiag);
   if (!AST || !InputsAreLatest) {
     auto RebuildStartTime = DebouncePolicy::clock::now();
     llvm::Optional<ParsedAST> NewAST = ParsedAST::build(

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 <atomic>
+#include <chrono>
+#include <memory>
 #include <mutex>
 
 namespace clang {
@@ -209,27 +213,54 @@ void log(const llvm::Twine &Message) {
 }
 
 // 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<llvm::json::Object>(Args)};
+  llvm::Optional<WithContextValue> 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<std::chrono::milliseconds>(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

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 <chrono>
+#include <string>
+#include <vector>
 
 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 @@ public:
   /// 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 @@ void log(const llvm::Twine &Name);
 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.

clang-tools-extra/clangd/unittests/CMakeLists.txt

@@ -83,6 +83,7 @@ add_unittest(ClangdUnitTests ClangdTests
   support/FunctionTests.cpp
   support/MarkupTests.cpp
   support/ThreadingTests.cpp
+  support/TestTracer.cpp
   support/TraceTests.cpp
 
   $<TARGET_OBJECTS:obj.clangDaemonTweaks>

clang-tools-extra/clangd/unittests/ClangdLSPServerTests.cpp

@@ -14,6 +14,9 @@
 #include "TestFS.h"
 #include "refactor/Rename.h"
 #include "support/Logger.h"
+#include "support/TestTracer.h"
+#include "llvm/ADT/StringRef.h"
+#include "llvm/Support/Error.h"
 #include "llvm/Support/JSON.h"
 #include "llvm/Testing/Support/SupportHelpers.h"
 #include "gmock/gmock.h"
@@ -147,6 +150,14 @@ TEST_F(LSPTest, DiagnosticsHeaderSaved) {
                   DiagMessage("Use of undeclared identifier 'changed'"))));
 }
 
+TEST_F(LSPTest, RecordsLatencies) {
+  trace::TestTracer Tracer;
+  auto &Client = start();
+  llvm::StringLiteral MethodName = "method_name";
+  EXPECT_THAT(Tracer.takeMetric("lsp_latency", MethodName), testing::SizeIs(0));
+  llvm::consumeError(Client.call(MethodName, {}).take().takeError());
+  EXPECT_THAT(Tracer.takeMetric("lsp_latency", MethodName), testing::SizeIs(1));
+}
 } // namespace
 } // namespace clangd
 } // namespace clang

clang-tools-extra/clangd/unittests/LSPClient.cpp

@@ -20,7 +20,9 @@ llvm::Expected<llvm::json::Value> clang::clangd::LSPClient::CallResult::take() {
     ADD_FAILURE() << "No result from call after 10 seconds!";
     return llvm::json::Value(nullptr);
   }
-  return std::move(*Value);
+  auto Res = std::move(*Value);
+  Value.reset();
+  return Res;
 }
 
 llvm::json::Value LSPClient::CallResult::takeValue() {

clang-tools-extra/clangd/unittests/RenameTests.cpp

@@ -13,6 +13,7 @@
 #include "TestTU.h"
 #include "index/Ref.h"
 #include "refactor/Rename.h"
+#include "support/TestTracer.h"
 #include "clang/Tooling/Core/Replacement.h"
 #include "llvm/ADT/STLExtras.h"
 #include "llvm/Support/MemoryBuffer.h"
@@ -24,9 +25,11 @@ namespace clang {
 namespace clangd {
 namespace {
 
+using testing::ElementsAre;
 using testing::Eq;
-using testing::Pair;
 using testing::IsEmpty;
+using testing::Pair;
+using testing::SizeIs;
 using testing::UnorderedElementsAre;
 using testing::UnorderedElementsAreArray;
 
@@ -1016,7 +1019,8 @@ TEST(CrossFileRenameTests, WithUpToDateIndex) {
       },
   };
 
-  for (const auto& T : Cases) {
+  trace::TestTracer Tracer;
+  for (const auto &T : Cases) {
     SCOPED_TRACE(T.FooH);
     Annotations FooH(T.FooH);
     Annotations FooCC(T.FooCC);
@@ -1038,8 +1042,10 @@ TEST(CrossFileRenameTests, WithUpToDateIndex) {
 
     llvm::StringRef NewName = "NewName";
     for (const auto &RenamePos : FooH.points()) {
+      EXPECT_THAT(Tracer.takeMetric("rename_files"), SizeIs(0));
       auto FileEditsList = llvm::cantFail(runRename(
           Server, FooHPath, RenamePos, NewName, {/*CrossFile=*/true}));
+      EXPECT_THAT(Tracer.takeMetric("rename_files"), ElementsAre(2));
       EXPECT_THAT(
           applyEdits(std::move(FileEditsList)),
           UnorderedElementsAre(

clang-tools-extra/clangd/unittests/TUSchedulerTests.cpp

@@ -17,6 +17,7 @@
 #include "support/Cancellation.h"
 #include "support/Context.h"
 #include "support/Path.h"
+#include "support/TestTracer.h"
 #include "support/Threading.h"
 #include "clang/Basic/DiagnosticDriver.h"
 #include "llvm/ADT/ArrayRef.h"
@@ -41,6 +42,7 @@ using ::testing::Eq;
 using ::testing::Field;
 using ::testing::IsEmpty;
 using ::testing::Pointee;
+using ::testing::SizeIs;
 using ::testing::UnorderedElementsAre;
 
 MATCHER_P2(TUState, PreambleActivity, ASTActivity, "") {
@@ -502,6 +504,7 @@ TEST_F(TUSchedulerTests, EvictedAST) {
   auto Opts = optsForTest();
   Opts.AsyncThreadsCount = 1;
   Opts.RetentionPolicy.MaxRetainedASTs = 2;
+  trace::TestTracer Tracer;
   TUScheduler S(CDB, Opts);
 
   llvm::StringLiteral SourceContents = R"cpp(
@@ -517,12 +520,16 @@ TEST_F(TUSchedulerTests, EvictedAST) {
   auto Bar = testPath("bar.cpp");
   auto Baz = testPath("baz.cpp");
 
+  EXPECT_THAT(Tracer.takeMetric("ast_access_diag", "hit"), SizeIs(0));
+  EXPECT_THAT(Tracer.takeMetric("ast_access_diag", "miss"), SizeIs(0));
   // Build one file in advance. We will not access it later, so it will be the
   // one that the cache will evict.
   updateWithCallback(S, Foo, SourceContents, WantDiagnostics::Yes,
                      [&BuiltASTCounter]() { ++BuiltASTCounter; });
   ASSERT_TRUE(S.blockUntilIdle(timeoutSeconds(10)));
   ASSERT_EQ(BuiltASTCounter.load(), 1);
+  EXPECT_THAT(Tracer.takeMetric("ast_access_diag", "hit"), SizeIs(0));
+  EXPECT_THAT(Tracer.takeMetric("ast_access_diag", "miss"), SizeIs(1));
 
   // Build two more files. Since we can retain only 2 ASTs, these should be
   // the ones we see in the cache later.
@@ -532,6 +539,8 @@ TEST_F(TUSchedulerTests, EvictedAST) {
                      [&BuiltASTCounter]() { ++BuiltASTCounter; });
   ASSERT_TRUE(S.blockUntilIdle(timeoutSeconds(10)));
   ASSERT_EQ(BuiltASTCounter.load(), 3);
+  EXPECT_THAT(Tracer.takeMetric("ast_access_diag", "hit"), SizeIs(0));
+  EXPECT_THAT(Tracer.takeMetric("ast_access_diag", "miss"), SizeIs(2));
 
   // Check only the last two ASTs are retained.
   ASSERT_THAT(S.getFilesWithCachedAST(), UnorderedElementsAre(Bar, Baz));
@@ -541,6 +550,8 @@ TEST_F(TUSchedulerTests, EvictedAST) {
                      [&BuiltASTCounter]() { ++BuiltASTCounter; });
   ASSERT_TRUE(S.blockUntilIdle(timeoutSeconds(10)));
   ASSERT_EQ(BuiltASTCounter.load(), 4);
+  EXPECT_THAT(Tracer.takeMetric("ast_access_diag", "hit"), SizeIs(0));
+  EXPECT_THAT(Tracer.takeMetric("ast_access_diag", "miss"), SizeIs(1));
 
   // Check the AST for foo.cpp is retained now and one of the others got
   // evicted.
@@ -758,11 +769,16 @@ TEST_F(TUSchedulerTests, ForceRebuild) {
   EXPECT_EQ(DiagCount, 2U);
 }
 TEST_F(TUSchedulerTests, NoChangeDiags) {
+  trace::TestTracer Tracer;
   TUScheduler S(CDB, optsForTest(), captureDiags());
 
   auto FooCpp = testPath("foo.cpp");
-  auto Contents = "int a; int b;";
+  const auto *Contents = "int a; int b;";
 
+  EXPECT_THAT(Tracer.takeMetric("ast_access_read", "hit"), SizeIs(0));
+  EXPECT_THAT(Tracer.takeMetric("ast_access_read", "miss"), SizeIs(0));
+  EXPECT_THAT(Tracer.takeMetric("ast_access_diag", "hit"), SizeIs(0));
+  EXPECT_THAT(Tracer.takeMetric("ast_access_diag", "miss"), SizeIs(0));
   updateWithDiags(
       S, FooCpp, Contents, WantDiagnostics::No,
       [](std::vector<Diag>) { ADD_FAILURE() << "Should not be called."; });
@@ -771,6 +787,8 @@ TEST_F(TUSchedulerTests, NoChangeDiags) {
     cantFail(std::move(IA));
   });
   ASSERT_TRUE(S.blockUntilIdle(timeoutSeconds(10)));
+  EXPECT_THAT(Tracer.takeMetric("ast_access_read", "hit"), SizeIs(0));
+  EXPECT_THAT(Tracer.takeMetric("ast_access_read", "miss"), SizeIs(1));
 
   // Even though the inputs didn't change and AST can be reused, we need to
   // report the diagnostics, as they were not reported previously.
@@ -779,6 +797,8 @@ TEST_F(TUSchedulerTests, NoChangeDiags) {
                   [&](std::vector<Diag>) { SeenDiags = true; });
   ASSERT_TRUE(S.blockUntilIdle(timeoutSeconds(10)));
   ASSERT_TRUE(SeenDiags);
+  EXPECT_THAT(Tracer.takeMetric("ast_access_diag", "hit"), SizeIs(1));
+  EXPECT_THAT(Tracer.takeMetric("ast_access_diag", "miss"), SizeIs(0));
 
   // Subsequent request does not get any diagnostics callback because the same
   // diags have previously been reported and the inputs didn't change.

clang-tools-extra/clangd/unittests/TestTracer.h

@@ -0,0 +1,50 @@
+//===-- TestTracer.h --------------------------------------------*- C++ -*-===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+//
+// Allows setting up a fake tracer for tests.
+//
+//===----------------------------------------------------------------------===//
+
+#ifndef LLVM_CLANG_TOOLS_EXTRA_UNITTESTS_CLANGD_TESTFS_H
+#define LLVM_CLANG_TOOLS_EXTRA_UNITTESTS_CLANGD_TESTFS_H
+
+#include "support/Trace.h"
+#include "llvm/ADT/StringMap.h"
+#include <string>
+#include <utility>
+#include <vector>
+
+namespace clang {
+namespace clangd {
+namespace trace {
+
+/// A RAII Tracer that can be used by tests.
+class TestTracer : public EventTracer {
+public:
+  TestTracer() : Session(*this) {}
+  /// Stores all the measurements to be returned with take later on.
+  void record(const Metric &Metric, double Value,
+              llvm::StringRef Label) override;
+
+  /// Returns recorded measurements for \p Metric and clears them.
+  std::vector<double> take(std::string Metric, std::string Label = "");
+
+private:
+  struct Measure {
+    std::string Label;
+    double Value;
+  };
+  /// Measurements recorded per metric.
+  llvm::StringMap<std::vector<Measure>> Measurements;
+  Session Session;
+};
+
+} // namespace trace
+} // namespace clangd
+} // namespace clang
+#endif

clang-tools-extra/clangd/unittests/support/TestTracer.cpp

@@ -0,0 +1,39 @@
+//===-- TestTracer.cpp - Tracing unit tests ---------------------*- C++ -*-===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+#include "TestTracer.h"
+#include "support/Trace.h"
+#include "llvm/ADT/StringRef.h"
+#include <mutex>
+
+namespace clang {
+namespace clangd {
+namespace trace {
+
+void TestTracer::record(const Metric &Metric, double Value,
+                        llvm::StringRef Label) {
+  std::lock_guard<std::mutex> Lock(Mu);
+  Measurements[Metric.Name][Label].push_back(Value);
+}
+
+std::vector<double> TestTracer::takeMetric(llvm::StringRef Metric,
+                                           llvm::StringRef Label) {
+  std::lock_guard<std::mutex> Lock(Mu);
+  auto LabelsIt = Measurements.find(Metric);
+  if (LabelsIt == Measurements.end())
+    return {};
+  auto &Labels = LabelsIt->getValue();
+  auto ValuesIt = Labels.find(Label);
+  if (ValuesIt == Labels.end())
+    return {};
+  auto Res = std::move(ValuesIt->getValue());
+  ValuesIt->getValue().clear();
+  return Res;
+}
+} // namespace trace
+} // namespace clangd
+} // namespace clang

clang-tools-extra/clangd/unittests/support/TestTracer.h

@@ -0,0 +1,49 @@
+//===-- TestTracer.h --------------------------------------------*- C++ -*-===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+//
+// Allows setting up a fake tracer for tests.
+//
+//===----------------------------------------------------------------------===//
+
+#ifndef LLVM_CLANG_TOOLS_EXTRA_UNITTESTS_CLANGD_SUPPORT_TESTTRACER_H
+#define LLVM_CLANG_TOOLS_EXTRA_UNITTESTS_CLANGD_SUPPORT_TESTTRACER_H
+
+#include "support/Trace.h"
+#include "llvm/ADT/StringMap.h"
+#include "llvm/ADT/StringRef.h"
+#include <mutex>
+#include <string>
+#include <vector>
+
+namespace clang {
+namespace clangd {
+namespace trace {
+
+/// A RAII Tracer that can be used by tests.
+class TestTracer : public EventTracer {
+public:
+  TestTracer() : Session(*this) {}
+  /// Stores all the measurements to be returned with take later on.
+  void record(const Metric &Metric, double Value,
+              llvm::StringRef Label) override;
+
+  /// Returns recorded measurements for \p Metric and clears them.
+  std::vector<double> takeMetric(llvm::StringRef Metric,
+                                 llvm::StringRef Label = "");
+
+private:
+  std::mutex Mu;
+  /// Measurements recorded per metric per label.
+  llvm::StringMap<llvm::StringMap<std::vector<double>>> Measurements;
+  Session Session;
+};
+
+} // namespace trace
+} // namespace clangd
+} // namespace clang
+#endif

clang-tools-extra/clangd/unittests/support/TraceTests.cpp

@@ -6,10 +6,12 @@
 //
 //===----------------------------------------------------------------------===//
 
+#include "support/Context.h"
+#include "support/TestTracer.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"
@@ -20,6 +22,8 @@ namespace clang {
 namespace clangd {
 namespace {
 
+using testing::SizeIs;
+
 MATCHER_P(StringNode, Val, "") {
   if (arg->getType() != llvm::yaml::Node::NK_Scalar) {
     *result_listener << "is a " << arg->getVerbatimTag();
@@ -122,6 +126,18 @@ TEST(TraceTest, SmokeTest) {
   ASSERT_EQ(++Prop, Root->end());
 }
 
+TEST(MetricsTracer, LatencyTest) {
+  trace::TestTracer Tracer;
+  constexpr llvm::StringLiteral MetricName = "span_latency";
+  constexpr llvm::StringLiteral OpName = "op_name";
+  {
+    // A span should record latencies to span_latency by default.
+    trace::Span SpanWithLat(OpName);
+    EXPECT_THAT(Tracer.takeMetric(MetricName, OpName), SizeIs(0));
+  }
+  EXPECT_THAT(Tracer.takeMetric(MetricName, OpName), SizeIs(1));
+}
+
 } // namespace
 } // namespace clangd
 } // namespace clang