[clangd] Fix tracing now that spans lifetimes can overlap on a thread.

[sammccall]

Summary

The chrome trace viewer requires events within a thread to strictly nest.
So we need to record the lifetime of the Span objects, not the contexts.

But we still want to show the relationship between spans where a context crosses
threads, so do this with flow events (i.e. arrows).

Before: https://photos.app.goo.gl/q4Dd9u9xtelaXk1v1
After: https://photos.app.goo.gl/5RNLmAMLZR3unvY83

(This could stand some further improvement, in particular I think we want a
container span whenever we schedule work on a thread. But that's another patch)

[ilya-biryukov]

LG with a few NITs.

clangd/Trace.cpp

133

Maybe make all fields except EndTime const?

clangd/Trace.h

46

It feels awkward that endSpan() does not have any parameters explicitly connecting it to beginSpan().
We could change beginSpan() to return a callback that would be called when Span ends instead, that would make the connection clear, albeit it's not very useful for JSONTracer.

Not sure we should change it, just thinking out loud :-)

[sammccall]

clangd/Trace.cpp

133

Good idea - what's safe to read vs write wasn't clear.
Ended up just making this a class and encapsulating EndTime instead though.

clangd/Trace.h

46

So destructor-of-context is still the preferred way of observing the end of an event. endSpan() is kind of an attractive nuisance that we need for chrome tracing.

Added comments to explain this.

Given that, I think we want a signature that:

• you basically can't use without first implementing and understanding the primary interface
• can be defaulted to do nothing without interfering with the primary interface (this also gives us backwards compatibility).

I'm not sure think it's a problem that this is a bit obscure...

[sammccall]

address review comments

[CarlosAlbertoEnciso]

Hi,

It seems that your submission have broken the Windows and Linux Builds for 'clangd'.

This is the error message:

/home/xxx/llvm-root/llvm/tools/clang/tools/extra/clangd/Trace.cpp:54:76: error: call of overloaded ‘make_unique(clang::clangd::trace::{anonymous}::JSONTracer*, llvm::StringRef&, clang::clangd::json::obj*&)’ is ambiguous

make_unique<JSONSpan>(this, Name, Args));
                                      ^

Thanks,

[sammccall]

r325239 should fix, sorry!

[CarlosAlbertoEnciso]

In D43272#1008703, @sammccall wrote:

r325239 should fix, sorry!

Build now is OK. Thanks @sammccall.

clangd/Trace.h

public:
   virtual ~EventTracer() = default;
 
   /// Called when event that has a duration starts. \p Name describes the event.
   /// Returns a derived context that will be destroyed when the event ends.
   /// Usually implementations will store an object in the returned context
   /// whose destructor records the end of the event.
   /// The args are *Args, only complete when the event ends.
   virtual Context beginSpan(llvm::StringRef Name, json::obj *Args) = 0;
+  // Called when a Span is destroyed (it may still be active on other threads).
+  // beginSpan() and endSpan() will always form a proper stack on each thread.
+  // The Context returned by beginSpan is active, but Args is not ready.
+  // Tracers should not override this unless they need to observe strict
+  // per-thread nesting. Instead they should observe context destruction.
+  virtual void endSpan() {};
 
   /// Called for instant events.
   virtual void instant(llvm::StringRef Name, json::obj &&Args) = 0;
 };
 
 /// Sets up a global EventTracer that consumes events produced by Span and
 /// trace::log. Only one TracingSession can be active at a time and it should be
 /// set up before calling any clangd-specific functions.

 ///
 /// 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(llvm::StringRef Name);
+  ~Span();
 
   /// Mutable metadata, if this span is interested.
   /// Prefer to use SPAN_ATTACH rather than accessing this directly.
   json::obj *const Args;
 
 private:
   WithContext RestoreCtx;
 };

clangd/Trace.cpp

 #include "Context.h"
 #include "Function.h"
 #include "llvm/ADT/DenseSet.h"
 #include "llvm/ADT/ScopeExit.h"
 #include "llvm/Support/Chrono.h"
 #include "llvm/Support/FormatProviders.h"
 #include "llvm/Support/FormatVariadic.h"
 #include "llvm/Support/Threading.h"
