clang-tools  14.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(
57  llvm::StringRef Name,
58  llvm::function_ref<void(llvm::json::Object *)> AttachDetails) override {
59  auto JS = std::make_unique<JSONSpan>(this, Name);
60  AttachDetails(&JS->Args);
61  return Context::current().derive(SpanKey, std::move(JS));
62  }
63 
64  // Trace viewer requires each thread to properly stack events.
65  // So we need to mark only duration that the span was active on the thread.
66  // (Hopefully any off-thread activity will be connected by a flow event).
67  // Record the end time here, but don't write the event: Args aren't ready yet.
68  void endSpan() override {
69  Context::current().getExisting(SpanKey)->markEnded();
70  }
71 
72  void instant(llvm::StringRef Name, llvm::json::Object &&Args) override {
73  captureThreadMetadata();
74  jsonEvent("i",
75  llvm::json::Object{{"name", Name}, {"args", std::move(Args)}});
76  }
77 
78  // Record an event on the current thread. ph, pid, tid, ts are set.
79  // Contents must be a list of the other JSON key/values.
80  void jsonEvent(llvm::StringRef Phase, llvm::json::Object &&Contents,
81  uint64_t TID = llvm::get_threadid(), double Timestamp = 0) {
82  Contents["ts"] = Timestamp ? Timestamp : timestamp();
83  Contents["tid"] = int64_t(TID);
84  std::lock_guard<std::mutex> Lock(Mu);
85  rawEvent(Phase, Contents);
86  }
87 
88 private:
89  class JSONSpan {
90  public:
91  JSONSpan(JSONTracer *Tracer, llvm::StringRef Name)
92  : StartTime(Tracer->timestamp()), EndTime(0), Name(Name),
93  TID(llvm::get_threadid()), Tracer(Tracer) {
94  // ~JSONSpan() may run in a different thread, so we need to capture now.
95  Tracer->captureThreadMetadata();
96 
97  // We don't record begin events here (and end events in the destructor)
98  // because B/E pairs have to appear in the right order, which is awkward.
99  // Instead we send the complete (X) event in the destructor.
100 
101  // If our parent was on a different thread, add an arrow to this span.
102  auto *Parent = Context::current().get(SpanKey);
103  if (Parent && *Parent && (*Parent)->TID != TID) {
104  // If the parent span ended already, then show this as "following" it.
105  // Otherwise show us as "parallel".
106  double OriginTime = (*Parent)->EndTime;
107  if (!OriginTime)
108  OriginTime = (*Parent)->StartTime;
109 
110  auto FlowID = nextID();
111  Tracer->jsonEvent(
112  "s",
113  llvm::json::Object{{"id", FlowID},
114  {"name", "Context crosses threads"},
115  {"cat", "mock_cat"}},
116  (*Parent)->TID, (*Parent)->StartTime);
117  Tracer->jsonEvent(
118  "f",
119  llvm::json::Object{{"id", FlowID},
120  {"bp", "e"},
121  {"name", "Context crosses threads"},
122  {"cat", "mock_cat"}},
123  TID);
124  }
125  }
126 
127  ~JSONSpan() {
128  // Finally, record the event (ending at EndTime, not timestamp())!
129  Tracer->jsonEvent("X",
130  llvm::json::Object{{"name", std::move(Name)},
131  {"args", std::move(Args)},
132  {"dur", EndTime - StartTime}},
133  TID, StartTime);
134  }
135 
136  // May be called by any thread.
137  void markEnded() { EndTime = Tracer->timestamp(); }
138 
139  llvm::json::Object Args;
140 
141  private:
142  static int64_t nextID() {
143  static std::atomic<int64_t> Next = {0};
144  return Next++;
145  }
146 
147  double StartTime;
148  std::atomic<double> EndTime; // Filled in by markEnded().
149  std::string Name;
150  uint64_t TID;
151  JSONTracer *Tracer;
152  };
153  static Key<std::unique_ptr<JSONSpan>> SpanKey;
154 
155  // Record an event. ph and pid are set.
156  // Contents must be a list of the other JSON key/values.
157  void rawEvent(llvm::StringRef Phase,
158  const llvm::json::Object &Event) /*REQUIRES(Mu)*/ {
159  // PID 0 represents the clangd process.
160  Out.object([&] {
161  Out.attribute("pid", 0);
162  Out.attribute("ph", Phase);
163  for (const auto &KV : Event)
164  Out.attribute(KV.first, KV.second);
165  });
166  }
167 
168  // If we haven't already, emit metadata describing this thread.
169  void captureThreadMetadata() {
170  uint64_t TID = llvm::get_threadid();
171  std::lock_guard<std::mutex> Lock(Mu);
172  if (ThreadsWithMD.insert(TID).second) {
173  llvm::SmallString<32> Name;
174  llvm::get_thread_name(Name);
175  if (!Name.empty()) {
176  rawEvent("M", llvm::json::Object{
177  {"tid", int64_t(TID)},
178  {"name", "thread_name"},
179  {"args", llvm::json::Object{{"name", Name}}},
180  });
181  }
182  }
183  }
184 
185  double timestamp() {
186  using namespace std::chrono;
187  return duration<double, std::micro>(system_clock::now() - Start).count();
188  }
189 
190  std::mutex Mu;
191  llvm::json::OStream Out /*GUARDED_BY(Mu)*/;
192  llvm::DenseSet<uint64_t> ThreadsWithMD /*GUARDED_BY(Mu)*/;
193  const llvm::sys::TimePoint<> Start;
194 };
195 
196 // We emit CSV as specified in RFC 4180: https://www.ietf.org/rfc/rfc4180.txt.
197 // \r\n line endings are used, cells with \r\n," are quoted, quotes are doubled.
198 class CSVMetricTracer : public EventTracer {
199 public:
200  CSVMetricTracer(llvm::raw_ostream &Out) : Out(Out) {
201  Start = std::chrono::steady_clock::now();
202 
203  Out.SetUnbuffered(); // We write each line atomically.
204  Out << "Kind,Metric,Label,Value,Timestamp\r\n";
205  }
206 
207  void record(const Metric &Metric, double Value,
208  llvm::StringRef Label) override {
209  assert(!needsQuote(Metric.Name));
210  std::string QuotedLabel;
211  if (needsQuote(Label))
212  Label = QuotedLabel = quote(Label);
213  uint64_t Micros = std::chrono::duration_cast<std::chrono::microseconds>(
214  std::chrono::steady_clock::now() - Start)
215  .count();
216  std::lock_guard<std::mutex> Lock(Mu);
217  Out << llvm::formatv("{0},{1},{2},{3:e},{4}.{5:6}\r\n",
218  typeName(Metric.Type), Metric.Name, Label, Value,
219  Micros / 1000000, Micros % 1000000);
220  }
221 
222 private:
223  llvm::StringRef typeName(Metric::MetricType T) {
224  switch (T) {
225  case Metric::Value:
226  return "v";
227  case Metric::Counter:
228  return "c";
230  return "d";
231  }
232  llvm_unreachable("Unknown Metric::MetricType enum");
233  }
234 
235  static bool needsQuote(llvm::StringRef Text) {
236  // https://www.ietf.org/rfc/rfc4180.txt section 2.6
237  return Text.find_first_of(",\"\r\n") != llvm::StringRef::npos;
238  }
239 
240  std::string quote(llvm::StringRef Text) {
241  std::string Result = "\"";
242  for (char C : Text) {
243  Result.push_back(C);
244  if (C == '"')
245  Result.push_back('"');
246  }
247  Result.push_back('"');
248  return Result;
249  }
250 
251 private:
252  std::mutex Mu;
253  llvm::raw_ostream &Out /*GUARDED_BY(Mu)*/;
254  std::chrono::steady_clock::time_point Start;
255 };
256 
257 Key<std::unique_ptr<JSONTracer::JSONSpan>> JSONTracer::SpanKey;
258 
259 EventTracer *T = nullptr;
260 } // namespace
261 
263  assert(!T && "Resetting global tracer is not allowed.");
264  T = &Tracer;
265 }
266 
267 Session::~Session() { T = nullptr; }
268 
269 std::unique_ptr<EventTracer> createJSONTracer(llvm::raw_ostream &OS,
270  bool Pretty) {
271  return std::make_unique<JSONTracer>(OS, Pretty);
272 }
273 
274 std::unique_ptr<EventTracer> createCSVMetricTracer(llvm::raw_ostream &OS) {
275  return std::make_unique<CSVMetricTracer>(OS);
276 }
277 
278 void log(const llvm::Twine &Message) {
279  if (!T)
280  return;
281  T->instant("Log", llvm::json::Object{{"Message", Message.str()}});
282 }
283 
284 bool enabled() { return T != nullptr; }
285 
286 // The JSON object is event args (owned by context), if the tracer wants them.
287 static std::pair<Context, llvm::json::Object *>
288 makeSpanContext(llvm::Twine Name, const Metric &LatencyMetric) {
289  if (!T)
290  return std::make_pair(Context::current().clone(), nullptr);
291  llvm::Optional<WithContextValue> WithLatency;
292  using Clock = std::chrono::high_resolution_clock;
293  WithLatency.emplace(llvm::make_scope_exit(
294  [StartTime = Clock::now(), Name = Name.str(), &LatencyMetric] {
295  LatencyMetric.record(
296  std::chrono::duration_cast<std::chrono::milliseconds>(Clock::now() -
297  StartTime)
298  .count(),
299  Name);
300  }));
301  llvm::json::Object *Args = nullptr;
302  Context Ctx = T->beginSpan(
303  Name.isSingleStringRef() ? Name.getSingleStringRef()
304  : llvm::StringRef(Name.str()),
305  [&](llvm::json::Object *A) {
306  assert(A && A->empty() && "Invalid AttachDetails() placeholder!");
307  Args = A;
308  });
309  return std::make_pair(std::move(Ctx), Args);
310 }
311 
312 // Fallback metric that measures latencies for spans without an explicit latency
313 // metric. Labels are span names.
314 constexpr Metric SpanLatency("span_latency", Metric::Distribution, "span_name");
315 
316 // Span keeps a non-owning pointer to the args, which is how users access them.
317 // The args are owned by the context though. They stick around until the
318 // beginSpan() context is destroyed, when the tracing engine will consume them.
319 Span::Span(llvm::Twine Name) : Span(Name, SpanLatency) {}
320 Span::Span(llvm::Twine Name, const Metric &LatencyMetric)
321  : Span(makeSpanContext(Name, LatencyMetric)) {}
322 Span::Span(std::pair<Context, llvm::json::Object *> Pair)
323  : Args(Pair.second), RestoreCtx(std::move(Pair.first)) {}
324 
326  if (T)
327  T->endSpan();
328 }
329 
330 void Metric::record(double Value, llvm::StringRef Label) const {
331  if (!T)
332  return;
333  assert((LabelName.empty() == Label.empty()) &&
334  "recording a measurement with inconsistent labeling");
335  T->record(*this, Value, Label);
336 }
337 
339  llvm::StringRef Name,
340  llvm::function_ref<void(llvm::json::Object *)> AttachDetails) {
341  return Context::current().clone();
342 }
343 } // namespace trace
344 } // namespace clangd
345 } // namespace clang
clang::clangd::trace::Metric::LabelName
const llvm::StringLiteral LabelName
Indicates what measurement labels represent, e.g.
Definition: Trace.h:68
Label
std::string Label
Definition: InlayHintTests.cpp:38
clang::clangd::trace::EventTracer
A consumer of trace events and measurements.
Definition: Trace.h:74
Tracer
std::unique_ptr< trace::EventTracer > Tracer
Definition: TraceTests.cpp:164
clang::clangd::Context::current
static const Context & current()
Returns the context for the current thread, creating it if needed.
Definition: Context.cpp:27
clang::clangd::Context::clone
Context clone() const
Clone this context object.
Definition: Context.cpp:20
clang::clangd::trace::Span::~Span
~Span()
Definition: Trace.cpp:325
clang::clangd::Context::get
const Type * get(const Key< Type > &Key) const
Get data stored for a typed Key.
Definition: Context.h:98
clang::clangd::trace::Span::Span
Span(llvm::Twine Name)
Definition: Trace.cpp:319
clang::tidy::bugprone::Message
static const char Message[]
Definition: ReservedIdentifierCheck.cpp:31
clang::clangd::trace::Metric::record
void record(double Value, llvm::StringRef Label="") const
Records a measurement for this metric to active tracer.
Definition: Trace.cpp:330
clang::clangd::trace::makeSpanContext
static std::pair< Context, llvm::json::Object * > makeSpanContext(llvm::Twine Name, const Metric &LatencyMetric)
Definition: Trace.cpp:288
Text
std::string Text
Definition: HTMLGenerator.cpp:80
Ctx
Context Ctx
Definition: TUScheduler.cpp:454
Trace.h
clang::clangd::trace::log
void log(const llvm::Twine &Message)
Records a single instant event, associated with the current thread.
Definition: Trace.cpp:278
clang::clangd::trace::createJSONTracer
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:269
clang::clangd::trace::Metric::MetricType
MetricType
Definition: Trace.h:39
ns1::ns2::A
@ A
Definition: CategoricalFeature.h:3
clang::clangd::trace::createCSVMetricTracer
std::unique_ptr< EventTracer > createCSVMetricTracer(llvm::raw_ostream &OS)
Create an instance of EventTracer that outputs metric measurements as CSV.
Definition: Trace.cpp:274
clang::clangd::trace::Session::~Session
~Session()
Definition: Trace.cpp:267
Name
llvm::StringRef Name
Definition: CodeComplete.cpp:162
clang::clangd::trace::enabled
bool enabled()
Returns true if there is an active tracer.
Definition: Trace.cpp:284
Args
llvm::json::Object Args
Definition: Trace.cpp:139
clang::clangd::trace::Metric::Distribution
@ Distribution
A distribution of values with a meaningful mean and count.
Definition: Trace.h:52
clang::clangd::trace::SpanLatency
constexpr Metric SpanLatency("span_latency", Metric::Distribution, "span_name")
clang::clangd::trace::Session::Session
Session(EventTracer &Tracer)
Definition: Trace.cpp:262
Parent
const Node * Parent
Definition: ExtractFunction.cpp:152
clang::clangd::trace::Metric::Counter
@ Counter
An aggregate number whose rate of change over time is meaningful.
Definition: Trace.h:46
clang::clangd::Context::derive
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:119
clang::clangd::trace::Metric
Represents measurements of clangd events, e.g.
Definition: Trace.h:38
C
const Criteria C
Definition: FunctionCognitiveComplexityCheck.cpp:93
clang::clangd::trace::EventTracer::beginSpan
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:338
clang
===– Representation.cpp - ClangDoc Representation --------—*- C++ -*-===//
Definition: ApplyReplacements.h:27
OS
llvm::raw_string_ostream OS
Definition: TraceTests.cpp:163
clang::clangd::trace::Metric::Value
@ Value
A number whose value is meaningful, and may vary over time.
Definition: Trace.h:42
clang::clangd::record
void record(const MemoryTree &MT, std::string RootName, const trace::Metric &Out)
Records total memory usage of each node under Out.
Definition: MemoryTree.cpp:46
Out
CompiledFragmentImpl & Out
Definition: ConfigCompile.cpp:100
clang::clangd::Context::getExisting
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
clang::clangd::Context
A context is an immutable container for per-request data that must be propagated through layers that ...
Definition: Context.h:69
Context.h
clang::clangd::trace::Span
Records an event whose duration is the lifetime of the Span object.
Definition: Trace.h:143