[clangd] Add CSV export for trace metrics

[sammccall]

Summary

Example: https://docs.google.com/spreadsheets/d/1VZKGetSUTTDe9p4ooIETmdcwUod1_aE3vgD0E9x7HhI/edit

[kadircet]

Thanks, LGTM!

clang-tools-extra/clangd/support/Trace.cpp

210

do we ever expect to have any of \r \n , " in a label? I think it would be OK to just assert notNeedsQuote on Label.

Up to you though.

214

unused var

215

acquire Mu before printing ?

221

why not use integers instead?

251

what are the benefits for making these absolute apart from being able to merge streams coming from different runs?
I am not sure if we'll ever merge data from multiple users, or even multiple runs from the same user.

This would help decrease output size only by a couple percents though, so not that important. Just wondering if there are any other reasons.

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

183

nit: maybe have a getLines() in the fixture.

[sammccall]

clang-tools-extra/clangd/support/Trace.cpp

210

I don't think it's terribly likely but I can certainly imagine:

• using a filename as a label, and some people have weird filenames
• wanting a compound label, and choosing comma as a separator

I was torn between:

• doing the escaping (seems a little silly)
• asserting (a bit of a time bomb in cases above)
• just ignoring this and outputting garbage

Chose A because it's pretty short, and I wrote a test :-)

251

Yeah no good reason I think. Removed.
Was thinking about converting into walltimes in analysis but it seems unlikely.

[sammccall]

Address comments

[thakis]

This broke tests on Windows: http://45.33.8.238/win/15539/step_9.txt

Please take a look, and revert if it takes a while to investigate.

(I'll note that the presubmit bot now has a win/msvc bot that failed compile and reported this on this review before it got merged: https://reviews.llvm.org/B56290 . the bot i linked to builds with clang. i'm guessing the msvc bot would also fail tests once the compile is fixed there.)

clang-tools-extra/clangd/support/Trace.h

 public:
   Session(EventTracer &Tracer);
   ~Session();
 };
 
 /// Create an instance of EventTracer that produces an output in the Trace Event
 /// format supported by Chrome's trace viewer (chrome://tracing).
 ///
+/// FIXME: Metrics are not recorded, some could become counter events.
+///
 /// The format is documented here:
 /// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview
 std::unique_ptr<EventTracer> createJSONTracer(llvm::raw_ostream &OS,
                                               bool Pretty = false);
 
+/// Create an instance of EventTracer that outputs metric measurements as CSV.
+///
+/// Trace spans and instant events are ignored.
+std::unique_ptr<EventTracer> createCSVMetricTracer(llvm::raw_ostream &OS);
+
 /// Records a single instant event, associated with the current thread.
 void log(const llvm::Twine &Name);
 
 /// Records an event whose duration is the lifetime of the Span object.
 /// This lifetime is extended when the span's context is reused.
 ///
 /// This is the main public interface for producing tracing events.
 ///

clang-tools-extra/clangd/support/Trace.cpp

private:
   }
 
   std::mutex Mu;
   llvm::json::OStream Out /*GUARDED_BY(Mu)*/;
   llvm::DenseSet<uint64_t> ThreadsWithMD /*GUARDED_BY(Mu)*/;
   const llvm::sys::TimePoint<> Start;
 };
 
