345 lines · cpp
1//===--- Trace.cpp - Performance tracing facilities -----------------------===//2//3// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.4// See https://llvm.org/LICENSE.txt for license information.5// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception6//7//===----------------------------------------------------------------------===//8 9#include "support/Trace.h"10#include "support/Context.h"11#include "llvm/ADT/DenseSet.h"12#include "llvm/ADT/ScopeExit.h"13#include "llvm/ADT/StringRef.h"14#include "llvm/Support/Chrono.h"15#include "llvm/Support/FormatVariadic.h"16#include "llvm/Support/Threading.h"17#include <atomic>18#include <chrono>19#include <memory>20#include <mutex>21#include <optional>22 23namespace clang {24namespace clangd {25namespace trace {26 27namespace {28// The current implementation is naive: each thread writes to Out guarded by Mu.29// Perhaps we should replace this by something that disturbs performance less.30class JSONTracer : public EventTracer {31public:32 JSONTracer(llvm::raw_ostream &OS, bool Pretty)33 : Out(OS, Pretty ? 2 : 0), Start(std::chrono::system_clock::now()) {34 // The displayTimeUnit must be ns to avoid low-precision overlap35 // calculations!36 Out.objectBegin();37 Out.attribute("displayTimeUnit", "ns");38 Out.attributeBegin("traceEvents");39 Out.arrayBegin();40 rawEvent("M", llvm::json::Object{41 {"name", "process_name"},42 {"args", llvm::json::Object{{"name", "clangd"}}},43 });44 }45 46 ~JSONTracer() {47 Out.arrayEnd();48 Out.attributeEnd();49 Out.objectEnd();50 Out.flush();51 }52 53 // We stash a Span object in the context. It will record the start/end,54 // and this also allows us to look up the parent Span's information.55 Context beginSpan(56 llvm::StringRef Name,57 llvm::function_ref<void(llvm::json::Object *)> AttachDetails) override {58 auto JS = std::make_unique<JSONSpan>(this, Name);59 AttachDetails(&JS->Args);60 return Context::current().derive(SpanKey, std::move(JS));61 }62 63 // Trace viewer requires each thread to properly stack events.64 // So we need to mark only duration that the span was active on the thread.65 // (Hopefully any off-thread activity will be connected by a flow event).66 // Record the end time here, but don't write the event: Args aren't ready yet.67 void endSpan() override {68 Context::current().getExisting(SpanKey)->markEnded();69 }70 71 void instant(llvm::StringRef Name, llvm::json::Object &&Args) override {72 captureThreadMetadata();73 jsonEvent("i",74 llvm::json::Object{{"name", Name}, {"args", std::move(Args)}});75 }76 77 // Record an event on the current thread. ph, pid, tid, ts are set.78 // Contents must be a list of the other JSON key/values.79 void jsonEvent(llvm::StringRef Phase, llvm::json::Object &&Contents,80 uint64_t TID = llvm::get_threadid(), double Timestamp = 0) {81 Contents["ts"] = Timestamp ? Timestamp : timestamp();82 Contents["tid"] = int64_t(TID);83 std::lock_guard<std::mutex> Lock(Mu);84 rawEvent(Phase, Contents);85 }86 87private:88 class JSONSpan {89 public:90 JSONSpan(JSONTracer *Tracer, llvm::StringRef Name)91 : StartTime(Tracer->timestamp()), EndTime(0), Name(Name),92 TID(llvm::get_threadid()), Tracer(Tracer) {93 // ~JSONSpan() may run in a different thread, so we need to capture now.94 Tracer->captureThreadMetadata();95 96 // We don't record begin events here (and end events in the destructor)97 // because B/E pairs have to appear in the right order, which is awkward.98 // Instead we send the complete (X) event in the destructor.99 100 // If our parent was on a different thread, add an arrow to this span.101 auto *Parent = Context::current().get(SpanKey);102 if (Parent && *Parent && (*Parent)->TID != TID) {103 // If the parent span ended already, then show this as "following" it.104 // Otherwise show us as "parallel".105 double OriginTime = (*Parent)->EndTime;106 if (!OriginTime)107 OriginTime = (*Parent)->StartTime;108 109 auto FlowID = nextID();110 Tracer->jsonEvent(111 "s",112 llvm::json::Object{{"id", FlowID},113 {"name", "Context crosses threads"},114 {"cat", "mock_cat"}},115 (*Parent)->TID, (*Parent)->StartTime);116 Tracer->jsonEvent(117 "f",118 llvm::json::Object{{"id", FlowID},119 {"bp", "e"},120 {"name", "Context crosses threads"},121 {"cat", "mock_cat"}},122 TID);123 }124 }125 126 ~JSONSpan() {127 // Finally, record the event (ending at EndTime, not timestamp())!128 Tracer->jsonEvent("X",129 llvm::json::Object{{"name", std::move(Name)},130 {"args", std::move(Args)},131 {"dur", EndTime - StartTime}},132 TID, StartTime);133 }134 135 // May be called by any thread.136 void markEnded() { EndTime = Tracer->timestamp(); }137 138 llvm::json::Object Args;139 140 private:141 static int64_t nextID() {142 static std::atomic<int64_t> Next = {0};143 return Next++;144 }145 146 double StartTime;147 std::atomic<double> EndTime; // Filled in by markEnded().148 std::string Name;149 uint64_t TID;150 JSONTracer *Tracer;151 };152 static Key<std::unique_ptr<JSONSpan>> SpanKey;153 154 // Record an event. ph and pid are set.155 // Contents must be a list of the other JSON key/values.156 void rawEvent(llvm::StringRef Phase,157 const llvm::json::Object &Event) /*REQUIRES(Mu)*/ {158 // PID 0 represents the clangd process.159 Out.object([&] {160 Out.attribute("pid", 0);161 Out.attribute("ph", Phase);162 for (const auto *KV : llvm::json::sortedElements(Event))163 Out.attribute(KV->first, KV->second);164 });165 }166 167 // If we haven't already, emit metadata describing this thread.168 void captureThreadMetadata() {169 uint64_t TID = llvm::get_threadid();170 std::lock_guard<std::mutex> Lock(Mu);171 if (ThreadsWithMD.insert(TID).second) {172 llvm::SmallString<32> Name;173 llvm::get_thread_name(Name);174 if (!Name.empty()) {175 rawEvent("M", llvm::json::Object{176 {"tid", int64_t(TID)},177 {"name", "thread_name"},178 {"args", llvm::json::Object{{"name", Name}}},179 });180 }181 }182 }183 184 double timestamp() {185 using namespace std::chrono;186 return duration<double, std::micro>(system_clock::now() - Start).count();187 }188 189 std::mutex Mu;190 llvm::json::OStream Out /*GUARDED_BY(Mu)*/;191 llvm::DenseSet<uint64_t> ThreadsWithMD /*GUARDED_BY(Mu)*/;192 const llvm::sys::TimePoint<> Start;193};194 195// We emit CSV as specified in RFC 4180: https://www.ietf.org/rfc/rfc4180.txt.196// \r\n line endings are used, cells with \r\n," are quoted, quotes are doubled.197class CSVMetricTracer : public EventTracer {198public:199 CSVMetricTracer(llvm::raw_ostream &Out) : Out(Out) {200 Start = std::chrono::steady_clock::now();201 202 Out.SetUnbuffered(); // We write each line atomically.203 Out << "Kind,Metric,Label,Value,Timestamp\r\n";204 }205 206 void record(const Metric &Metric, double Value,207 llvm::StringRef Label) override {208 assert(!needsQuote(Metric.Name));209 std::string QuotedLabel;210 if (needsQuote(Label))211 Label = QuotedLabel = quote(Label);212 uint64_t Micros = std::chrono::duration_cast<std::chrono::microseconds>(213 std::chrono::steady_clock::now() - Start)214 .count();215 std::lock_guard<std::mutex> Lock(Mu);216 Out << llvm::formatv("{0},{1},{2},{3:e},{4}.{5:6}\r\n",217 typeName(Metric.Type), Metric.Name, Label, Value,218 Micros / 1000000, Micros % 1000000);219 }220 221private:222 llvm::StringRef typeName(Metric::MetricType T) {223 switch (T) {224 case Metric::Value:225 return "v";226 case Metric::Counter:227 return "c";228 case Metric::Distribution:229 return "d";230 }231 llvm_unreachable("Unknown Metric::MetricType enum");232 }233 234 static bool needsQuote(llvm::StringRef Text) {235 // https://www.ietf.org/rfc/rfc4180.txt section 2.6236 return Text.find_first_of(",\"\r\n") != llvm::StringRef::npos;237 }238 239 std::string quote(llvm::StringRef Text) {240 std::string Result = "\"";241 for (char C : Text) {242 Result.push_back(C);243 if (C == '"')244 Result.push_back('"');245 }246 Result.push_back('"');247 return Result;248 }249 250private:251 std::mutex Mu;252 llvm::raw_ostream &Out /*GUARDED_BY(Mu)*/;253 std::chrono::steady_clock::time_point Start;254};255 256Key<std::unique_ptr<JSONTracer::JSONSpan>> JSONTracer::SpanKey;257 258EventTracer *T = nullptr;259} // namespace260 261Session::Session(EventTracer &Tracer) {262 assert(!T && "Resetting global tracer is not allowed.");263 T = &Tracer;264}265 266Session::~Session() { T = nullptr; }267 268std::unique_ptr<EventTracer> createJSONTracer(llvm::raw_ostream &OS,269 bool Pretty) {270 return std::make_unique<JSONTracer>(OS, Pretty);271}272 273std::unique_ptr<EventTracer> createCSVMetricTracer(llvm::raw_ostream &OS) {274 return std::make_unique<CSVMetricTracer>(OS);275}276 277void log(const llvm::Twine &Message) {278 if (!T)279 return;280 T->instant("Log", llvm::json::Object{{"Message", Message.str()}});281}282 283bool enabled() { return T != nullptr; }284 285// The JSON object is event args (owned by context), if the tracer wants them.286static std::pair<Context, llvm::json::Object *>287makeSpanContext(llvm::Twine Name, const Metric &LatencyMetric) {288 if (!T)289 return std::make_pair(Context::current().clone(), nullptr);290 std::optional<WithContextValue> WithLatency;291 using Clock = std::chrono::high_resolution_clock;292 WithLatency.emplace(llvm::make_scope_exit(293 [StartTime = Clock::now(), Name = Name.str(), &LatencyMetric] {294 LatencyMetric.record(295 std::chrono::duration_cast<std::chrono::milliseconds>(Clock::now() -296 StartTime)297 .count(),298 Name);299 }));300 llvm::json::Object *Args = nullptr;301 Context Ctx = T->beginSpan(302 Name.isSingleStringRef() ? Name.getSingleStringRef()303 : llvm::StringRef(Name.str()),304 [&](llvm::json::Object *A) {305 assert(A && A->empty() && "Invalid AttachDetails() placeholder!");306 Args = A;307 });308 return std::make_pair(std::move(Ctx), Args);309}310 311// Fallback metric that measures latencies for spans without an explicit latency312// metric. Labels are span names.313constexpr Metric SpanLatency("span_latency", Metric::Distribution, "span_name");314 315// Span keeps a non-owning pointer to the args, which is how users access them.316// The args are owned by the context though. They stick around until the317// beginSpan() context is destroyed, when the tracing engine will consume them.318Span::Span(llvm::Twine Name) : Span(Name, SpanLatency) {}319Span::Span(llvm::Twine Name, const Metric &LatencyMetric)320 : Span(makeSpanContext(Name, LatencyMetric)) {}321Span::Span(std::pair<Context, llvm::json::Object *> Pair)322 : Args(Pair.second), RestoreCtx(std::move(Pair.first)) {}323 324Span::~Span() {325 if (T)326 T->endSpan();327}328 329void Metric::record(double Value, llvm::StringRef Label) const {330 if (!T)331 return;332 assert((LabelName.empty() == Label.empty()) &&333 "recording a measurement with inconsistent labeling");334 T->record(*this, Value, Label);335}336 337Context EventTracer::beginSpan(338 llvm::StringRef Name,339 llvm::function_ref<void(llvm::json::Object *)> AttachDetails) {340 return Context::current().clone();341}342} // namespace trace343} // namespace clangd344} // namespace clang345