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