+// We emit CSV as specified in RFC 4180: https://www.ietf.org/rfc/rfc4180.txt.
+// \r\n line endings are used, cells with \r\n," are quoted, quotes are doubled.
+class CSVMetricTracer : public EventTracer {
+public:
+  CSVMetricTracer(llvm::raw_ostream &Out) : Out(Out) {
+    Start = std::chrono::steady_clock::now();
+
+    Out.SetUnbuffered(); // We write each line atomically.
+    Out << "Kind,Metric,Label,Value,Timestamp\r\n";
+  }
+
+  void record(const Metric &Metric, double Value,
+              llvm::StringRef Label) override {
+    assert(!needsQuote(Metric.Name));
+    std::string QuotedLabel;
+    if (needsQuote(Label))
+      Label = QuotedLabel = quote(Label);
+    uint64_t Micros = std::chrono::duration_cast<std::chrono::microseconds>(
+                          std::chrono::steady_clock::now() - Start)
+                          .count();
+    std::lock_guard<std::mutex> Lock(Mu);
+    Out << llvm::formatv("{0},{1},{2},{3:e},{4}.{5:6}\r\n",
+                         typeName(Metric.Type), Metric.Name, Label, Value,
+                         Micros / 1000000, Micros % 1000000);
+  }
+
+private:
+  llvm::StringRef typeName(Metric::MetricType T) {
+    switch (T) {
+    case Metric::Value:
+      return "v";
+    case Metric::Counter:
+      return "c";
+    case Metric::Distribution:
+      return "d";
+    }
+  }
+
+  static bool needsQuote(llvm::StringRef Text) {
+    // https://www.ietf.org/rfc/rfc4180.txt section 2.6
+    return Text.find_first_of(",\"\r\n") != llvm::StringRef::npos;
+  }
+
+  std::string quote(llvm::StringRef Text) {
+    std::string Result = "\"";
+    for (char C : Text) {
+      Result.push_back(C);
+      if (C == '"')
+        Result.push_back('"');
+    }
+    Result.push_back('"');
+    return Result;
+  }
+
+private:
+  std::mutex Mu;
+  llvm::raw_ostream &Out /*GUARDED_BY(Mu)*/;
+  std::chrono::steady_clock::time_point Start;
+};
+
 Key<std::unique_ptr<JSONTracer::JSONSpan>> JSONTracer::SpanKey;
 
 EventTracer *T = nullptr;
 } // namespace
 
 Session::Session(EventTracer &Tracer) {
   assert(!T && "Resetting global tracer is not allowed.");
   T = &Tracer;
 }
 
 Session::~Session() { T = nullptr; }
 
 std::unique_ptr<EventTracer> createJSONTracer(llvm::raw_ostream &OS,
                                               bool Pretty) {
   return std::make_unique<JSONTracer>(OS, Pretty);
 }
 
+std::unique_ptr<EventTracer> createCSVMetricTracer(llvm::raw_ostream &OS) {
+  return std::make_unique<CSVMetricTracer>(OS);
+}
+
 void log(const llvm::Twine &Message) {
   if (!T)
     return;
   T->instant("Log", llvm::json::Object{{"Message", Message.str()}});
 }
 
 // Returned context owns Args.
 static Context makeSpanContext(llvm::Twine Name, llvm::json::Object *Args,

clang-tools-extra/clangd/test/metrics.test

+# RUN: env CLANGD_METRICS=%t clangd -lit-test < %s && FileCheck %s < %t
+{"jsonrpc":"2.0","id":0,"method":"initialize","params":{"processId":123,"rootPath":"clangd","capabilities":{},"trace":"off"}}
+---
+{"jsonrpc":"2.0","method":"textDocument/didOpen","params":{"textDocument":{"uri":"test:///foo.c","languageId":"c","version":1,"text":"void main() {}"}}}
+# Don't verify value, timestamp, or order.
+# CHECK-DAG: d,lsp_latency,textDocument/didOpen,
+# CHECK-DAG: c,ast_access_diag,miss,
+---
+{"jsonrpc":"2.0","id":5,"method":"shutdown"}
+---
+{"jsonrpc":"2.0","method":"exit"}

clang-tools-extra/clangd/tool/ClangdMain.cpp

if (!InputMirrorFile.empty()) {
     } else {
       InputMirrorStream->SetUnbuffered();
     }
   }
 
   // Setup tracing facilities if CLANGD_TRACE is set. In practice enabling a
   // trace flag in your editor's config is annoying, launching with
   // `CLANGD_TRACE=trace.json vim` is easier.
-  llvm::Optional<llvm::raw_fd_ostream> TraceStream;
+  llvm::Optional<llvm::raw_fd_ostream> TracerStream;
   std::unique_ptr<trace::EventTracer> Tracer;