+#include <atomic>
 #include <mutex>
 
 namespace clang {
 namespace clangd {
 namespace trace {
 using namespace llvm;
 
 namespace {
rawEvent("M", json::obj{
                   });
   }
 
   ~JSONTracer() {
     Out << "\n]}";
     Out.flush();
   }
 
+  // We stash a Span object in the context. It will record the start/end,
+  // and this also allows us to look up the parent Span's information.
   Context beginSpan(llvm::StringRef Name, json::obj *Args) override {
-    jsonEvent("B", json::obj{{"name", Name}});
-    return Context::current().derive(make_scope_exit([this, Args] {
-      jsonEvent("E", json::obj{{"args", std::move(*Args)}});
-    }));
+    return Context::current().derive(SpanKey,
+                                     make_unique<JSONSpan>(this, Name, Args));
+  }
+
+  // Trace viewer requires each thread to properly stack events.
+  // So we need to mark only duration that the span was active on the thread.
+  // (Hopefully any off-thread activity will be connected by a flow event).
+  // Record the end time here, but don't write the event: Args aren't ready yet.
+  void endSpan() override {
+    Context::current().getExisting(SpanKey)->markEnded();
   }
 
   void instant(llvm::StringRef Name, json::obj &&Args) override {
+    captureThreadMetadata();
     jsonEvent("i", json::obj{{"name", Name}, {"args", std::move(Args)}});
   }
 
   // Record an event on the current thread. ph, pid, tid, ts are set.
   // Contents must be a list of the other JSON key/values.
-  void jsonEvent(StringRef Phase, json::obj &&Contents) {
-    uint64_t TID = get_threadid();
+  void jsonEvent(StringRef Phase, json::obj &&Contents,
+                 uint64_t TID = get_threadid(),
+                 double Timestamp = 0) {
+    Contents["ts"] = Timestamp ? Timestamp : timestamp();
+    Contents["tid"] = TID;
     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", json::obj{
-                          {"tid", TID},
-                          {"name", "thread_name"},
-                          {"args", json::obj{{"name", Name}}},
-                      });
-      }
+    rawEvent(Phase, std::move(Contents));
+
+private:
+  class JSONSpan {
+  public:
+    JSONSpan(JSONTracer *Tracer, llvm::StringRef Name, json::obj *Args)
+        : StartTime(Tracer->timestamp()), EndTime(0), Name(Name),
+          TID(get_threadid()), Tracer(Tracer), Args(Args) {
+      // ~JSONSpan() may run in a different thread, so we need to capture now.
+      Tracer->captureThreadMetadata();
+
+      // We don't record begin events here (and end events in the destructor)
+      // because B/E pairs have to appear in the right order, which is awkward.
+      // Instead we send the complete (X) event in the destructor.
+
+      // If our parent was on a different thread, add an arrow to this span.
+      auto *Parent = Context::current().get(SpanKey);
+      if (Parent && *Parent && (*Parent)->TID != TID) {
+        // If the parent span ended already, then show this as "following" it.
+        // Otherwise show us as "parallel".
+        double OriginTime = (*Parent)->EndTime;
+        if (!OriginTime)
+          OriginTime = (*Parent)->StartTime;
+
+        auto FlowID = nextID();
+        Tracer->jsonEvent("s",
+                          json::obj{{"id", FlowID},
+                                    {"name", "Context crosses threads"},
+                                    {"cat", "dummy"}},
+                          (*Parent)->TID, (*Parent)->StartTime);
+        Tracer->jsonEvent("f",
+                          json::obj{{"id", FlowID},
+                                    {"bp", "e"},
+                                    {"name", "Context crosses threads"},
+                                    {"cat", "dummy"}},
+                          TID);
       }
-    Contents["ts"] = timestamp();
-    Contents["tid"] = TID;
-    rawEvent(Phase, std::move(Contents));
+    }
+
+    ~JSONSpan() {
+      // Finally, record the event (ending at EndTime, not timestamp())!
+      Tracer->jsonEvent("X",
+                        json::obj{{"name", std::move(Name)},
+                                  {"args", std::move(*Args)},
+                                  {"dur", EndTime - StartTime}},
+                        TID, StartTime);
+    }
+
+    // May be called by any thread.
+    void markEnded() {
+      EndTime = Tracer->timestamp();
     }
 
   private:
+    static uint64_t nextID() {
+      static std::atomic<uint64_t> Next = {0};
+      return Next++;
+    }
+
+    double StartTime;
+    std::atomic<double> EndTime; // Filled in by markEnded().
+    std::string Name;
+    uint64_t TID;
+    JSONTracer *Tracer;
+    json::obj *Args;
+  };
+  static Key<std::unique_ptr<JSONSpan>> SpanKey;
+
   // Record an event. ph and pid are set.
   // Contents must be a list of the other JSON key/values.
   void rawEvent(StringRef Phase, json::obj &&Event) /*REQUIRES(Mu)*/ {
     // PID 0 represents the clangd process.
     Event["pid"] = 0;
     Event["ph"] = Phase;
     Out << Sep << formatv(JSONFormat, json::Expr(std::move(Event)));
     Sep = ",\n";
   }
 
+  // If we haven't already, emit metadata describing this thread.
+  void captureThreadMetadata() {
+    uint64_t TID = get_threadid();
+    std::lock_guard<std::mutex> Lock(Mu);
+    if (ThreadsWithMD.insert(TID).second) {
+      SmallString<32> Name;
+      get_thread_name(Name);
+      if (!Name.empty()) {
+        rawEvent("M", json::obj{
+                          {"tid", TID},
+                          {"name", "thread_name"},
+                          {"args", json::obj{{"name", Name}}},
+                      });
+      }
+    }
+  }
+
   double timestamp() {
     using namespace std::chrono;
     return duration<double, std::micro>(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;
   const char *JSONFormat;
 };
 
+Key<std::unique_ptr<JSONTracer::JSONSpan>> JSONTracer::SpanKey;
+
 EventTracer *T = nullptr;
 } // namespace
 
 Session::Session(EventTracer &Tracer) {
   assert(!T && "Resetting global tracer is not allowed.");
   T = &Tracer;
 }
 

 
 // Span keeps a non-owning pointer to the args, which is how users access them.
 // The args are owned by the context though. They stick around until the
 // beginSpan() context is destroyed, when the tracing engine will consume them.
 Span::Span(llvm::StringRef Name)
     : Args(T ? new json::obj() : nullptr),
       RestoreCtx(makeSpanContext(Name, Args)) {}
 
+Span::~Span() {
+  if (T)
+    T->endSpan();
+}
+
 } // namespace trace
 } // namespace clangd
 } // namespace clang

