Performance tracing facility for clangd.

[sammccall]

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.

[ioeric]

Looks good in general. A few nits.

clangd/JSONRPCDispatcher.cpp

230

Why this empty block?

clangd/Trace.cpp

90

Would it make sense to have a helper class which handles starting/stopping in, say, constructor/destructor? ... so that we don't need to worry about forgetting to stop?

clangd/tool/ClangdMain.cpp

98

Is this intended? Start tracing even if there is an error?

unittests/clangd/TraceTests.cpp

47

Add a comment on why we skip unexpected keys?

[sammccall]

Address review comments.

clangd/JSONRPCDispatcher.cpp

230

Oops, was tracing here but it didn't turn out to be useful. Reverted.

clangd/Trace.cpp

90

I didn't do this for a couple of reasons:

• it obscures the static-stateful nature of this code, making it look like e.g. you could dynamically turn on tracing while clangd is running. (Which would be cool, but wouldn't currently work)
• it's some more boilerplate, and isn't actually very convenient to ClangdMain (since start() is conditional)

clangd/tool/ClangdMain.cpp

98

Oops, thanks!

[ioeric]

lgtm

[ilya-biryukov]

clangd/Trace.cpp

88

Maybe use unique_ptr<Tracer> (or even llvm::Optional<Tracer>)? Otherwise we leak memory and don't flush the stream if users of tracing API forget to call stop(). (I think I'm on the same page with @ioeric here about forgetting a call to stop()).

Having a static global of non-pod type is a no-go, but we could use static local variables:

llvm::Optional<Tracer>& getTracerInstance() {
 static llvm::Optional<Tracer> Tracer;
 return Tracer;
}

103

NIT: Use FIXME instead of TODO

[sammccall]

clangd/Trace.cpp

88

So Eric's solution of a scoped object that would be owned by main() makes sense to me, and I'm happy to add it (though personally not sure it carries its weight).

However I don't understand *your* suggestion :-)

Having a static global of non-pod type is a no-go, but we could use static local variables:

llvm::Optional<Tracer>& getTracerInstance() {
  static llvm::Optional<Tracer> Tracer;
  return Tracer;
}

So it's not global, which means we're not calling Optional() on startup, which would actually be totally safe (I guess the constructor should be marked as constexpr).

But we *are* calling ~Optional() and therefore ~Tracer() at shutdown. And maybe ~Tracer() calls something that logs, and llvm::errs() has already been destroyed... *this* is why avoid static objects, right?

Otherwise we leak memory and don't flush the stream if users of tracing API forget to call stop()

The intended time to call stop() is at the end of the program. If you forget to call it, we won't be leaking memory :-) We indeed won't flush the stream, but that wouldn't be safe (see above).

The other option is the user is calling start() and stop() multiple times, and they call start() twice without stopping. We already assert on this, and anyone who doesn't reproducibly hit that assert is well into racy UB-land (logging methods may be called concurrently with each other, but everything else must be synchronized).

Overall I'm not really seeing what scenario we can detect and safely do something about.

[sammccall]

Address FIXME now that r316330 is in.

[ilya-biryukov]

clangd/Trace.cpp

88

Forget what I said, you're right. Tracer has state, can be reconfigured multiple times and there's no guarantee our references won't be dangling on destruction of Tracer.

I do think Eric's solution is good, though. For all the same reasons why RAII is good.

[sammccall]

Provide RAII-like interface to trace functionality.

Note that we may want to provide a backend API here.

[ioeric]

still lgtm

clangd/Trace.h

39

createJSON is a bit confusing... maybe just create since json is just the underlying representation which users don't have to know about?

[sammccall]

createJSON -> create

[sammccall]

clangd/Trace.h

39

I think later we might have an API for non-JSON sessions (crazy google internal tracing tools) but until then, create is a fine name.

[sammccall]

clang-format

[RKSimon]

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

57 ↗

