1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236
|
//===--- Trace.cpp - Performance tracing facilities -----------------------===//
//
// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
// See https://llvm.org/LICENSE.txt for license information.
// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
//
//===----------------------------------------------------------------------===//
#include "Trace.h"
#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 {
namespace {
// The current implementation is naive: each thread writes to Out guarded by Mu.
// Perhaps we should replace this by something that disturbs performance less.
class JSONTracer : public EventTracer {
public:
JSONTracer(llvm::raw_ostream &OS, bool Pretty)
: Out(OS, Pretty ? 2 : 0), Start(std::chrono::system_clock::now()) {
// The displayTimeUnit must be ns to avoid low-precision overlap
// calculations!
Out.objectBegin();
Out.attribute("displayTimeUnit", "ns");
Out.attributeBegin("traceEvents");
Out.arrayBegin();
rawEvent("M", llvm::json::Object{
{"name", "process_name"},
{"args", llvm::json::Object{{"name", "clangd"}}},
});
}
~JSONTracer() {
Out.arrayEnd();
Out.attributeEnd();
Out.objectEnd();
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, llvm::json::Object *Args) override {
return Context::current().derive(
SpanKey, llvm::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, llvm::json::Object &&Args) override {
captureThreadMetadata();
jsonEvent("i",
llvm::json::Object{{"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(llvm::StringRef Phase, llvm::json::Object &&Contents,
uint64_t TID = llvm::get_threadid(), double Timestamp = 0) {
Contents["ts"] = Timestamp ? Timestamp : timestamp();
Contents["tid"] = int64_t(TID);
std::lock_guard<std::mutex> Lock(Mu);
rawEvent(Phase, Contents);
}
private:
class JSONSpan {
public:
JSONSpan(JSONTracer *Tracer, llvm::StringRef Name, llvm::json::Object *Args)
: StartTime(Tracer->timestamp()), EndTime(0), Name(Name),
TID(llvm::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",
llvm::json::Object{{"id", FlowID},
{"name", "Context crosses threads"},
{"cat", "dummy"}},
(*Parent)->TID, (*Parent)->StartTime);
Tracer->jsonEvent(
"f",
llvm::json::Object{{"id", FlowID},
{"bp", "e"},
{"name", "Context crosses threads"},
{"cat", "dummy"}},
TID);
}
}
~JSONSpan() {
// Finally, record the event (ending at EndTime, not timestamp())!
Tracer->jsonEvent("X",
llvm::json::Object{{"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 int64_t nextID() {
static std::atomic<int64_t> Next = {0};
return Next++;
}
double StartTime;
std::atomic<double> EndTime; // Filled in by markEnded().
std::string Name;
uint64_t TID;
JSONTracer *Tracer;
llvm::json::Object *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(llvm::StringRef Phase,
const llvm::json::Object &Event) /*REQUIRES(Mu)*/ {
// PID 0 represents the clangd process.
Out.object([&]{
Out.attribute("pid", 0);
Out.attribute("ph", Phase);
for (const auto& KV : Event)
Out.attribute(KV.first, KV.second);
});
}
// If we haven't already, emit metadata describing this thread.
void captureThreadMetadata() {
uint64_t TID = llvm::get_threadid();
std::lock_guard<std::mutex> Lock(Mu);
if (ThreadsWithMD.insert(TID).second) {
llvm::SmallString<32> Name;
llvm::get_thread_name(Name);
if (!Name.empty()) {
rawEvent("M", llvm::json::Object{
{"tid", int64_t(TID)},
{"name", "thread_name"},
{"args", llvm::json::Object{{"name", Name}}},
});
}
}
}
double timestamp() {
using namespace std::chrono;
return duration<double, std::micro>(system_clock::now() - Start).count();
}
std::mutex Mu;
llvm::json::OStream Out /*GUARDED_BY(Mu)*/;
llvm::DenseSet<uint64_t> ThreadsWithMD /*GUARDED_BY(Mu)*/;
const llvm::sys::TimePoint<> Start;
};
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;
}
Session::~Session() { T = nullptr; }
std::unique_ptr<EventTracer> createJSONTracer(llvm::raw_ostream &OS,
bool Pretty) {
return llvm::make_unique<JSONTracer>(OS, Pretty);
}
void log(const llvm::Twine &Message) {
if (!T)
return;
T->instant("Log", llvm::json::Object{{"Message", Message.str()}});
}
// Returned context owns Args.
static Context makeSpanContext(llvm::Twine Name, llvm::json::Object *Args) {
if (!T)
return Context::current().clone();
WithContextValue WithArgs{std::unique_ptr<llvm::json::Object>(Args)};
return T->beginSpan(Name.isSingleStringRef() ? Name.getSingleStringRef()
: llvm::StringRef(Name.str()),
Args);
}
// 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::Twine Name)
: Args(T ? new llvm::json::Object() : nullptr),
RestoreCtx(makeSpanContext(Name, Args)) {}
Span::~Span() {
if (T)
T->endSpan();
}
} // namespace trace
} // namespace clangd
} // namespace clang
|