diff --git a/clang-tools-extra/clangd/support/Trace.cpp b/clang-tools-extra/clangd/support/Trace.cpp index 6bf4816268e5cc..10ae461221ee3b 100644 --- a/clang-tools-extra/clangd/support/Trace.cpp +++ b/clang-tools-extra/clangd/support/Trace.cpp @@ -189,6 +189,66 @@ class JSONTracer : public EventTracer { 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::steady_clock::now() - Start) + .count(); + std::lock_guard 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> JSONTracer::SpanKey; EventTracer *T = nullptr; @@ -206,6 +266,10 @@ std::unique_ptr createJSONTracer(llvm::raw_ostream &OS, return std::make_unique(OS, Pretty); } +std::unique_ptr createCSVMetricTracer(llvm::raw_ostream &OS) { + return std::make_unique(OS); +} + void log(const llvm::Twine &Message) { if (!T) return; diff --git a/clang-tools-extra/clangd/support/Trace.h b/clang-tools-extra/clangd/support/Trace.h index 90a11bb1feb48a..9dc397a84b7449 100644 --- a/clang-tools-extra/clangd/support/Trace.h +++ b/clang-tools-extra/clangd/support/Trace.h @@ -108,11 +108,18 @@ class 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 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 createCSVMetricTracer(llvm::raw_ostream &OS); + /// Records a single instant event, associated with the current thread. void log(const llvm::Twine &Name); diff --git a/clang-tools-extra/clangd/test/metrics.test b/clang-tools-extra/clangd/test/metrics.test new file mode 100644 index 00000000000000..874a5dad8308f5 --- /dev/null +++ b/clang-tools-extra/clangd/test/metrics.test @@ -0,0 +1,11 @@ +# 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"} diff --git a/clang-tools-extra/clangd/tool/ClangdMain.cpp b/clang-tools-extra/clangd/tool/ClangdMain.cpp index 566430167a517a..e59aecb2d75286 100644 --- a/clang-tools-extra/clangd/tool/ClangdMain.cpp +++ b/clang-tools-extra/clangd/tool/ClangdMain.cpp @@ -539,18 +539,23 @@ clangd accepts flags on the commandline, and in the CLANGD_FLAGS environment var // 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 TraceStream; + llvm::Optional TracerStream; std::unique_ptr 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, - llvm::sys::fs::FA_Read | llvm::sys::fs::FA_Write); + 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); } } diff --git a/clang-tools-extra/clangd/unittests/support/TraceTests.cpp b/clang-tools-extra/clangd/unittests/support/TraceTests.cpp index 10670f79be1b47..cee43f73f211e2 100644 --- a/clang-tools-extra/clangd/unittests/support/TraceTests.cpp +++ b/clang-tools-extra/clangd/unittests/support/TraceTests.cpp @@ -11,6 +11,7 @@ #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" @@ -22,7 +23,11 @@ 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) { @@ -138,6 +143,51 @@ TEST(MetricsTracer, LatencyTest) { 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 outputLines() { + // Deliberately don't flush output stream, the tracer should do that. + // This is important when clangd crashes. + llvm::SmallVector Lines; + llvm::StringRef(Output).split(Lines, "\r\n"); + return {Lines.begin(), Lines.end()}; + } + + std::string Output; + llvm::raw_string_ostream OS; + std::unique_ptr 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