Index: clangd/Trace.h =================================================================== --- clangd/Trace.h +++ clangd/Trace.h @@ -40,6 +40,10 @@ /// 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 before a Span ends. beginSpan() and endSpan() will always form a + // proper stack on a given thread. + // The Context returned by beginSpan is active, but Args is not ready. + virtual void endSpan() {}; /// Called for instant events. virtual void instant(llvm::StringRef Name, json::obj &&Args) = 0; @@ -77,6 +81,7 @@ 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. Index: clangd/Trace.cpp =================================================================== --- clangd/Trace.cpp +++ clangd/Trace.cpp @@ -16,6 +16,7 @@ #include "llvm/Support/FormatProviders.h" #include "llvm/Support/FormatVariadic.h" #include "llvm/Support/Threading.h" +#include #include namespace clang { @@ -46,40 +47,96 @@ 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(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)->EndTime = timestamp(); } 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(); - 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", json::obj{ - {"tid", TID}, - {"name", "thread_name"}, - {"args", json::obj{{"name", Name}}}, - }); - } - } - Contents["ts"] = timestamp(); + 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 Lock(Mu); rawEvent(Phase, std::move(Contents)); } private: + struct JSONSpan { + 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); + } + } + + ~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); + } + + static uint64_t nextID() { + static std::atomic Next = {0}; + return Next++; + } + + const double StartTime; + std::atomic EndTime; // Filled in by endSpan(). + std::string Name; + const uint64_t TID; + JSONTracer *Tracer; + json::obj *Args; + }; + static Key> 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)*/ { @@ -90,6 +147,23 @@ Sep = ",\n"; } + // If we haven't already, emit metadata describing this thread. + void captureThreadMetadata() { + uint64_t TID = get_threadid(); + std::lock_guard 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(system_clock::now() - Start).count(); @@ -103,6 +177,8 @@ const char *JSONFormat; }; +Key> JSONTracer::SpanKey; + EventTracer *T = nullptr; } // namespace @@ -139,6 +215,11 @@ : Args(T ? new json::obj() : nullptr), RestoreCtx(makeSpanContext(Name, Args)) {} +Span::~Span() { + if (T) + T->endSpan(); +} + } // namespace trace } // namespace clangd } // namespace clang Index: test/clangd/trace.test =================================================================== --- test/clangd/trace.test +++ test/clangd/trace.test @@ -2,18 +2,22 @@ {"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"} Index: unittests/clangd/TraceTests.cpp =================================================================== --- unittests/clangd/TraceTests.cpp +++ unittests/clangd/TraceTests.cpp @@ -114,12 +114,10 @@ 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()); }