clang-tools  16.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/FormatVariadic.h"
17 #include "llvm/Support/Threading.h"
18 #include <atomic>
19 #include <chrono>
20 #include <memory>
21 #include <mutex>
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.
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));
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:
90  JSONSpan(JSONTracer *Tracer, llvm::StringRef Name)
91  : StartTime(Tracer->timestamp()), EndTime(0), Name(Name),
92  TID(llvm::get_threadid()), Tracer(Tracer) {
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"},
114  {"cat", "mock_cat"}},
115  (*Parent)->TID, (*Parent)->StartTime);
116  Tracer->jsonEvent(
117  "f",
118  llvm::json::Object{{"id", FlowID},
119  {"bp", "e"},
120  {"name", "Context crosses threads"},
121  {"cat", "mock_cat"}},
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)},
130  {"args", std::move(Args)},
131  {"dur", EndTime - StartTime}},
132  TID, StartTime);
133  }
134 
135  // May be called by any thread.
136  void markEnded() { EndTime = Tracer->timestamp(); }
137 
138  llvm::json::Object Args;
139 
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";
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 
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 
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) {
288  if (!T)
289  return std::make_pair(Context::current().clone(), nullptr);
290  llvm::Optional<WithContextValue> WithLatency;
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  }));
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);
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)
320  : Span(makeSpanContext(Name, LatencyMetric)) {}
321 Span::Span(std::pair<Context, llvm::json::Object *> Pair)
322  : Args(Pair.second), RestoreCtx(std::move(Pair.first)) {}
323 
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 
338  llvm::StringRef Name,
339  llvm::function_ref<void(llvm::json::Object *)> AttachDetails) {
340  return Context::current().clone();
341 }
342 } // namespace trace
343 } // namespace clangd
344 } // 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:46
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:161
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:324
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:318
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:329
clang::clangd::trace::makeSpanContext
static std::pair< Context, llvm::json::Object * > makeSpanContext(llvm::Twine Name, const Metric &LatencyMetric)
Definition: Trace.cpp:287
Text
std::string Text
Definition: HTMLGenerator.cpp:81
Ctx
Context Ctx
Definition: TUScheduler.cpp:553
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:277
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:268
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:273
clang::clangd::Context::derive
Context derive(const Key< Type > &Key, std::decay_t< 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::Session::~Session
~Session()
Definition: Trace.cpp:266
clang::clangd::trace::enabled
bool enabled()
Returns true if there is an active tracer.
Definition: Trace.cpp:283
Args
llvm::json::Object Args
Definition: Trace.cpp:138
clang::clangd::trace::Metric::Distribution
@ Distribution
A distribution of values with a meaningful mean and count.
Definition: Trace.h:52
Name
Token Name
Definition: MacroToEnumCheck.cpp:89
clang::clangd::trace::SpanLatency
constexpr Metric SpanLatency("span_latency", Metric::Distribution, "span_name")
clang::clangd::trace::Session::Session
Session(EventTracer &Tracer)
Definition: Trace.cpp:261
Parent
const Node * Parent
Definition: ExtractFunction.cpp:157
clang::clangd::trace::Metric::Counter
@ Counter
An aggregate number whose rate of change over time is meaningful.
Definition: Trace.h:46
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:337
clang
===– Representation.cpp - ClangDoc Representation --------—*- C++ -*-===//
Definition: ApplyReplacements.h:27
OS
llvm::raw_string_ostream OS
Definition: TraceTests.cpp:160
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:53
Out
CompiledFragmentImpl & Out
Definition: ConfigCompile.cpp:99
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