Performance tracing facility for clangd.

Summary: This lets you visualize clangd's activity on different threads over time, and understand critical paths of requests and object lifetimes. The data produced can be visualized in Chrome (at chrome://tracing), or in a standalone copy of catapult (http://github.com/catapult-project/catapult) This patch consists of: - a command line flag "-trace" that causes clangd to emit JSON trace data - an API (in Trace.h) allowing clangd code to easily add events to the stream - several initial uses of this API to capture JSON-RPC requests, builds, logs Example result: https://photos.app.goo.gl/12L9swaz5REGQ1rm1 Caveats: - JSON serialization is ad-hoc (isn't it everywhere?) so the API is limited to naming events rather than attaching arbitrary metadata. I'd like to fix this (I think we could use a JSON-object abstraction). - The recording is very naive: events are written immediately by locking a mutex. Contention on the mutex might disturb performance. - For now it just traces instants or spans on the current thread. There are other things that make sense to show (cross-thread flows, non-thread resources such as ASTs). But we have to start somewhere. Reviewers: ioeric, ilya-biryukov Subscribers: cfe-commits, mgorny Differential Revision: https://reviews.llvm.org/D39086 llvm-svn: 317193
llvm · Nov 2, 2017 · 8567cb3 · 8567cb3
1 parent 6a3ed9b
commit 8567cb3
Show file tree

Hide file tree