-  if (auto *TraceFile = getenv("CLANGD_TRACE")) {
+  const char *JSONTraceFile = getenv("CLANGD_TRACE");
+  const char *MetricsCSVFile = getenv("CLANGD_METRICS");
+  const char *TracerFile = JSONTraceFile ? JSONTraceFile : MetricsCSVFile;
+  if (TracerFile) {
     std::error_code EC;
-    TraceStream.emplace(TraceFile, /*ref*/ EC,
+    TracerStream.emplace(TracerFile, /*ref*/ EC,
                          llvm::sys::fs::FA_Read | llvm::sys::fs::FA_Write);
     if (EC) {
-      TraceStream.reset();
-      llvm::errs() << "Error while opening trace file " << TraceFile << ": "
+      TracerStream.reset();
+      llvm::errs() << "Error while opening trace file " << TracerFile << ": "
                    << EC.message();
     } else {
-      Tracer = trace::createJSONTracer(*TraceStream, PrettyPrint);
+      Tracer = (TracerFile == JSONTraceFile)
+                   ? trace::createJSONTracer(*TracerStream, PrettyPrint)
+                   : trace::createCSVMetricTracer(*TracerStream);
     }
   }
 
   llvm::Optional<trace::Session> TracingSession;
   if (Tracer)
     TracingSession.emplace(*Tracer);
 
   // If a user ran `clangd` in a terminal without redirecting anything,

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

 //===-- TraceTests.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/Context.h"
 #include "support/Trace.h"
 #include "llvm/ADT/DenseMap.h"
 #include "llvm/ADT/SmallString.h"
+#include "llvm/ADT/StringExtras.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/Support/SourceMgr.h"
 #include "llvm/Support/Threading.h"
 #include "llvm/Support/YAMLParser.h"
 #include "gmock/gmock.h"
 #include "gtest/gtest.h"
 
 namespace clang {
 namespace clangd {
 namespace {
 
+using testing::_;
+using testing::ElementsAre;
+using testing::MatchesRegex;
 using testing::SizeIs;
+using testing::StartsWith;
 
 MATCHER_P(StringNode, Val, "") {
   if (arg->getType() != llvm::yaml::Node::NK_Scalar) {
     *result_listener << "is a " << arg->getVerbatimTag();
     return false;
   }
   llvm::SmallString<32> S;
   return Val == static_cast<llvm::yaml::ScalarNode *>(arg)->getValue(S);
TEST(MetricsTracer, LatencyTest) {
   {
     // 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));
 }
 
+class CSVMetricsTracerTest : public ::testing::Test {
+protected:
+  CSVMetricsTracerTest()
+      : OS(Output), Tracer(trace::createCSVMetricTracer(OS)), Session(*Tracer) {
+  }
+  trace::Metric Dist = {"dist", trace::Metric::Distribution, "lbl"};
+  trace::Metric Counter = {"cnt", trace::Metric::Counter};
+
+  std::vector<llvm::StringRef> outputLines() {
+    // Deliberately don't flush output stream, the tracer should do that.
+    // This is important when clangd crashes.
+    llvm::SmallVector<llvm::StringRef, 4> Lines;
+    llvm::StringRef(Output).split(Lines, "\r\n");
+    return {Lines.begin(), Lines.end()};
+  }
+
+  std::string Output;
+  llvm::raw_string_ostream OS;
+  std::unique_ptr<trace::EventTracer> Tracer;
+  trace::Session Session;
+};
+
+TEST_F(CSVMetricsTracerTest, RecordsValues) {
+  Dist.record(1, "x");
+  Counter.record(1, "");
+  Dist.record(2, "y");
+
+  EXPECT_THAT(
+      outputLines(),
+      ElementsAre("Kind,Metric,Label,Value,Timestamp",
+                  MatchesRegex(R"(d,dist,x,1\.000000e\+00,[0-9]+\.[0-9]{6})"),
+                  StartsWith("c,cnt,,1.000000e+00,"),
+                  StartsWith("d,dist,y,2.000000e+00,"), ""));
+}
+
+TEST_F(CSVMetricsTracerTest, Escaping) {
+  Dist.record(1, ",");
+  Dist.record(1, "a\"b");
+  Dist.record(1, "a\nb");
+
+  EXPECT_THAT(outputLines(), ElementsAre(_, StartsWith(R"(d,dist,",",1)"),
+                                         StartsWith(R"(d,dist,"a""b",1)"),
+                                         StartsWith("d,dist,\"a\nb\",1"), ""));
+}
+
 } // namespace
 } // namespace clangd
 } // namespace clang