[PATCH] D40132: [clangd] Tracing improvements

[Sam McCall via Phabricator via cfe-commits]

This revision was automatically updated to reflect the committed changes.
Closed by commit rL318928: [clangd] Tracing improvements (authored by 
sammccall).

Repository:
  rL LLVM

https://reviews.llvm.org/D40132

Files:
  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

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());
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,32 +47,34 @@
 
   // 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.
 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("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) 

[PATCH] D40132: [clangd] Tracing improvements

[Ilya Biryukov via Phabricator via cfe-commits]

ilya-biryukov added inline comments.



Comment at: clangd/JSONRPCDispatcher.h:78
   llvm::Optional ID;
+  std::unique_ptr Tracer;
 };

ilya-biryukov wrote:
> sammccall wrote:
> > ilya-biryukov wrote:
> > > Why do we need `unique_ptr`? Are `Span`s non-movable?
> > Spans aren't movable, they have an explicitly declared destructor. (The 
> > copy constructor is only deprecated by this condition, but Span has a 
> > unique_ptr member).
> > 
> > We could make them movable, though it's not absolutely trivial (we need an 
> > extra bool to indicate that this is moved-from and the destructor should be 
> > a no-op).
> > 
> > I think wrapping them in a `unique_ptr` here is slightly simpler than 
> > implementing the right move semantics by hand, but LMK what you think.
> > We could make them movable, though it's not absolutely trivial (we need an 
> > extra bool to indicate that this is moved-from and the destructor should be 
> > a no-op).
> I kinda hate this part when dealing with movable objects, too. I still do 
> that, mostly to avoid heap allocs, but we're not on a hot path, so it's fine 
> both ways.
> We could use `llvm::Optional` instead of `unique_ptr` to get rid of the heap 
> alloc too.
Oh, sorry, `llvm::Optional` surely doesn't help here, it would still be 
non-movable. Forget what I said.


https://reviews.llvm.org/D40132



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

[PATCH] D40132: [clangd] Tracing improvements

[Ilya Biryukov via Phabricator via cfe-commits]

ilya-biryukov accepted this revision.
ilya-biryukov added a comment.
This revision is now accepted and ready to land.

LGTM




Comment at: clangd/JSONRPCDispatcher.h:78
   llvm::Optional ID;
+  std::unique_ptr Tracer;
 };

sammccall wrote:
> ilya-biryukov wrote:
> > Why do we need `unique_ptr`? Are `Span`s non-movable?
> Spans aren't movable, they have an explicitly declared destructor. (The copy 
> constructor is only deprecated by this condition, but Span has a unique_ptr 
> member).
> 
> We could make them movable, though it's not absolutely trivial (we need an 
> extra bool to indicate that this is moved-from and the destructor should be a 
> no-op).
> 
> I think wrapping them in a `unique_ptr` here is slightly simpler than 
> implementing the right move semantics by hand, but LMK what you think.
> We could make them movable, though it's not absolutely trivial (we need an 
> extra bool to indicate that this is moved-from and the destructor should be a 
> no-op).
I kinda hate this part when dealing with movable objects, too. I still do that, 
mostly to avoid heap allocs, but we're not on a hot path, so it's fine both 
ways.
We could use `llvm::Optional` instead of `unique_ptr` to get rid of the heap 
alloc too.



Comment at: clangd/Trace.cpp:50
   // 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();

sammccall wrote:
> ilya-biryukov wrote:
> > Any reason why we use rval-ref instead of accepting by-value?
> Two reasons I prefer this for json::expr/obj/arr:
> 
>  - major: you almost always want to pass a new literal, or move an existing 
> one. Passing a `const Expr &` is usually a mistake, and taking `Expr&&`  
> makes it an error.
>  - minor: expr/obj/arr aren't trivially cheap to move. We forward these 
> around internally, taking && at every level means we only pay for the move 
> constructor once, pass-by-value pays on every call.
Makes sense, thanks for expanding on this. I'll make sure to pass around by 
r-value ref too when dealing with JSON objects.


https://reviews.llvm.org/D40132



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

[PATCH] D40132: [clangd] Tracing improvements

[Sam McCall via Phabricator via cfe-commits]

sammccall added inline comments.



Comment at: clangd/JSONRPCDispatcher.h:78
   llvm::Optional ID;
+  std::unique_ptr Tracer;
 };

ilya-biryukov wrote:
> Why do we need `unique_ptr`? Are `Span`s non-movable?
Spans aren't movable, they have an explicitly declared destructor. (The copy 
constructor is only deprecated by this condition, but Span has a unique_ptr 
member).

