Index: clang-tools-extra/trunk/clangd/ClangdUnit.cpp =================================================================== --- clang-tools-extra/trunk/clangd/ClangdUnit.cpp +++ clang-tools-extra/trunk/clangd/ClangdUnit.cpp @@ -1293,7 +1293,8 @@ // (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 PreambleDiags; StoreDiagsConsumer PreambleDiagnosticsConsumer(/*ref*/ PreambleDiags); IntrusiveRefCntPtr PreambleDiagsEngine = @@ -1342,7 +1343,8 @@ // Compute updated AST. llvm::Optional 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); Index: clang-tools-extra/trunk/clangd/JSONRPCDispatcher.h =================================================================== --- clang-tools-extra/trunk/clangd/JSONRPCDispatcher.h +++ clang-tools-extra/trunk/clangd/JSONRPCDispatcher.h @@ -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 @@ /// Context object passed to handlers to allow replies. class RequestContext { public: - RequestContext(JSONOutput &Out, llvm::Optional ID) - : Out(Out), ID(std::move(ID)) {} + RequestContext(JSONOutput &Out, StringRef Method, + llvm::Optional ID) + : Out(Out), ID(std::move(ID)), + Tracer(llvm::make_unique(Method)) { + if (this->ID) + SPAN_ATTACH(tracer(), "ID", *this->ID); + } /// Sends a successful reply. void reply(json::Expr &&Result); @@ -65,9 +71,12 @@ /// Sends a request to the client. void call(llvm::StringRef Method, json::Expr &&Params); + trace::Span &tracer() { return *Tracer; } + private: JSONOutput &Out; llvm::Optional ID; + std::unique_ptr Tracer; }; /// Main JSONRPC entry point. This parses the JSONRPC "header" and calls the Index: clang-tools-extra/trunk/clangd/JSONRPCDispatcher.cpp =================================================================== --- clang-tools-extra/trunk/clangd/JSONRPCDispatcher.cpp +++ clang-tools-extra/trunk/clangd/JSONRPCDispatcher.cpp @@ -59,6 +59,7 @@ 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::replyError(ErrorCode code, const llvm::StringRef &Message) { Out.log("Error " + Twine(static_cast(code)) + ": " + Message + "\n"); + SPAN_ATTACH(tracer(), "Error", + (json::obj{{"code", static_cast(code)}, + {"message", Message.str()}})); if (ID) { Out.writeMessage(json::obj{ {"jsonrpc", "2.0"}, @@ -82,6 +86,8 @@ 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 @@ 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 @@ std::vector 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); Index: clang-tools-extra/trunk/clangd/Trace.h =================================================================== --- clang-tools-extra/trunk/clangd/Trace.h +++ clang-tools-extra/trunk/clangd/Trace.h @@ -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 @@ class Session { public: // Starts a sessions capturing trace events and writing Trace Event JSON. - static std::unique_ptr create(llvm::raw_ostream &OS); + static std::unique_ptr create(llvm::raw_ostream &OS, + bool Pretty = false); ~Session(); private: @@ -46,14 +48,30 @@ 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 Args; }; +#define SPAN_ATTACH(S, Name, Expr) \ + do { \ + if ((S).args() != nullptr) { \ + (*((S).args()))[(Name)] = (Expr); \ + } \ + } while (0) + } // namespace trace } // namespace clangd } // namespace clang Index: clang-tools-extra/trunk/clangd/Trace.cpp =================================================================== --- clang-tools-extra/trunk/clangd/Trace.cpp +++ clang-tools-extra/trunk/clangd/Trace.cpp @@ -27,13 +27,17 @@ // 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 @@ // 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 void event(StringRef Phase, const T &Contents) { + void event(StringRef Phase, json::obj &&Contents) { uint64_t TID = get_threadid(); std::lock_guard Lock(Mu); // If we haven't already, emit metadata describing this thread. @@ -51,24 +55,26 @@ 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 - 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 @@ const char *Sep /*GUARDED_BY(Mu)*/; DenseSet ThreadsWithMD /*GUARDED_BY(Mu)*/; const sys::TimePoint<> Start; + const char *JSONFormat; }; static Tracer *T = nullptr; } // namespace -std::unique_ptr Session::create(raw_ostream &OS) { +std::unique_ptr 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(new Session()); } @@ -101,19 +108,25 @@ 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(); } Span::~Span() { if (!T) return; - T->event("E", R"("_":0)" /* Dummy property to ensure valid JSON */); + if (!Args) + Args = llvm::make_unique(); + T->event("E", Args ? json::obj{{"args", std::move(*Args)}} : json::obj{}); } } // namespace trace Index: clang-tools-extra/trunk/clangd/tool/ClangdMain.cpp =================================================================== --- clang-tools-extra/trunk/clangd/tool/ClangdMain.cpp +++ clang-tools-extra/trunk/clangd/tool/ClangdMain.cpp @@ -124,7 +124,7 @@ TraceFile.reset(); llvm::errs() << "Error while opening trace file: " << EC.message(); } else { - TraceSession = trace::Session::create(*TraceStream); + TraceSession = trace::Session::create(*TraceStream, PrettyPrint); } } Index: clang-tools-extra/trunk/test/clangd/trace.test =================================================================== --- clang-tools-extra/trunk/test/clangd/trace.test +++ clang-tools-extra/trunk/test/clangd/trace.test @@ -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: 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"} Index: clang-tools-extra/trunk/unittests/clangd/TraceTests.cpp =================================================================== --- clang-tools-extra/trunk/unittests/clangd/TraceTests.cpp +++ clang-tools-extra/trunk/unittests/clangd/TraceTests.cpp @@ -116,7 +116,7 @@ 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());