|
173
|
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>
|
|
252
|
21 #include <optional>
|
|
173
|
22
|
|
|
23 namespace clang {
|
|
|
24 namespace clangd {
|
|
|
25 namespace trace {
|
|
|
26
|
|
|
27 namespace {
|
|
|
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.
|
|
|
30 class JSONTracer : public EventTracer {
|
|
|
31 public:
|
|
|
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.
|
|
221
|
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));
|
|
173
|
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
|
|
|
87 private:
|
|
|
88 class JSONSpan {
|
|
|
89 public:
|
|
221
|
90 JSONSpan(JSONTracer *Tracer, llvm::StringRef Name)
|
|
173
|
91 : StartTime(Tracer->timestamp()), EndTime(0), Name(Name),
|
|
221
|
92 TID(llvm::get_threadid()), Tracer(Tracer) {
|
|
173
|
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"},
|
|
221
|
114 {"cat", "mock_cat"}},
|
|
173
|
115 (*Parent)->TID, (*Parent)->StartTime);
|
|
|
116 Tracer->jsonEvent(
|
|
|
117 "f",
|
|
|
118 llvm::json::Object{{"id", FlowID},
|
|
|
119 {"bp", "e"},
|
|
|
120 {"name", "Context crosses threads"},
|
|
221
|
121 {"cat", "mock_cat"}},
|
|
173
|
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)},
|
|
221
|
130 {"args", std::move(Args)},
|
|
173
|
131 {"dur", EndTime - StartTime}},
|
|
|
132 TID, StartTime);
|
|
|
133 }
|
|
|
134
|
|
|
135 // May be called by any thread.
|
|
|
136 void markEnded() { EndTime = Tracer->timestamp(); }
|
|
|
137
|
|
221
|
138 llvm::json::Object Args;
|
|
|
139
|
|
173
|
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 : 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.
|
|
|
197 class CSVMetricTracer : public EventTracer {
|
|
|
198 public:
|
|
|
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
|
|
|
221 private:
|
|
|
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.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
|
|
|
250 private:
|
|
|
251 std::mutex Mu;
|
|
|
252 llvm::raw_ostream &Out /*GUARDED_BY(Mu)*/;
|
|
|
253 std::chrono::steady_clock::time_point Start;
|
|
|
254 };
|
|
|
255
|
|
|
256 Key<std::unique_ptr<JSONTracer::JSONSpan>> JSONTracer::SpanKey;
|
|
|
257
|
|
|
258 EventTracer *T = nullptr;
|
|
|
259 } // namespace
|
|
|
260
|
|
|
261 Session::Session(EventTracer &Tracer) {
|
|
|
262 assert(!T && "Resetting global tracer is not allowed.");
|
|
|
263 T = &Tracer;
|
|
|
264 }
|
|
|
265
|
|
|
266 Session::~Session() { T = nullptr; }
|
|
|
267
|
|
|
268 std::unique_ptr<EventTracer> createJSONTracer(llvm::raw_ostream &OS,
|
|
|
269 bool Pretty) {
|
|
|
270 return std::make_unique<JSONTracer>(OS, Pretty);
|
|
|
271 }
|
|
|
272
|
|
|
273 std::unique_ptr<EventTracer> createCSVMetricTracer(llvm::raw_ostream &OS) {
|
|
|
274 return std::make_unique<CSVMetricTracer>(OS);
|
|
|
275 }
|
|
|
276
|
|
|
277 void log(const llvm::Twine &Message) {
|
|
|
278 if (!T)
|
|
|
279 return;
|
|
|
280 T->instant("Log", llvm::json::Object{{"Message", Message.str()}});
|
|
|
281 }
|
|
|
282
|
|
221
|
283 bool enabled() { return T != nullptr; }
|
|
|
284
|
|
|
285 // The JSON object is event args (owned by context), if the tracer wants them.
|
|
|
286 static std::pair<Context, llvm::json::Object *>
|
|
|
287 makeSpanContext(llvm::Twine Name, const Metric &LatencyMetric) {
|
|
173
|
288 if (!T)
|
|
221
|
289 return std::make_pair(Context::current().clone(), nullptr);
|
|
252
|
290 std::optional<WithContextValue> WithLatency;
|
|
173
|
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 }));
|
|
221
|
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);
|
|
173
|
309 }
|
|
|
310
|
|
|
311 // Fallback metric that measures latencies for spans without an explicit latency
|
|
|
312 // metric. Labels are span names.
|
|
|
313 constexpr 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.
|
|
|
318 Span::Span(llvm::Twine Name) : Span(Name, SpanLatency) {}
|
|
|
319 Span::Span(llvm::Twine Name, const Metric &LatencyMetric)
|
|
221
|
320 : Span(makeSpanContext(Name, LatencyMetric)) {}
|
|
|
321 Span::Span(std::pair<Context, llvm::json::Object *> Pair)
|
|
|
322 : Args(Pair.second), RestoreCtx(std::move(Pair.first)) {}
|
|
173
|
323
|
|
|
324 Span::~Span() {
|
|
|
325 if (T)
|
|
|
326 T->endSpan();
|
|
|
327 }
|
|
|
328
|
|
|
329 void 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
|
|
221
|
337 Context EventTracer::beginSpan(
|
|
|
338 llvm::StringRef Name,
|
|
|
339 llvm::function_ref<void(llvm::json::Object *)> AttachDetails) {
|
|
173
|
340 return Context::current().clone();
|
|
|
341 }
|
|
|
342 } // namespace trace
|
|
|
343 } // namespace clangd
|
|
|
344 } // namespace clang
|