We could make them movable, though it's not absolutely trivial (we need an 
extra bool to indicate that this is moved-from and the destructor should be a 
no-op).

I think wrapping them in a `unique_ptr` here is slightly simpler than 
implementing the right move semantics by hand, but LMK what you think.



Comment at: clangd/Trace.cpp:50
   // 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();

ilya-biryukov wrote:
> Any reason why we use rval-ref instead of accepting by-value?
Two reasons I prefer this for json::expr/obj/arr:

 - major: you almost always want to pass a new literal, or move an existing 
one. Passing a `const Expr &` is usually a mistake, and taking `Expr&&`  makes 
it an error.
 - minor: expr/obj/arr aren't trivially cheap to move. We forward these around 
internally, taking && at every level means we only pay for the move constructor 
once, pass-by-value pays on every call.


https://reviews.llvm.org/D40132



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

[PATCH] D40132: [clangd] Tracing improvements

[Sam McCall via Phabricator via cfe-commits]

sammccall updated this revision to Diff 124069.
sammccall marked an inline comment as done.
sammccall added a comment.

Address review comment.


https://reviews.llvm.org/D40132

Files:
  clangd/ClangdUnit.cpp
  clangd/JSONRPCDispatcher.cpp
  clangd/JSONRPCDispatcher.h
  clangd/Trace.cpp
  clangd/Trace.h
  clangd/tool/ClangdMain.cpp
  test/clangd/trace.test
  unittests/clangd/TraceTests.cpp

Index: unittests/clangd/TraceTests.cpp
===
--- unittests/clangd/TraceTests.cpp
+++ 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());
Index: test/clangd/trace.test
===
--- test/clangd/trace.test
+++ 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: clangd/tool/ClangdMain.cpp
===
--- clangd/tool/ClangdMain.cpp
+++ clangd/tool/ClangdMain.cpp
@@ -114,7 +114,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: clangd/Trace.h
===
--- clangd/Trace.h
+++ 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: clangd/Trace.cpp
===
--- clangd/Trace.cpp
+++ 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}" :

[PATCH] D40132: [clangd] Tracing improvements

[Ilya Biryukov via Phabricator via cfe-commits]

ilya-biryukov requested changes to this revision.
ilya-biryukov added a comment.
This revision now requires changes to proceed.

Oops, accidentally accepted the revision.
There are no major issues, but still wanted to learn the reasons we use 
rval-refs and allocate span dynamically.


https://reviews.llvm.org/D40132



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

[PATCH] D40132: [clangd] Tracing improvements

[Ilya Biryukov via Phabricator via cfe-commits]

ilya-biryukov accepted this revision.
ilya-biryukov added inline comments.
This revision is now accepted and ready to land.



Comment at: clangd/JSONRPCDispatcher.h:61
+ llvm::Optional ID)
+  : Out(Out), ID(std::move(ID)), Tracer(new trace::Span(Method)) {
+if (this->ID)

NIT: maybe replace `new` with `llvm::make_unique`?



Comment at: clangd/JSONRPCDispatcher.h:78
   llvm::Optional ID;
+  std::unique_ptr Tracer;
 };

Why do we need `unique_ptr`? Are `Span`s non-movable?



Comment at: clangd/Trace.cpp:50
   // 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();

Any reason why we use rval-ref instead of accepting by-value?


https://reviews.llvm.org/D40132



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

[PATCH] D40132: [clangd] Tracing improvements

[Sam McCall via Phabricator via cfe-commits]

sammccall created this revision.

[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.


https://reviews.llvm.org/D40132

Files:
  clangd/ClangdUnit.cpp
  clangd/JSONRPCDispatcher.cpp
  clangd/JSONRPCDispatcher.h
  clangd/Trace.cpp
  clangd/Trace.h
  clangd/tool/ClangdMain.cpp
  test/clangd/trace.test
  unittests/clangd/TraceTests.cpp

Index: unittests/clangd/TraceTests.cpp
===
--- unittests/clangd/TraceTests.cpp
+++ 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());
Index: test/clangd/trace.test
===
--- test/clangd/trace.test
+++ 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: clangd/tool/ClangdMain.cpp
===
--- clangd/tool/ClangdMain.cpp
+++ clangd/tool/ClangdMain.cpp
@@ -101,7 +101,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: clangd/Trace.h
===
--- clangd/Trace.h
+++ 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: clangd/Trace.cpp
===
--- clangd/Trace.cpp
+++ 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(Ou