Showing 11 changed files with 381 additions and 19 deletions.
diff --git a/clang-tools-extra/clangd/CMakeLists.txt b/clang-tools-extra/clangd/CMakeLists.txt
@@ -13,6 +13,7 @@ add_clang_library(clangDaemon
   Logger.cpp
   Protocol.cpp
   ProtocolHandlers.cpp
+  Trace.cpp
 
   LINK_LIBS
   clangAST

diff --git a/clang-tools-extra/clangd/ClangdServer.cpp b/clang-tools-extra/clangd/ClangdServer.cpp
@@ -15,6 +15,8 @@
 #include "llvm/ADT/ArrayRef.h"
 #include "llvm/Support/Errc.h"
 #include "llvm/Support/FileSystem.h"
+#include "llvm/Support/FormatProviders.h"
+#include "llvm/Support/FormatVariadic.h"
 #include "llvm/Support/Path.h"
 #include "llvm/Support/raw_ostream.h"
 #include <future>
@@ -98,7 +100,8 @@ ClangdScheduler::ClangdScheduler(unsigned AsyncThreadsCount)
 
   Workers.reserve(AsyncThreadsCount);
   for (unsigned I = 0; I < AsyncThreadsCount; ++I) {
-    Workers.push_back(std::thread([this]() {
+    Workers.push_back(std::thread([this, I]() {
+      llvm::set_thread_name(llvm::formatv("scheduler/{0}", I));
       while (true) {
         UniqueFunction<void()> Request;
 

diff --git a/clang-tools-extra/clangd/ClangdUnit.cpp b/clang-tools-extra/clangd/ClangdUnit.cpp
@@ -10,6 +10,7 @@
 #include "ClangdUnit.h"
 
 #include "Logger.h"
+#include "Trace.h"
 #include "clang/Frontend/CompilerInstance.h"
 #include "clang/Frontend/CompilerInvocation.h"
 #include "clang/Frontend/FrontendActions.h"
@@ -1285,6 +1286,7 @@ CppFile::deferRebuild(StringRef NewContents,
         return OldPreamble;
       }
 
+      trace::Span Tracer(llvm::Twine("Preamble: ") + That->FileName);
       std::vector<DiagWithFixIts> PreambleDiags;
       StoreDiagsConsumer PreambleDiagnosticsConsumer(/*ref*/ PreambleDiags);
       IntrusiveRefCntPtr<DiagnosticsEngine> PreambleDiagsEngine =
@@ -1330,9 +1332,13 @@ CppFile::deferRebuild(StringRef NewContents,
     }
 
     // Compute updated AST.
-    llvm::Optional<ParsedAST> NewAST =
-        ParsedAST::Build(std::move(CI), PreambleForAST, SerializedPreambleDecls,
-                         std::move(ContentsBuffer), PCHs, VFS, That->Logger);
+    llvm::Optional<ParsedAST> NewAST;
+    {
+      trace::Span Tracer(llvm::Twine("Build: ") + That->FileName);
+      NewAST = ParsedAST::Build(
+          std::move(CI), PreambleForAST, SerializedPreambleDecls,
+          std::move(ContentsBuffer), PCHs, VFS, That->Logger);
+    }
 
     if (NewAST) {
       Diagnostics.insert(Diagnostics.end(), NewAST->getDiagnostics().begin(),

diff --git a/clang-tools-extra/clangd/JSONRPCDispatcher.cpp b/clang-tools-extra/clangd/JSONRPCDispatcher.cpp
@@ -9,6 +9,7 @@
 
 #include "JSONRPCDispatcher.h"
 #include "ProtocolHandlers.h"
+#include "Trace.h"
 #include "llvm/ADT/SmallString.h"
 #include "llvm/Support/SourceMgr.h"
 #include "llvm/Support/YAMLParser.h"
@@ -32,6 +33,7 @@ void JSONOutput::writeMessage(const Twine &Message) {
 }
 
 void JSONOutput::log(const Twine &Message) {
+  trace::log(Message);
   std::lock_guard<std::mutex> Guard(StreamMutex);
   Logs << Message;
   Logs.flush();
@@ -75,8 +77,10 @@ callHandler(const llvm::StringMap<JSONRPCDispatcher::Handler> &Handlers,
             llvm::yaml::MappingNode *Params,
             const JSONRPCDispatcher::Handler &UnknownHandler, JSONOutput &Out) {
   llvm::SmallString<64> MethodStorage;
-  auto I = Handlers.find(Method->getValue(MethodStorage));
+  llvm::StringRef MethodStr = Method->getValue(MethodStorage);
+  auto I = Handlers.find(MethodStr);
   auto &Handler = I != Handlers.end() ? I->second : UnknownHandler;
+  trace::Span Tracer(MethodStr);
   Handler(RequestContext(Out, Id ? Id->getRawValue() : ""), Params);
 }
 
@@ -206,21 +210,27 @@ void clangd::runLanguageServerLoop(std::istream &In, JSONOutput &Out,
     }
 
     if (ContentLength > 0) {
-      // Now read the JSON. Insert a trailing null byte as required by the YAML
-      // parser.
       std::vector<char> JSON(ContentLength + 1, '\0');
-      In.read(JSON.data(), ContentLength);
-      Out.mirrorInput(StringRef(JSON.data(), In.gcount()));
-
-      // If the stream is aborted before we read ContentLength bytes, In
-      // will have eofbit and failbit set.
-      if (!In) {
-        Out.log("Input was aborted. Read only " + std::to_string(In.gcount()) +
-                " bytes of expected " + std::to_string(ContentLength) + ".\n");
-        break;
+      llvm::StringRef JSONRef;
+      {
+        trace::Span Tracer("Reading request");
+        // Now read the JSON. Insert a trailing null byte as required by the
+        // YAML parser.
+        In.read(JSON.data(), ContentLength);
+        Out.mirrorInput(StringRef(JSON.data(), In.gcount()));
+
+        // If the stream is aborted before we read ContentLength bytes, In
+        // will have eofbit and failbit set.
+        if (!In) {
+          Out.log("Input was aborted. Read only " +
+                  std::to_string(In.gcount()) + " bytes of expected " +
+                  std::to_string(ContentLength) + ".\n");
+          break;
+        }
+
+        JSONRef = StringRef(JSON.data(), ContentLength);
       }
 
-      llvm::StringRef JSONRef(JSON.data(), ContentLength);
       // Log the message.
       Out.log("<-- " + JSONRef + "\n");
 

diff --git a/clang-tools-extra/clangd/ProtocolHandlers.cpp b/clang-tools-extra/clangd/ProtocolHandlers.cpp
@@ -11,6 +11,7 @@
 #include "ClangdLSPServer.h"
 #include "ClangdServer.h"
 #include "DraftStore.h"
+#include "Trace.h"
 
 using namespace clang;
 using namespace clang::clangd;
@@ -30,7 +31,10 @@ struct HandlerRegisterer {
     auto *Callbacks = this->Callbacks;
     Dispatcher.registerHandler(
         Method, [=](RequestContext C, llvm::yaml::MappingNode *RawParams) {
-          if (auto P = std::decay<Param>::type::parse(RawParams, *Out)) {
+          if (auto P = [&] {
+                trace::Span Tracer("Parse");
+                return std::decay<Param>::type::parse(RawParams, *Out);
+              }()) {
             (Callbacks->*Handler)(std::move(C), *P);
           } else {
             Out->log("Failed to decode " + Method + " request.\n");

diff --git a/clang-tools-extra/clangd/Trace.cpp b/clang-tools-extra/clangd/Trace.cpp
@@ -0,0 +1,121 @@
+//===--- Trace.cpp - Performance tracing facilities -----------------------===//
+//
+//                     The LLVM Compiler Infrastructure
+//
+// This file is distributed under the University of Illinois Open Source
+// License. See LICENSE.TXT for details.
+//
+//===----------------------------------------------------------------------===//
+
+#include "Trace.h"
+
+#include "llvm/ADT/DenseSet.h"
+#include "llvm/Support/Chrono.h"
+#include "llvm/Support/FormatProviders.h"
+#include "llvm/Support/FormatVariadic.h"
+#include "llvm/Support/Threading.h"
+#include "llvm/Support/YAMLParser.h"
+#include <mutex>
+
+namespace clang {
+namespace clangd {
+namespace trace {
+using namespace llvm;
+
+namespace {
+// The current implementation is naive: each thread writes to Out guarded by Mu.
+// Perhaps we should replace this by something that disturbs performance less.
+class Tracer {
+public:
+  Tracer(raw_ostream &Out)
+      : Out(Out), Sep(""), Start(std::chrono::system_clock::now()) {
+    // The displayTimeUnit must be ns to avoid low-precision overlap
+    // calculations!
+    Out << R"({"displayTimeUnit":"ns","traceEvents":[)"
+        << "\n";
+    rawEvent("M", R"("name": "process_name", "args":{"name":"clangd"})");
+  }
+
+  ~Tracer() {
+    Out << "\n]}";
+    Out.flush();
+  }
+
+  // Record an event on the current thread. ph, pid, tid, ts are set.
+  // Contents must be a list of the other JSON key/values.
+  template <typename T> void event(StringRef Phase, const T &Contents) {
+    uint64_t TID = get_threadid();
+    std::lock_guard<std::mutex> Lock(Mu);
+    // If we haven't already, emit metadata describing this thread.
+    if (ThreadsWithMD.insert(TID).second) {
+      SmallString<32> Name;
+      get_thread_name(Name);
+      if (!Name.empty()) {
+        rawEvent(
+            "M",
+            formatv(
+                R"("tid": {0}, "name": "thread_name", "args":{"name":"{1}"})",
+                TID, StringRef(&Name[0], Name.size())));
+      }
+    }
+    rawEvent(Phase, formatv(R"("ts":{0}, "tid":{1}, {2})", timestamp(), TID,
+                            Contents));
+  }
+
+private:
+  // Record an event. ph and pid are set.
+  // Contents must be a list of the other JSON key/values.
+  template <typename T>
+  void rawEvent(StringRef Phase, const T &Contents) /*REQUIRES(Mu)*/ {
+    // PID 0 represents the clangd process.
+    Out << Sep << R"({"pid":0, "ph":")" << Phase << "\", " << Contents << "}";
+    Sep = ",\n";
+  }
+
+  double timestamp() {
+    using namespace std::chrono;
+    return duration<double, std::milli>(system_clock::now() - Start).count();
+  }
+
+  std::mutex Mu;
+  raw_ostream &Out /*GUARDED_BY(Mu)*/;
+  const char *Sep /*GUARDED_BY(Mu)*/;
+  DenseSet<uint64_t> ThreadsWithMD /*GUARDED_BY(Mu)*/;
+  const sys::TimePoint<> Start;
+};
+
+static Tracer *T = nullptr;
+} // namespace
+
+std::unique_ptr<Session> Session::create(raw_ostream &OS) {
+  assert(!T && "A session is already active");
+  T = new Tracer(OS);
+  return std::unique_ptr<Session>(new Session());
+}
+
+Session::~Session() {
+  delete T;
+  T = nullptr;
+}
+
+void log(const Twine &Message) {
+  if (!T)
+    return;
+  T->event("i", formatv(R"("name":"{0}")", yaml::escape(Message.str())));
+}
+
+Span::Span(const Twine &Text) {
+  if (!T)
+    return;
+  T->event("B", formatv(R"("name":"{0}")", yaml::escape(Text.str())));
+}
+
+Span::~Span() {
+  if (!T)
+    return;
+  T->event("E", R"("_":0)" /* Dummy property to ensure valid JSON */);
+}
+
+} // namespace trace
+} // namespace clangd
+} // namespace clang
diff --git a/clang-tools-extra/clangd/Trace.h b/clang-tools-extra/clangd/Trace.h
@@ -0,0 +1,61 @@
+//===--- Trace.h - Performance tracing facilities ---------------*- C++ -*-===//
+//
+//                     The LLVM Compiler Infrastructure
+//
+// This file is distributed under the University of Illinois Open Source
+// License. See LICENSE.TXT for details.
+//
+//===----------------------------------------------------------------------===//
+//
+// Supports writing performance traces describing clangd's behavior.
+// Traces are written in the Trace Event format supported by chrome's trace
+// viewer (chrome://tracing).
+//
+// The format is documented here:
+// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview
+//
+// All APIs are no-ops unless a Session is active (created by ClangdMain).
+//
+//===----------------------------------------------------------------------===//
+
+#ifndef LLVM_CLANG_TOOLS_EXTRA_CLANGD_TRACE_H_
+#define LLVM_CLANG_TOOLS_EXTRA_CLANGD_TRACE_H_
+
+#include "llvm/ADT/Twine.h"
+#include "llvm/Support/raw_ostream.h"
+
+namespace clang {
+namespace clangd {
+namespace trace {
+
+// A session directs the output of trace events. Only one Session can exist.
+// It should be created before clangd threads are spawned, and destroyed after
+// they exit.
+// TODO: we may want to add pluggable support for other tracing backends.
+class Session {
+public:
+  // Starts a sessions capturing trace events and writing Trace Event JSON.
+  static std::unique_ptr<Session> create(llvm::raw_ostream &OS);
+  ~Session();
+
+private:
+  Session() = default;
+};
+
+// 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.
+class Span {
+public:
+  Span(const llvm::Twine &Name);
+  ~Span();
+
+private:
+};
+
+} // namespace trace
+} // namespace clangd
+} // namespace clang
+
+#endif // LLVM_CLANG_TOOLS_EXTRA_CLANGD_TRACE_H_
diff --git a/clang-tools-extra/clangd/tool/ClangdMain.cpp b/clang-tools-extra/clangd/tool/ClangdMain.cpp
@@ -10,6 +10,7 @@
 #include "ClangdLSPServer.h"
 #include "JSONRPCDispatcher.h"
 #include "Path.h"
+#include "Trace.h"
 #include "llvm/Support/CommandLine.h"
 #include "llvm/Support/FileSystem.h"
 #include "llvm/Support/Path.h"
@@ -56,6 +57,12 @@ static llvm::cl::opt<Path> InputMirrorFile(
         "Mirror all LSP input to the specified file. Useful for debugging."),
     llvm::cl::init(""), llvm::cl::Hidden);
 
+static llvm::cl::opt<Path> TraceFile(
+    "trace",
+    llvm::cl::desc(
+        "Trace internal events and timestamps in chrome://tracing JSON format"),
+    llvm::cl::init(""), llvm::cl::Hidden);
+
 int main(int argc, char *argv[]) {
   llvm::cl::ParseCommandLineOptions(argc, argv, "clangd");
 
@@ -81,6 +88,18 @@ int main(int argc, char *argv[]) {
                    << EC.message();
     }
   }
+  llvm::Optional<llvm::raw_fd_ostream> TraceStream;
+  std::unique_ptr<trace::Session> TraceSession;
+  if (!TraceFile.empty()) {
+    std::error_code EC;
+    TraceStream.emplace(TraceFile, /*ref*/ EC, llvm::sys::fs::F_RW);
+    if (EC) {
+      TraceFile.reset();
+      llvm::errs() << "Error while opening trace file: " << EC.message();
+    } else {
+      TraceSession = trace::Session::create(*TraceStream);
+    }
+  }
 
   llvm::raw_ostream &Outs = llvm::outs();
   llvm::raw_ostream &Logs = llvm::errs();
@@ -113,7 +132,7 @@ int main(int argc, char *argv[]) {
   // Initialize and run ClangdLSPServer.
   ClangdLSPServer LSPServer(Out, WorkerThreadsCount, EnableSnippets,
                             ResourceDirRef, CompileCommandsDirPath);
-
   constexpr int NoShutdownRequestErrorCode = 1;
+  llvm::set_thread_name("clangd.main");
   return LSPServer.run(std::cin) ? 0 : NoShutdownRequestErrorCode;
 }
diff --git a/clang-tools-extra/test/clangd/trace.test b/clang-tools-extra/test/clangd/trace.test
@@ -0,0 +1,16 @@
+# RUN: clangd -run-synchronously -trace %t < %s && FileCheck %s < %t
+# It is absolutely vital that this file has CRLF line endings.
+#
+Content-Length: 125
+
+{"jsonrpc":"2.0","id":0,"method":"initialize","params":{"processId":123,"rootPath":"clangd","capabilities":{},"trace":"off"}}
+#
+Content-Length: 152
+
+{"jsonrpc":"2.0","method":"textDocument/didOpen","params":{"textDocument":{"uri":"file:///foo.c","languageId":"c","version":1,"text":"void main() {}"}}}
+# CHECK: "textDocument/didOpen"
+# CHECK: "Preamble: /foo.c"
+# CHECK: "Build: /foo.c"
+Content-Length: 44
+
+{"jsonrpc":"2.0","id":5,"method":"shutdown"}