[clang-tools-extra] r318928 - [clangd] Tracing improvements
Sam McCall via cfe-commits
cfe-commits at lists.llvm.org
Thu Nov 23 09:12:04 PST 2017
Author: sammccall
Date: Thu Nov 23 09:12:04 2017
New Revision: 318928
URL: http://llvm.org/viewvc/llvm-project?rev=318928&view=rev
Log:
[clangd] Tracing improvements
Summary:
[clangd] Tracing improvements
Compose JSON using JSONExpr
Allow attaching metadata to spans (and avoid it if tracing is off)
Attach IDs and responses of JSON RPCs to their spans
The downside is that large responses make the trace viewer sluggish.
We should make our responses less huge :-) Or fix trace viewer.
Reviewers: ilya-biryukov
Subscribers: cfe-commits
Differential Revision: https://reviews.llvm.org/D40132
Modified:
clang-tools-extra/trunk/clangd/ClangdUnit.cpp
clang-tools-extra/trunk/clangd/JSONRPCDispatcher.cpp
clang-tools-extra/trunk/clangd/JSONRPCDispatcher.h
clang-tools-extra/trunk/clangd/Trace.cpp
clang-tools-extra/trunk/clangd/Trace.h
clang-tools-extra/trunk/clangd/tool/ClangdMain.cpp
clang-tools-extra/trunk/test/clangd/trace.test
clang-tools-extra/trunk/unittests/clangd/TraceTests.cpp
Modified: clang-tools-extra/trunk/clangd/ClangdUnit.cpp
URL: http://llvm.org/viewvc/llvm-project/clang-tools-extra/trunk/clangd/ClangdUnit.cpp?rev=318928&r1=318927&r2=318928&view=diff
==============================================================================
--- clang-tools-extra/trunk/clangd/ClangdUnit.cpp (original)
+++ clang-tools-extra/trunk/clangd/ClangdUnit.cpp Thu Nov 23 09:12:04 2017
@@ -1293,7 +1293,8 @@ CppFile::deferRebuild(StringRef NewConte
// (if there are no other references to it).
OldPreamble.reset();
- trace::Span Tracer(llvm::Twine("Preamble: ") + That->FileName);
+ trace::Span Tracer("Preamble");
+ SPAN_ATTACH(Tracer, "File", That->FileName);
std::vector<DiagWithFixIts> PreambleDiags;
StoreDiagsConsumer PreambleDiagnosticsConsumer(/*ref*/ PreambleDiags);
IntrusiveRefCntPtr<DiagnosticsEngine> PreambleDiagsEngine =
@@ -1342,7 +1343,8 @@ CppFile::deferRebuild(StringRef NewConte
// Compute updated AST.
llvm::Optional<ParsedAST> NewAST;
{
- trace::Span Tracer(llvm::Twine("Build: ") + That->FileName);
+ trace::Span Tracer("Build");
+ SPAN_ATTACH(Tracer, "File", That->FileName);
NewAST = ParsedAST::Build(
std::move(CI), PreambleForAST, SerializedPreambleDecls,
std::move(ContentsBuffer), PCHs, VFS, That->Logger);
Modified: clang-tools-extra/trunk/clangd/JSONRPCDispatcher.cpp
URL: http://llvm.org/viewvc/llvm-project/clang-tools-extra/trunk/clangd/JSONRPCDispatcher.cpp?rev=318928&r1=318927&r2=318928&view=diff
==============================================================================
--- clang-tools-extra/trunk/clangd/JSONRPCDispatcher.cpp (original)
+++ clang-tools-extra/trunk/clangd/JSONRPCDispatcher.cpp Thu Nov 23 09:12:04 2017
@@ -59,6 +59,7 @@ void RequestContext::reply(json::Expr &&
Out.log("Attempted to reply to a notification!\n");
return;
}
+ SPAN_ATTACH(tracer(), "Reply", Result);
Out.writeMessage(json::obj{
{"jsonrpc", "2.0"},
{"id", *ID},
@@ -69,6 +70,9 @@ void RequestContext::reply(json::Expr &&
void RequestContext::replyError(ErrorCode code,
const llvm::StringRef &Message) {
Out.log("Error " + Twine(static_cast<int>(code)) + ": " + Message + "\n");
+ SPAN_ATTACH(tracer(), "Error",
+ (json::obj{{"code", static_cast<int>(code)},
+ {"message", Message.str()}}));
if (ID) {
Out.writeMessage(json::obj{
{"jsonrpc", "2.0"},
@@ -82,6 +86,8 @@ void RequestContext::replyError(ErrorCod
void RequestContext::call(StringRef Method, json::Expr &&Params) {
// FIXME: Generate/Increment IDs for every request so that we can get proper
// replies once we need to.
+ SPAN_ATTACH(tracer(), "Call",
+ (json::obj{{"method", Method.str()}, {"params", Params}}));
Out.writeMessage(json::obj{
{"jsonrpc", "2.0"},
{"id", 1},
@@ -104,8 +110,7 @@ callHandler(const llvm::StringMap<JSONRP
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, std::move(ID)), Params);
+ Handler(RequestContext(Out, MethodStr, std::move(ID)), Params);
}
bool JSONRPCDispatcher::call(StringRef Content, JSONOutput &Out) const {
@@ -249,7 +254,6 @@ void clangd::runLanguageServerLoop(std::
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.
In.read(JSON.data(), ContentLength);
Modified: clang-tools-extra/trunk/clangd/JSONRPCDispatcher.h
URL: http://llvm.org/viewvc/llvm-project/clang-tools-extra/trunk/clangd/JSONRPCDispatcher.h?rev=318928&r1=318927&r2=318928&view=diff
==============================================================================
--- clang-tools-extra/trunk/clangd/JSONRPCDispatcher.h (original)
+++ clang-tools-extra/trunk/clangd/JSONRPCDispatcher.h Thu Nov 23 09:12:04 2017
@@ -13,6 +13,7 @@
#include "JSONExpr.h"
#include "Logger.h"
#include "Protocol.h"
+#include "Trace.h"
#include "clang/Basic/LLVM.h"
#include "llvm/ADT/SmallString.h"
#include "llvm/ADT/StringMap.h"
@@ -55,8 +56,13 @@ private:
/// Context object passed to handlers to allow replies.
class RequestContext {
public:
- RequestContext(JSONOutput &Out, llvm::Optional<json::Expr> ID)
- : Out(Out), ID(std::move(ID)) {}
+ RequestContext(JSONOutput &Out, StringRef Method,
+ llvm::Optional<json::Expr> ID)
+ : Out(Out), ID(std::move(ID)),
+ Tracer(llvm::make_unique<trace::Span>(Method)) {
+ if (this->ID)
+ SPAN_ATTACH(tracer(), "ID", *this->ID);
+ }
/// Sends a successful reply.
void reply(json::Expr &&Result);
@@ -65,9 +71,12 @@ public:
/// Sends a request to the client.
void call(llvm::StringRef Method, json::Expr &&Params);
+ trace::Span &tracer() { return *Tracer; }
+
private:
JSONOutput &Out;
llvm::Optional<json::Expr> ID;
+ std::unique_ptr<trace::Span> Tracer;
};
/// Main JSONRPC entry point. This parses the JSONRPC "header" and calls the
Modified: clang-tools-extra/trunk/clangd/Trace.cpp
URL: http://llvm.org/viewvc/llvm-project/clang-tools-extra/trunk/clangd/Trace.cpp?rev=318928&r1=318927&r2=318928&view=diff
==============================================================================
--- clang-tools-extra/trunk/clangd/Trace.cpp (original)
+++ clang-tools-extra/trunk/clangd/Trace.cpp Thu Nov 23 09:12:04 2017
@@ -27,13 +27,17 @@ namespace {
// 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()) {
+ Tracer(raw_ostream &Out, bool Pretty)
+ : Out(Out), Sep(""), Start(std::chrono::system_clock::now()),
+ JSONFormat(Pretty ? "{0:2}" : "{0}") {
// 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"})");
+ rawEvent("M", json::obj{
+ {"name", "process_name"},
+ {"args", json::obj{{"name", "clangd"}}},
+ });
}
~Tracer() {
@@ -43,7 +47,7 @@ public:
// 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) {
+ void event(StringRef Phase, json::obj &&Contents) {
uint64_t TID = get_threadid();
std::lock_guard<std::mutex> Lock(Mu);
// If we haven't already, emit metadata describing this thread.
@@ -51,24 +55,26 @@ public:
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("M", json::obj{
+ {"tid", TID},
+ {"name", "thread_name"},
+ {"args", json::obj{{"name", Name}}},
+ });
}
}
- rawEvent(Phase, formatv(R"("ts":{0}, "tid":{1}, {2})", timestamp(), TID,
- Contents));
+ Contents["ts"] = timestamp();
+ Contents["tid"] = TID;
+ rawEvent(Phase, std::move(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)*/ {
+ void rawEvent(StringRef Phase, json::obj &&Event) /*REQUIRES(Mu)*/ {
// PID 0 represents the clangd process.
- Out << Sep << R"({"pid":0, "ph":")" << Phase << "\", " << Contents << "}";
+ Event["pid"] = 0;
+ Event["ph"] = Phase;
+ Out << Sep << formatv(JSONFormat, json::Expr(std::move(Event)));
Sep = ",\n";
}
@@ -82,14 +88,15 @@ private:
const char *Sep /*GUARDED_BY(Mu)*/;
DenseSet<uint64_t> ThreadsWithMD /*GUARDED_BY(Mu)*/;
const sys::TimePoint<> Start;
+ const char *JSONFormat;
};
static Tracer *T = nullptr;
} // namespace
-std::unique_ptr<Session> Session::create(raw_ostream &OS) {
+std::unique_ptr<Session> Session::create(raw_ostream &OS, bool Pretty) {
assert(!T && "A session is already active");
- T = new Tracer(OS);
+ T = new Tracer(OS, Pretty);
return std::unique_ptr<Session>(new Session());
}
@@ -101,19 +108,25 @@ Session::~Session() {
void log(const Twine &Message) {
if (!T)
return;
- T->event("i", formatv(R"("name":"{0}")", yaml::escape(Message.str())));
+ T->event("i", json::obj{
+ {"name", "Log"},
+ {"args", json::obj{{"Message", Message.str()}}},
+ });
}
-Span::Span(const Twine &Text) {
+Span::Span(std::string Name) {
if (!T)
return;
- T->event("B", formatv(R"("name":"{0}")", yaml::escape(Text.str())));
+ T->event("B", json::obj{{"name", std::move(Name)}});
+ Args = llvm::make_unique<json::obj>();
}
Span::~Span() {
if (!T)
return;
- T->event("E", R"("_":0)" /* Dummy property to ensure valid JSON */);
+ if (!Args)
+ Args = llvm::make_unique<json::obj>();
+ T->event("E", Args ? json::obj{{"args", std::move(*Args)}} : json::obj{});
}
} // namespace trace
Modified: clang-tools-extra/trunk/clangd/Trace.h
URL: http://llvm.org/viewvc/llvm-project/clang-tools-extra/trunk/clangd/Trace.h?rev=318928&r1=318927&r2=318928&view=diff
==============================================================================
--- clang-tools-extra/trunk/clangd/Trace.h (original)
+++ clang-tools-extra/trunk/clangd/Trace.h Thu Nov 23 09:12:04 2017
@@ -21,6 +21,7 @@
#ifndef LLVM_CLANG_TOOLS_EXTRA_CLANGD_TRACE_H_
#define LLVM_CLANG_TOOLS_EXTRA_CLANGD_TRACE_H_
+#include "JSONExpr.h"
#include "llvm/ADT/Twine.h"
#include "llvm/Support/raw_ostream.h"
@@ -35,7 +36,8 @@ namespace trace {
class Session {
public:
// Starts a sessions capturing trace events and writing Trace Event JSON.
- static std::unique_ptr<Session> create(llvm::raw_ostream &OS);
+ static std::unique_ptr<Session> create(llvm::raw_ostream &OS,
+ bool Pretty = false);
~Session();
private:
@@ -46,14 +48,30 @@ private:
void log(const llvm::Twine &Name);
// Records an event whose duration is the lifetime of the Span object.
+//
+// Arbitrary JSON metadata can be attached while this span is active:
+// SPAN_ATTACH(MySpan, "Payload", SomeJSONExpr);
+// SomeJSONExpr is evaluated and copied only if actually needed.
class Span {
public:
- Span(const llvm::Twine &Name);
+ Span(std::string Name);
~Span();
+ // Returns mutable span metadata if this span is interested.
+ // Prefer to use SPAN_ATTACH rather than accessing this directly.
+ json::obj *args() { return Args.get(); }
+
private:
+ std::unique_ptr<json::obj> Args;
};
+#define SPAN_ATTACH(S, Name, Expr) \
+ do { \
+ if ((S).args() != nullptr) { \
+ (*((S).args()))[(Name)] = (Expr); \
+ } \
+ } while (0)
+
} // namespace trace
} // namespace clangd
} // namespace clang
Modified: clang-tools-extra/trunk/clangd/tool/ClangdMain.cpp
URL: http://llvm.org/viewvc/llvm-project/clang-tools-extra/trunk/clangd/tool/ClangdMain.cpp?rev=318928&r1=318927&r2=318928&view=diff
==============================================================================
--- clang-tools-extra/trunk/clangd/tool/ClangdMain.cpp (original)
+++ clang-tools-extra/trunk/clangd/tool/ClangdMain.cpp Thu Nov 23 09:12:04 2017
@@ -124,7 +124,7 @@ int main(int argc, char *argv[]) {
TraceFile.reset();
llvm::errs() << "Error while opening trace file: " << EC.message();
} else {
- TraceSession = trace::Session::create(*TraceStream);
+ TraceSession = trace::Session::create(*TraceStream, PrettyPrint);
}
}
Modified: clang-tools-extra/trunk/test/clangd/trace.test
URL: http://llvm.org/viewvc/llvm-project/clang-tools-extra/trunk/test/clangd/trace.test?rev=318928&r1=318927&r2=318928&view=diff
==============================================================================
--- clang-tools-extra/trunk/test/clangd/trace.test (original)
+++ clang-tools-extra/trunk/test/clangd/trace.test Thu Nov 23 09:12:04 2017
@@ -1,4 +1,4 @@
-# RUN: clangd -run-synchronously -trace %t < %s && FileCheck %s < %t
+# RUN: clangd -pretty -run-synchronously -trace %t < %s && FileCheck %s < %t
# It is absolutely vital that this file has CRLF line endings.
#
Content-Length: 125
@@ -8,9 +8,19 @@ Content-Length: 125
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"
+# CHECK: {"displayTimeUnit":"ns","traceEvents":[
+# Start opening the doc.
+# CHECK: "name": "textDocument/didOpen"
+# CHECK: "ph": "E"
+# Start building the preamble.
+# CHECK: "name": "Preamble"
+# CHECK: },
+# Finish building the preamble, with filename.
+# CHECK: "File": "/foo.c"
+# CHECK-NEXT: },
+# CHECK-NEXT: "ph": "E"
+# Start building the file.
+# CHECK: "name": "Build"
Content-Length: 44
{"jsonrpc":"2.0","id":5,"method":"shutdown"}
Modified: clang-tools-extra/trunk/unittests/clangd/TraceTests.cpp
URL: http://llvm.org/viewvc/llvm-project/clang-tools-extra/trunk/unittests/clangd/TraceTests.cpp?rev=318928&r1=318927&r2=318928&view=diff
==============================================================================
--- clang-tools-extra/trunk/unittests/clangd/TraceTests.cpp (original)
+++ clang-tools-extra/trunk/unittests/clangd/TraceTests.cpp Thu Nov 23 09:12:04 2017
@@ -116,7 +116,7 @@ TEST(TraceTest, SmokeTest) {
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"}}));
+ EXPECT_TRUE(VerifyObject(*Event, {{"ph", "i"}, {"name", "Log"}}));
ASSERT_NE(++Event, Events->end()) << "Expected span end";
EXPECT_TRUE(VerifyObject(*Event, {{"ph", "E"}}));
ASSERT_EQ(++Event, Events->end());
More information about the cfe-commits
mailing list