clang-tools  12.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/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";
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 
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 
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
llvm::StringRef Name
A number whose value is meaningful, and may vary over time.
Definition: Trace.h:42
Session(EventTracer &Tracer)
Definition: Trace.cpp:258
Some operations such as code completion produce a set of candidates.
std::string Text
const Node * Parent
constexpr Metric SpanLatency("span_latency", Metric::Distribution, "span_name")
void record(double Value, llvm::StringRef Label="") const
Records a measurement for this metric to active tracer.
Definition: Trace.cpp:318
const llvm::StringLiteral Name
Uniquely identifies the metric.
Definition: Trace.h:63
CompiledFragmentImpl & Out
static Context makeSpanContext(llvm::Twine Name, llvm::json::Object *Args, const Metric &LatencyMetric)
Definition: Trace.cpp:281
An Event<T> allows events of type T to be broadcast to listeners.
Definition: Function.h:31
Values in a Context are indexed by typed keys.
Definition: Context.h:40
virtual Context beginSpan(llvm::StringRef Name, llvm::json::Object *Args)
Called when event that has a duration starts.
Definition: Trace.cpp:326
A distribution of values with a meaningful mean and count.
Definition: Trace.h:52
llvm::StringRef Contents
const Type * get(const Key< Type > &Key) const
Get data stored for a typed Key.
Definition: Context.h:100
Represents measurements of clangd events, e.g.
Definition: Trace.h:38
An aggregate number whose rate of change over time is meaningful.
Definition: Trace.h:46
Context clone() const
Clone this context object.
Definition: Context.cpp:20
llvm::raw_string_ostream OS
Definition: TraceTests.cpp:162
static const Context & current()
Returns the context for the current thread, creating it if needed.
Definition: Context.cpp:27
A context is an immutable container for per-request data that must be propagated through layers that ...
Definition: Context.h:69
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:111
const MetricType Type
Definition: Trace.h:64
===– Representation.cpp - ClangDoc Representation --------—*- C++ -*-===//
void log(const llvm::Twine &Message)
Records a single instant event, associated with the current thread.
Definition: Trace.cpp:274
Context derive(const Key< Type > &Key, typename std::decay< Type >::type Value) const &
Derives a child context It is safe to move or destroy a parent context after calling derive()...
Definition: Context.h:121
Span(llvm::Twine Name)
Definition: Trace.cpp:308
std::unique_ptr< trace::EventTracer > Tracer
Definition: TraceTests.cpp:163
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:265
WithContextValue extends Context::current() with a single value.
Definition: Context.h:204
llvm::json::Object *const Args
Mutable metadata, if this span is interested.
Definition: Trace.h:146
Records an event whose duration is the lifetime of the Span object.
Definition: Trace.h:135
std::unique_ptr< EventTracer > createCSVMetricTracer(llvm::raw_ostream &OS)
Create an instance of EventTracer that outputs metric measurements as CSV.
Definition: Trace.cpp:270
A consumer of trace events and measurements.
Definition: Trace.h:74