(On Diff #121257)

@sammccall PVS Studio is reporting a potential null dereference here: https://www.viva64.com/en/b/0771/ (Snippet 8)

[kadircet]

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

57 ↗

(On Diff #121257)

Sent out https://github.com/llvm/llvm-project/commit/68b48339e5b2e7c5f9b74e790b4a4e2419a0a50b

clangd/CMakeLists.txt

 set(LLVM_LINK_COMPONENTS
   Support
   )
 
 add_clang_library(clangDaemon
   ClangdLSPServer.cpp
   ClangdServer.cpp
   ClangdUnit.cpp
   ClangdUnitStore.cpp
   DraftStore.cpp
   GlobalCompilationDatabase.cpp
   JSONRPCDispatcher.cpp
   Logger.cpp
   Protocol.cpp
   ProtocolHandlers.cpp
+  Trace.cpp
 
   LINK_LIBS
   clangAST
   clangBasic
   clangFormat
   clangFrontend
   clangIndex
   clangLex
   clangSema
   clangSerialization
   clangTooling
   clangToolingCore
   ${LLVM_PTHREAD_LIB}
   )
 
 add_subdirectory(tool)

clangd/ClangdServer.cpp

 //===--- ClangdServer.cpp - Main clangd server code --------------*- C++-*-===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===-------------------------------------------------------------------===//
 
 #include "ClangdServer.h"
 #include "clang/Format/Format.h"
 #include "clang/Frontend/CompilerInstance.h"
 #include "clang/Frontend/CompilerInvocation.h"
 #include "clang/Tooling/CompilationDatabase.h"
 #include "llvm/ADT/ArrayRef.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>
 
 using namespace clang;
 using namespace clang::clangd;
 
 namespace {
ClangdScheduler::ClangdScheduler(unsigned AsyncThreadsCount)
     : RunSynchronously(AsyncThreadsCount == 0) {
   if (RunSynchronously) {
     // Don't start the worker thread if we're running synchronously
     return;
   }
 
   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;
 
         // Pick request from the queue
         {
           std::unique_lock<std::mutex> Lock(Mutex);
           // Wait for more requests.
           RequestCV.wait(Lock,

clangd/ClangdUnit.cpp

 //===--- ClangdUnit.cpp -----------------------------------------*- C++-*-===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===---------------------------------------------------------------------===//
 
 #include "ClangdUnit.h"
 
 #include "Logger.h"
+#include "Trace.h"
 #include "clang/Frontend/CompilerInstance.h"
 #include "clang/Frontend/CompilerInvocation.h"
 #include "clang/Frontend/FrontendActions.h"
 #include "clang/Frontend/Utils.h"
 #include "clang/Index/IndexDataConsumer.h"
 #include "clang/Index/IndexingAction.h"
 #include "clang/Lex/Lexer.h"
 #include "clang/Lex/MacroInfo.h"
auto FinishRebuild = [OldPreamble, VFS, RequestRebuildCounter, PCHs,
     auto DoRebuildPreamble = [&]() -> std::shared_ptr<const PreambleData> {
       auto Bounds =
           ComputePreambleBounds(*CI->getLangOpts(), ContentsBuffer.get(), 0);
       if (OldPreamble && OldPreamble->Preamble.CanReuse(
                              *CI, ContentsBuffer.get(), Bounds, VFS.get())) {
         return OldPreamble;
       }
 
+      trace::Span Tracer(llvm::Twine("Preamble: ") + That->FileName);
       std::vector<DiagWithFixIts> PreambleDiags;
       StoreDiagsConsumer PreambleDiagnosticsConsumer(/*ref*/ PreambleDiags);
       IntrusiveRefCntPtr<DiagnosticsEngine> PreambleDiagsEngine =
           CompilerInstance::createDiagnostics(
               &CI->getDiagnosticOpts(), &PreambleDiagnosticsConsumer, false);
       CppFilePreambleCallbacks SerializedDeclsCollector;
       auto BuiltPreamble = PrecompiledPreamble::Build(
           *CI, ContentsBuffer.get(), Bounds, *PreambleDiagsEngine, VFS, PCHs,
auto FinishRebuild = [OldPreamble, VFS, RequestRebuildCounter, PCHs,
     if (NewPreamble) {
       PreambleForAST = &NewPreamble->Preamble;
       SerializedPreambleDecls = NewPreamble->TopLevelDeclIDs;
       Diagnostics.insert(Diagnostics.begin(), NewPreamble->Diags.begin(),
                          NewPreamble->Diags.end());
     }
 
     // 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,
+    }
 
     if (NewAST) {
       Diagnostics.insert(Diagnostics.end(), NewAST->getDiagnostics().begin(),
                          NewAST->getDiagnostics().end());
     } else {
       // Don't report even Preamble diagnostics if we coulnd't build AST.
       Diagnostics.clear();
     }

clangd/JSONRPCDispatcher.cpp

 //===--- JSONRPCDispatcher.cpp - Main JSON parser entry point -------------===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 
 #include "JSONRPCDispatcher.h"
 #include "ProtocolHandlers.h"
+#include "Trace.h"
 #include "llvm/ADT/SmallString.h"
 #include "llvm/Support/SourceMgr.h"
 #include "llvm/Support/YAMLParser.h"
 #include <istream>
 
 using namespace clang;
 using namespace clangd;
 
 void JSONOutput::writeMessage(const Twine &Message) {
   llvm::SmallString<128> Storage;
   StringRef M = Message.toStringRef(Storage);
 
   std::lock_guard<std::mutex> Guard(StreamMutex);
   // Log without headers.
   Logs << "--> " << M << '\n';
   Logs.flush();
 
   // Emit message with header.
   Outs << "Content-Length: " << M.size() << "\r\n\r\n" << M;
   Outs.flush();
 }
 
 void JSONOutput::log(const Twine &Message) {
+  trace::log(Message);
   std::lock_guard<std::mutex> Guard(StreamMutex);
   Logs << Message;
   Logs.flush();
 }
 
 void JSONOutput::mirrorInput(const Twine &Message) {
   if (!InputMirror)
     return;

 }
 
 static void
 callHandler(const llvm::StringMap<JSONRPCDispatcher::Handler> &Handlers,
             llvm::yaml::ScalarNode *Method, llvm::yaml::ScalarNode *Id,
             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);
 }
 
 bool JSONRPCDispatcher::call(StringRef Content, JSONOutput &Out) const {
   llvm::SourceMgr SM;
   llvm::yaml::Stream YAMLStream(Content, SM);
 
   auto Doc = YAMLStream.begin();
while (In.good()) {
       } else {
         // An empty line indicates the end of headers.
         // Go ahead and read the JSON.
         break;
       }
     }
 
     if (ContentLength > 0) {
+      std::vector<char> JSON(ContentLength + 1, '\0');
+      llvm::StringRef JSONRef;
+      {
+        trace::Span Tracer("Reading request");
         // 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(JSON.data(), ContentLength);
+        JSONRef = StringRef(JSON.data(), ContentLength);
+      }
+
       // Log the message.
       Out.log("<-- " + JSONRef + "\n");
 
+      {
         // Finally, execute the action for this JSON message.
         if (!Dispatcher.call(JSONRef, Out))
           Out.log("JSON dispatch failed!\n");
+      }
 
       // If we're done, exit the loop.
       if (IsDone)
         break;
     } else {
       Out.log("Warning: Missing Content-Length header, or message has zero "
               "length.\n");
     }
   }
 }

clangd/ProtocolHandlers.cpp

 //===--- ProtocolHandlers.cpp - LSP callbacks -----------------------------===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 
 #include "ProtocolHandlers.h"
 #include "ClangdLSPServer.h"
 #include "ClangdServer.h"
 #include "DraftStore.h"
+#include "Trace.h"
 
 using namespace clang;
 using namespace clang::clangd;
 
 namespace {
 
 // Helper for attaching ProtocolCallbacks methods to a JSONRPCDispatcher.
 // Invoke like: Registerer("foo", &ProtocolCallbacks::onFoo)
 // onFoo should be: void onFoo(Ctx &C, FooParams &Params)
 // FooParams should have a static factory method: parse(yaml::MappingNode*).
 struct HandlerRegisterer {
   template <typename Param>
   void operator()(StringRef Method,
                   void (ProtocolCallbacks::*Handler)(RequestContext, Param)) {
     // Capture pointers by value, as the lambda will outlive this object.
     auto *Out = this->Out;
     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");
           }
         });
   }
 
   JSONRPCDispatcher &Dispatcher;

clangd/Trace.h

+//===--- 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 enabled by start()/stop() (called 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 {
+
+// start()/stop() cannot be called concurrently with tracing APIs.
+// They should be called before threads are spawned, and after they have exited.
+
+// Starts capturing trace events, writing JSON to OS.
+void start(llvm::raw_ostream &OS);
+// Stops capturing trace events, and finalizes partially written JSON objects.
+void stop();
+
+// 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_

clangd/Trace.cpp

+//===--- 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 <mutex>
+#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"
+
+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
+
+void start(raw_ostream &OS) {
+  assert(!T && "start() called twice without stop()");
+  T = new Tracer(OS);
+}
+
+void stop() {
+  delete T;
+  T = nullptr;
+}
+
+void log(const Twine &Message) {
+  if (!T) return;
+  // TODO: remove str() once formatv_object is formatv-able.
+  T->event("i", formatv(R"("name":"{0}")", yaml::escape(Message.str())).str());
+}
+
+Span::Span(const Twine &Text) {
+  if (!T) return;
+  T->event("B", formatv(R"("name":"{0}")", yaml::escape(Text.str())).str());
+}
+
+Span::~Span() {
+  if (!T) return;
+  T->event("E", R"("_":0)" /* Dummy property to ensure valid JSON */);
+}
+
+} // namespace trace
+} // namespace clangd
+} // namespace clang

clangd/tool/ClangdMain.cpp

 //===--- ClangdMain.cpp - clangd server loop ------------------------------===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 
 #include "ClangdLSPServer.h"
 #include "JSONRPCDispatcher.h"
+#include "Trace.h"
 #include "Path.h"
 #include "llvm/Support/CommandLine.h"
 #include "llvm/Support/FileSystem.h"
 #include "llvm/Support/Path.h"
 #include "llvm/Support/Program.h"
 #include "llvm/Support/raw_ostream.h"
 #include <iostream>
 #include <memory>
ResourceDir("resource-dir",
                 llvm::cl::init(""), llvm::cl::Hidden);
 
 static llvm::cl::opt<Path> InputMirrorFile(
     "input-mirror-file",
     llvm::cl::desc(
         "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");
 
   if (!RunSynchronously && WorkerThreadsCount == 0) {
     llvm::errs() << "A number of worker threads cannot be 0. Did you mean to "
                     "specify -run-synchronously?";
     return 1;
   }
if (!InputMirrorFile.empty()) {
     std::error_code EC;
     InputMirrorStream.emplace(InputMirrorFile, /*ref*/ EC, llvm::sys::fs::F_RW);
     if (EC) {
       InputMirrorStream.reset();
       llvm::errs() << "Error while opening an input mirror file: "
                    << EC.message();
     }
   }
+  llvm::Optional<llvm::raw_fd_ostream> TraceStream;
+  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();
+    }
+    trace::start(*TraceStream);
+  }
 
   llvm::raw_ostream &Outs = llvm::outs();
   llvm::raw_ostream &Logs = llvm::errs();
   JSONOutput Out(Outs, Logs,
                  InputMirrorStream ? InputMirrorStream.getPointer() : nullptr);
 
   // If --compile-commands-dir arg was invoked, check value and override default
   // path.
int main(int argc, char *argv[]) {
   llvm::Optional<StringRef> ResourceDirRef = None;
   if (!ResourceDir.empty())
     ResourceDirRef = ResourceDir;
 
   /// Change stdin to binary to not lose \r\n on windows.
   llvm::sys::ChangeStdinToBinary();
 
   /// Initialize and run ClangdLSPServer.
+  {
     ClangdLSPServer LSPServer(Out, WorkerThreadsCount, EnableSnippets,
                               ResourceDirRef, CompileCommandsDirPath);
+    llvm::set_thread_name("clangd.main");
     LSPServer.run(std::cin);
   }
+  trace::stop();
+}

test/clangd/trace.test

+# 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"}

unittests/clangd/CMakeLists.txt

 set(LLVM_LINK_COMPONENTS
   support
   )
 
 get_filename_component(CLANGD_SOURCE_DIR
   ${CMAKE_CURRENT_SOURCE_DIR}/../../clangd REALPATH)
 include_directories(
   ${CLANGD_SOURCE_DIR}
   )
 
 add_extra_unittest(ClangdTests
   ClangdTests.cpp
+  TraceTests.cpp
   )
 
 target_link_libraries(ClangdTests
   clangBasic
   clangDaemon
   clangFormat
   clangFrontend
   clangSema
   clangTooling
   clangToolingCore
   LLVMSupport
   )

unittests/clangd/TraceTests.cpp

+//===-- TraceTests.cpp - Tracing unit tests ---------------------*- C++ -*-===//
+//
+//                     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/DenseMap.h"
+#include "llvm/ADT/SmallString.h"
+#include "llvm/Support/SourceMgr.h"
+#include "llvm/Support/YAMLParser.h"
+#include "gtest/gtest.h"
+#include "gmock/gmock.h"
+
+namespace clang {
+namespace clangd {
+namespace {
+using namespace llvm;
+
+MATCHER_P(StringNode, Val, "") {
+  if (arg->getType() != yaml::Node::NK_Scalar) {
+    *result_listener << "is a " << arg->getVerbatimTag();
+    return false;
+  }
+  SmallString<32> S;
+  return Val == static_cast<yaml::ScalarNode*>(arg)->getValue(S);
+}
+
+// Checks that N is a Mapping (JS object) with the expected scalar properties.
+bool VerifyObject(yaml::Node &N, std::map<std::string, std::string> Expected) {
+  auto* M = dyn_cast<yaml::MappingNode>(&N);
+  if (!M) {
+    ADD_FAILURE() << "Not an object";
+    return false;
+  }
+  bool Match = true;
+  SmallString<32> Tmp;
+  for (auto Prop : *M) {
+    auto* K = dyn_cast_or_null<yaml::ScalarNode>(Prop.getKey());
+    if (!K) continue;
+    std::string KS = K->getValue(Tmp).str();
+    auto I = Expected.find(KS);
+    if (I == Expected.end()) continue;
+
+    auto* V = dyn_cast_or_null<yaml::ScalarNode>(Prop.getValue());
+    if (!V) {
+      ADD_FAILURE() << KS << " is not a string";
+      Match = false;
+    }
+    std::string VS = V->getValue(Tmp).str();
+    if (VS != I->second) {
+      ADD_FAILURE() << KS << " expected " << I->second << " but actual " << VS;
+      Match = false;
+    }
+    Expected.erase(I);
+  }
+  for (const auto& P : Expected) {
+    ADD_FAILURE() << P.first << " missing, expected " << P.second;
+    Match = false;
+  }
+  return Match;
+}
+
+TEST(TraceTest, SmokeTest) {
+  // Capture some events.
+  std::string JSON;
+  raw_string_ostream OS(JSON);
+  trace::start(OS);
+  {
+    trace::Span S("A");
+    trace::log("B");
+  }
+  trace::stop();
+
+  // Get the root JSON object using the YAML parser.
+  SourceMgr SM;
+  yaml::Stream Stream(JSON, SM);
+  auto Doc = Stream.begin();
+  ASSERT_NE(Doc, Stream.end());
+  auto* Root = dyn_cast_or_null<yaml::MappingNode>(Doc->getRoot());
+  ASSERT_NE(Root, nullptr) << "Root should be an object";
+
+  // We expect in order:
+  //   displayTimeUnit: "ns"
+  //   traceEvents: [process name, thread name, start span, log, end span]
+  // (The order doesn't matter, but the YAML parser is awkward to use otherwise)
+  auto Prop = Root->begin();
+  ASSERT_NE(Prop, Root->end()) << "Expected displayTimeUnit property";
+  ASSERT_THAT(Prop->getKey(), StringNode("displayTimeUnit"));
+  EXPECT_THAT(Prop->getValue(), StringNode("ns"));
+  ASSERT_NE(++Prop, Root->end()) << "Expected traceEvents property";
+  EXPECT_THAT(Prop->getKey(), StringNode("traceEvents"));
+  auto* Events = dyn_cast_or_null<yaml::SequenceNode>(Prop->getValue());
+  ASSERT_NE(Events, nullptr) << "traceEvents should be an array";
+  auto Event = Events->begin();
+  ASSERT_NE(Event, Events->end()) << "Expected process name";
+  EXPECT_TRUE(VerifyObject(*Event, {{"ph", "M"}, {"name", "process_name"}}));
+  ASSERT_NE(++Event, Events->end()) << "Expected thread name";
+  EXPECT_TRUE(VerifyObject(*Event, {{"ph", "M"}, {"name", "thread_name"}}));
+  ASSERT_NE(++Event, Events->end()) << "Expected span start";
+  EXPECT_TRUE(VerifyObject(*Event, {{"ph", "B"}, {"name", "A"}}));
+  ASSERT_NE(++Event, Events->end()) << "Expected log message";
+  EXPECT_TRUE(VerifyObject(*Event, {{"ph", "i"}, {"name", "B"}}));
+  ASSERT_NE(++Event, Events->end()) << "Expected span end";
+  EXPECT_TRUE(VerifyObject(*Event, {{"ph", "E"}}));
+  ASSERT_EQ(++Event, Events->end());
+  ASSERT_EQ(++Prop, Root->end());
+}
+
+} // namespace
+} // namespace clangd
+} // namespace clang