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 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345
|
//===--- 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 "support/Trace.h"
#include "support/Context.h"
#include "llvm/ADT/DenseSet.h"
#include "llvm/ADT/Optional.h"
#include "llvm/ADT/ScopeExit.h"
#include "llvm/ADT/StringRef.h"
#include "llvm/Support/Chrono.h"
#include "llvm/Support/FormatProviders.h"
#include "llvm/Support/FormatVariadic.h"
#include "llvm/Support/Threading.h"
#include <atomic>
#include <chrono>
#include <memory>
#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::function_ref<void(llvm::json::Object *)> AttachDetails) override {
auto JS = std::make_unique<JSONSpan>(this, Name);
AttachDetails(&JS->Args);
return Context::current().derive(SpanKey, std::move(JS));
}
// 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)
: StartTime(Tracer->timestamp()), EndTime(0), Name(Name),
TID(llvm::get_threadid()), Tracer(Tracer) {
// ~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", "mock_cat"}},
(*Parent)->TID, (*Parent)->StartTime);
Tracer->jsonEvent(
"f",
llvm::json::Object{{"id", FlowID},
{"bp", "e"},
{"name", "Context crosses threads"},
{"cat", "mock_cat"}},
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(); }
llvm::json::Object Args;
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;
};
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;
};
// We emit CSV as specified in RFC 4180: https://www.ietf.org/rfc/rfc4180.txt.
// \r\n line endings are used, cells with \r\n," are quoted, quotes are doubled.
class CSVMetricTracer : public EventTracer {
public:
CSVMetricTracer(llvm::raw_ostream &Out) : Out(Out) {
Start = std::chrono::steady_clock::now();
Out.SetUnbuffered(); // We write each line atomically.
Out << "Kind,Metric,Label,Value,Timestamp\r\n";
}
void record(const Metric &Metric, double Value,
llvm::StringRef Label) override {
assert(!needsQuote(Metric.Name));
std::string QuotedLabel;
if (needsQuote(Label))
Label = QuotedLabel = quote(Label);
uint64_t Micros = std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - Start)
.count();
std::lock_guard<std::mutex> Lock(Mu);
Out << llvm::formatv("{0},{1},{2},{3:e},{4}.{5:6}\r\n",
typeName(Metric.Type), Metric.Name, Label, Value,
Micros / 1000000, Micros % 1000000);
}
private:
llvm::StringRef typeName(Metric::MetricType T) {
switch (T) {
case Metric::Value:
return "v";
case Metric::Counter:
return "c";
case Metric::Distribution:
return "d";
}
llvm_unreachable("Unknown Metric::MetricType enum");
}
static bool needsQuote(llvm::StringRef Text) {
// https://www.ietf.org/rfc/rfc4180.txt section 2.6
return Text.find_first_of(",\"\r\n") != llvm::StringRef::npos;
}
std::string quote(llvm::StringRef Text) {
std::string Result = "\"";
for (char C : Text) {
Result.push_back(C);
if (C == '"')
Result.push_back('"');
}
Result.push_back('"');
return Result;
}
private:
std::mutex Mu;
llvm::raw_ostream &Out /*GUARDED_BY(Mu)*/;
std::chrono::steady_clock::time_point 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 std::make_unique<JSONTracer>(OS, Pretty);
}
std::unique_ptr<EventTracer> createCSVMetricTracer(llvm::raw_ostream &OS) {
return std::make_unique<CSVMetricTracer>(OS);
}
void log(const llvm::Twine &Message) {
if (!T)
return;
T->instant("Log", llvm::json::Object{{"Message", Message.str()}});
}
bool enabled() { return T != nullptr; }
// The JSON object is event args (owned by context), if the tracer wants them.
static std::pair<Context, llvm::json::Object *>
makeSpanContext(llvm::Twine Name, const Metric &LatencyMetric) {
if (!T)
return std::make_pair(Context::current().clone(), nullptr);
llvm::Optional<WithContextValue> WithLatency;
using Clock = std::chrono::high_resolution_clock;
WithLatency.emplace(llvm::make_scope_exit(
[StartTime = Clock::now(), Name = Name.str(), &LatencyMetric] {
LatencyMetric.record(
std::chrono::duration_cast<std::chrono::milliseconds>(Clock::now() -
StartTime)
.count(),
Name);
}));
llvm::json::Object *Args = nullptr;
Context Ctx = T->beginSpan(
Name.isSingleStringRef() ? Name.getSingleStringRef()
: llvm::StringRef(Name.str()),
[&](llvm::json::Object *A) {
assert(A && A->empty() && "Invalid AttachDetails() placeholder!");
Args = A;
});
return std::make_pair(std::move(Ctx), Args);
}
// Fallback metric that measures latencies for spans without an explicit latency
// metric. Labels are span names.
constexpr Metric SpanLatency("span_latency", Metric::Distribution, "span_name");
// 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) : Span(Name, SpanLatency) {}
Span::Span(llvm::Twine Name, const Metric &LatencyMetric)
: Span(makeSpanContext(Name, LatencyMetric)) {}
Span::Span(std::pair<Context, llvm::json::Object *> Pair)
: Args(Pair.second), RestoreCtx(std::move(Pair.first)) {}
Span::~Span() {
if (T)
T->endSpan();
}
void Metric::record(double Value, llvm::StringRef Label) const {
if (!T)
return;
assert((LabelName.empty() == Label.empty()) &&
"recording a measurement with inconsistent labeling");
T->record(*this, Value, Label);
}
Context EventTracer::beginSpan(
llvm::StringRef Name,
llvm::function_ref<void(llvm::json::Object *)> AttachDetails) {
return Context::current().clone();
}
} // namespace trace
} // namespace clangd
} // namespace clang
|