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