test/clangd/trace.test

 # RUN: clangd -lit-test -trace %t < %s && FileCheck %s < %t
 {"jsonrpc":"2.0","id":0,"method":"initialize","params":{"processId":123,"rootPath":"clangd","capabilities":{},"trace":"off"}}
 ---
 {"jsonrpc":"2.0","method":"textDocument/didOpen","params":{"textDocument":{"uri":"test:///foo.c","languageId":"c","version":1,"text":"void main() {}"}}}
-#      CHECK: {"displayTimeUnit":"ns","traceEvents":[
-# Start opening the doc.
-#      CHECK: "name": "textDocument/didOpen"
-#      CHECK: "ph": "B"
-# 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"
+# These assertions are a bit loose, to avoid brittleness.
+# CHECK: {"displayTimeUnit":"ns","traceEvents":[
+# CHECK: {
+# CHECK:   "args": {
+# CHECK:     "File": "{{.*(/|\\)}}foo.c"
+# CHECK:   },
+# CHECK:   "name": "Preamble",
+# CHECK:   "ph": "X",
+# CHECK: }
+# CHECK: {
+# CHECK:   "args": {
+# CHECK:     "File": "{{.*(/|\\)}}foo.c"
+# CHECK:   },
+# CHECK:   "name": "Build",
+# CHECK:   "ph": "X",
+# CHECK: }
+# CHECK: },
 ---
 {"jsonrpc":"2.0","id":5,"method":"shutdown"}

unittests/clangd/TraceTests.cpp

TEST(TraceTest, SmokeTest) {
   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"}}));
   if (ThreadsHaveNames) {
     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", "Log"}}));
   ASSERT_NE(++Event, Events->end()) << "Expected span end";
-  EXPECT_TRUE(VerifyObject(*Event, {{"ph", "E"}}));
+  EXPECT_TRUE(VerifyObject(*Event, {{"ph", "X"}, {"name", "A"}}));
   ASSERT_EQ(++Event, Events->end());
   ASSERT_EQ(++Prop, Root->end());
 }
 
 } // namespace
 } // namespace clangd
 } // namespace clang