sammccall updated this revision to Diff 121247.
sammccall added a comment.
Provide RAII-like interface to trace functionality.
Note that we may want to provide a backend API here.
https://reviews.llvm.org/D39086
Files:
clangd/CMakeLists.txt
clangd/ClangdServer.cpp
clangd/ClangdUnit.cpp
clangd/JSONRPCDispatcher.cpp
clangd/ProtocolHandlers.cpp
clangd/Trace.cpp
clangd/Trace.h
clangd/tool/ClangdMain.cpp
test/clangd/trace.test
unittests/clangd/CMakeLists.txt
unittests/clangd/TraceTests.cpp
Index: unittests/clangd/TraceTests.cpp
===================================================================
--- /dev/null
+++ unittests/clangd/TraceTests.cpp
@@ -0,0 +1,117 @@
+//===-- 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.
+// The object must have all the Expected properties, but may have others.
+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; // Ignore properties with no assertion.
+
+ 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
Index: unittests/clangd/CMakeLists.txt
===================================================================
--- unittests/clangd/CMakeLists.txt
+++ unittests/clangd/CMakeLists.txt
@@ -10,6 +10,7 @@
add_extra_unittest(ClangdTests
ClangdTests.cpp
+ TraceTests.cpp
)
target_link_libraries(ClangdTests
Index: test/clangd/trace.test
===================================================================
--- /dev/null
+++ 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"}
Index: clangd/tool/ClangdMain.cpp
===================================================================
--- clangd/tool/ClangdMain.cpp
+++ clangd/tool/ClangdMain.cpp
@@ -9,6 +9,7 @@
#include "ClangdLSPServer.h"
#include "JSONRPCDispatcher.h"
+#include "Trace.h"
#include "Path.h"
#include "llvm/Support/CommandLine.h"
#include "llvm/Support/FileSystem.h"
@@ -56,6 +57,12 @@
"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 @@
<< 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::createJSON(*TraceStream);
+ }
+ }
llvm::raw_ostream &Outs = llvm::outs();
llvm::raw_ostream &Logs = llvm::errs();
@@ -114,5 +133,6 @@
/// Initialize and run ClangdLSPServer.
ClangdLSPServer LSPServer(Out, WorkerThreadsCount, EnableSnippets,
ResourceDirRef, CompileCommandsDirPath);
+ llvm::set_thread_name("clangd.main");
LSPServer.run(std::cin);
}
Index: clangd/Trace.h
===================================================================
--- /dev/null
+++ 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> createJSON(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_
Index: clangd/Trace.cpp
===================================================================
--- /dev/null
+++ clangd/Trace.cpp
@@ -0,0 +1,118 @@
+//===--- 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
+
+std::unique_ptr<Session> Session::createJSON(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
Index: clangd/ProtocolHandlers.cpp
===================================================================
--- clangd/ProtocolHandlers.cpp
+++ 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 @@
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");
Index: clangd/JSONRPCDispatcher.cpp
===================================================================
--- clangd/JSONRPCDispatcher.cpp
+++ 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::log(const Twine &Message) {
+ trace::log(Message);
std::lock_guard<std::mutex> Guard(StreamMutex);
Logs << Message;
Logs.flush();
@@ -75,8 +77,10 @@
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);
}
@@ -200,21 +204,26 @@
}
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");
Index: clangd/ClangdUnit.cpp
===================================================================
--- clangd/ClangdUnit.cpp
+++ 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"
@@ -1244,6 +1245,7 @@
return OldPreamble;
}
+ trace::Span Tracer(llvm::Twine("Preamble: ") + That->FileName);
std::vector<DiagWithFixIts> PreambleDiags;
StoreDiagsConsumer PreambleDiagnosticsConsumer(/*ref*/ PreambleDiags);
IntrusiveRefCntPtr<DiagnosticsEngine> PreambleDiagsEngine =
@@ -1289,9 +1291,13 @@
}
// 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(),
Index: clangd/ClangdServer.cpp
===================================================================
--- clangd/ClangdServer.cpp
+++ clangd/ClangdServer.cpp
@@ -14,6 +14,8 @@
#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>
@@ -97,7 +99,8 @@
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;
Index: clangd/CMakeLists.txt
===================================================================
--- clangd/CMakeLists.txt
+++ clangd/CMakeLists.txt
@@ -13,6 +13,7 @@
Logger.cpp
Protocol.cpp
ProtocolHandlers.cpp
+ Trace.cpp
LINK_LIBS
clangAST
_______________________________________________
cfe-commits mailing list
cfe-commits@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
