clang-tools 20.0.0git
Trace.cpp
Go to the documentation of this file.
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-exception
6//
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 overlap
35 // 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";
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.6
236 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} // namespace
260
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 latency
312// 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 the
317// beginSpan() context is destroyed, when the tracing engine will consume them.
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
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
338 llvm::StringRef Name,
339 llvm::function_ref<void(llvm::json::Object *)> AttachDetails) {
340 return Context::current().clone();
341}
342} // namespace trace
343} // namespace clangd
344} // namespace clang
llvm::SmallString< 256U > Name
CompiledFragmentImpl & Out
const Node * Parent
const Criteria C
llvm::raw_string_ostream OS
Definition: TraceTests.cpp:160
llvm::json::Object Args
Definition: Trace.cpp:138
A context is an immutable container for per-request data that must be propagated through layers that ...
Definition: Context.h:69
Context derive(const Key< Type > &Key, std::decay_t< Type > Value) const &
Derives a child context It is safe to move or destroy a parent context after calling derive().
Definition: Context.h:119
Context clone() const
Clone this context object.
Definition: Context.cpp:20
static const Context & current()
Returns the context for the current thread, creating it if needed.
Definition: Context.cpp:27
const Type * get(const Key< Type > &Key) const
Get data stored for a typed Key.
Definition: Context.h:98
const Type & getExisting(const Key< Type > &Key) const
A helper to get a reference to a Key that must exist in the map.
Definition: Context.h:109
A consumer of trace events and measurements.
Definition: Trace.h:74
virtual Context beginSpan(llvm::StringRef Name, llvm::function_ref< void(llvm::json::Object *)> AttachDetails)
Called when event that has a duration starts.
Definition: Trace.cpp:337
Session(EventTracer &Tracer)
Definition: Trace.cpp:261
Records an event whose duration is the lifetime of the Span object.
Definition: Trace.h:143
Span(llvm::Twine Name)
Definition: Trace.cpp:318
std::unique_ptr< EventTracer > createJSONTracer(llvm::raw_ostream &OS, bool Pretty)
Create an instance of EventTracer that produces an output in the Trace Event format supported by Chro...
Definition: Trace.cpp:268
static std::pair< Context, llvm::json::Object * > makeSpanContext(llvm::Twine Name, const Metric &LatencyMetric)
Definition: Trace.cpp:287
std::unique_ptr< EventTracer > createCSVMetricTracer(llvm::raw_ostream &OS)
Create an instance of EventTracer that outputs metric measurements as CSV.
Definition: Trace.cpp:273
void log(const llvm::Twine &Message)
Records a single instant event, associated with the current thread.
Definition: Trace.cpp:277
constexpr Metric SpanLatency("span_latency", Metric::Distribution, "span_name")
bool enabled()
Returns true if there is an active tracer.
Definition: Trace.cpp:283
void record(const MemoryTree &MT, std::string RootName, const trace::Metric &Out)
Records total memory usage of each node under Out.
Definition: MemoryTree.cpp:53
===– Representation.cpp - ClangDoc Representation --------—*- C++ -*-===//
Represents measurements of clangd events, e.g.
Definition: Trace.h:38
const llvm::StringLiteral LabelName
Indicates what measurement labels represent, e.g.
Definition: Trace.h:68
@ Value
A number whose value is meaningful, and may vary over time.
Definition: Trace.h:42
@ Counter
An aggregate number whose rate of change over time is meaningful.
Definition: Trace.h:46
@ Distribution
A distribution of values with a meaningful mean and count.
Definition: Trace.h:52
void record(double Value, llvm::StringRef Label="") const
Records a measurement for this metric to active tracer.
Definition: Trace.cpp:329