Mercurial > hg > CbC > CbC_llvm

comparison clang-tools-extra/clangd/support/Trace.cpp @ 173:0572611fdcc8 llvm10 llvm12

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
reorgnization done
author Shinji KONO <kono@ie.u-ryukyu.ac.jp>
date Mon, 25 May 2020 11:55:54 +0900
parents
children 2e18cbf3894f
comparison
equal deleted inserted replaced
172:9fbae9c8bf63 173:0572611fdcc8
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