1 //===- xray-account.h - XRay Function Call Accounting ---------------------===//
2 //
3 // The LLVM Compiler Infrastructure
4 //
5 // This file is distributed under the University of Illinois Open Source
6 // License. See LICENSE.TXT for details.
7 //
8 //===----------------------------------------------------------------------===//
9 //
10 // This file implements basic function call accounting from an XRay trace.
11 //
12 //===----------------------------------------------------------------------===//
13
14 #include <algorithm>
15 #include <cassert>
16 #include <numeric>
17 #include <system_error>
18 #include <utility>
19
20 #include "xray-account.h"
21 #include "xray-registry.h"
22 #include "llvm/Support/ErrorHandling.h"
23 #include "llvm/Support/FormatVariadic.h"
24 #include "llvm/XRay/InstrumentationMap.h"
25 #include "llvm/XRay/Trace.h"
26
27 using namespace llvm;
28 using namespace llvm::xray;
29
30 static cl::SubCommand Account("account", "Function call accounting");
31 static cl::opt<std::string> AccountInput(cl::Positional,
32 cl::desc("<xray log file>"),
33 cl::Required, cl::sub(Account));
34 static cl::opt<bool>
35 AccountKeepGoing("keep-going", cl::desc("Keep going on errors encountered"),
36 cl::sub(Account), cl::init(false));
37 static cl::alias AccountKeepGoing2("k", cl::aliasopt(AccountKeepGoing),
38 cl::desc("Alias for -keep_going"),
39 cl::sub(Account));
40 static cl::opt<bool> AccountDeduceSiblingCalls(
41 "deduce-sibling-calls",
42 cl::desc("Deduce sibling calls when unrolling function call stacks"),
43 cl::sub(Account), cl::init(false));
44 static cl::alias
45 AccountDeduceSiblingCalls2("d", cl::aliasopt(AccountDeduceSiblingCalls),
46 cl::desc("Alias for -deduce_sibling_calls"),
47 cl::sub(Account));
48 static cl::opt<std::string>
49 AccountOutput("output", cl::value_desc("output file"), cl::init("-"),
50 cl::desc("output file; use '-' for stdout"),
51 cl::sub(Account));
52 static cl::alias AccountOutput2("o", cl::aliasopt(AccountOutput),
53 cl::desc("Alias for -output"),
54 cl::sub(Account));
55 enum class AccountOutputFormats { TEXT, CSV };
56 static cl::opt<AccountOutputFormats>
57 AccountOutputFormat("format", cl::desc("output format"),
58 cl::values(clEnumValN(AccountOutputFormats::TEXT,
59 "text", "report stats in text"),
60 clEnumValN(AccountOutputFormats::CSV, "csv",
61 "report stats in csv")),
62 cl::sub(Account));
63 static cl::alias AccountOutputFormat2("f", cl::desc("Alias of -format"),
64 cl::aliasopt(AccountOutputFormat),
65 cl::sub(Account));
66
67 enum class SortField {
68 FUNCID,
69 COUNT,
70 MIN,
71 MED,
72 PCT90,
73 PCT99,
74 MAX,
75 SUM,
76 FUNC,
77 };
78
79 static cl::opt<SortField> AccountSortOutput(
80 "sort", cl::desc("sort output by this field"), cl::value_desc("field"),
81 cl::sub(Account), cl::init(SortField::FUNCID),
82 cl::values(clEnumValN(SortField::FUNCID, "funcid", "function id"),
83 clEnumValN(SortField::COUNT, "count", "funciton call counts"),
84 clEnumValN(SortField::MIN, "min", "minimum function durations"),
85 clEnumValN(SortField::MED, "med", "median function durations"),
86 clEnumValN(SortField::PCT90, "90p", "90th percentile durations"),
87 clEnumValN(SortField::PCT99, "99p", "99th percentile durations"),
88 clEnumValN(SortField::MAX, "max", "maximum function durations"),
89 clEnumValN(SortField::SUM, "sum", "sum of call durations"),
90 clEnumValN(SortField::FUNC, "func", "function names")));
91 static cl::alias AccountSortOutput2("s", cl::aliasopt(AccountSortOutput),
92 cl::desc("Alias for -sort"),
93 cl::sub(Account));
94
95 enum class SortDirection {
96 ASCENDING,
97 DESCENDING,
98 };
99 static cl::opt<SortDirection> AccountSortOrder(
100 "sortorder", cl::desc("sort ordering"), cl::init(SortDirection::ASCENDING),
101 cl::values(clEnumValN(SortDirection::ASCENDING, "asc", "ascending"),
102 clEnumValN(SortDirection::DESCENDING, "dsc", "descending")),
103 cl::sub(Account));
104 static cl::alias AccountSortOrder2("r", cl::aliasopt(AccountSortOrder),
105 cl::desc("Alias for -sortorder"),
106 cl::sub(Account));
107
108 static cl::opt<int> AccountTop("top", cl::desc("only show the top N results"),
109 cl::value_desc("N"), cl::sub(Account),
110 cl::init(-1));
111 static cl::alias AccountTop2("p", cl::desc("Alias for -top"),
112 cl::aliasopt(AccountTop), cl::sub(Account));
113
114 static cl::opt<std::string>
115 AccountInstrMap("instr_map",
116 cl::desc("binary with the instrumentation map, or "
117 "a separate instrumentation map"),
118 cl::value_desc("binary with xray_instr_map"),
119 cl::sub(Account), cl::init(""));
120 static cl::alias AccountInstrMap2("m", cl::aliasopt(AccountInstrMap),
121 cl::desc("Alias for -instr_map"),
122 cl::sub(Account));
123
124 namespace {
125
setMinMax(std::pair<T,T> & MM,U && V)126 template <class T, class U> void setMinMax(std::pair<T, T> &MM, U &&V) {
127 if (MM.first == 0 || MM.second == 0)
128 MM = std::make_pair(std::forward<U>(V), std::forward<U>(V));
129 else
130 MM = std::make_pair(std::min(MM.first, V), std::max(MM.second, V));
131 }
132
diff(T L,T R)133 template <class T> T diff(T L, T R) { return std::max(L, R) - std::min(L, R); }
134
135 } // namespace
136
accountRecord(const XRayRecord & Record)137 bool LatencyAccountant::accountRecord(const XRayRecord &Record) {
138 setMinMax(PerThreadMinMaxTSC[Record.TId], Record.TSC);
139 setMinMax(PerCPUMinMaxTSC[Record.CPU], Record.TSC);
140
141 if (CurrentMaxTSC == 0)
142 CurrentMaxTSC = Record.TSC;
143
144 if (Record.TSC < CurrentMaxTSC)
145 return false;
146
147 auto &ThreadStack = PerThreadFunctionStack[Record.TId];
148 switch (Record.Type) {
149 case RecordTypes::CUSTOM_EVENT:
150 case RecordTypes::TYPED_EVENT:
151 // TODO: Support custom and typed event accounting in the future.
152 return true;
153 case RecordTypes::ENTER:
154 case RecordTypes::ENTER_ARG: {
155 ThreadStack.emplace_back(Record.FuncId, Record.TSC);
156 break;
157 }
158 case RecordTypes::EXIT:
159 case RecordTypes::TAIL_EXIT: {
160 if (ThreadStack.empty())
161 return false;
162
163 if (ThreadStack.back().first == Record.FuncId) {
164 const auto &Top = ThreadStack.back();
165 recordLatency(Top.first, diff(Top.second, Record.TSC));
166 ThreadStack.pop_back();
167 break;
168 }
169
170 if (!DeduceSiblingCalls)
171 return false;
172
173 // Look for the parent up the stack.
174 auto Parent =
175 std::find_if(ThreadStack.rbegin(), ThreadStack.rend(),
176 [&](const std::pair<const int32_t, uint64_t> &E) {
177 return E.first == Record.FuncId;
178 });
179 if (Parent == ThreadStack.rend())
180 return false;
181
182 // Account time for this apparently sibling call exit up the stack.
183 // Considering the following case:
184 //
185 // f()
186 // g()
187 // h()
188 //
189 // We might only ever see the following entries:
190 //
191 // -> f()
192 // -> g()
193 // -> h()
194 // <- h()
195 // <- f()
196 //
197 // Now we don't see the exit to g() because some older version of the XRay
198 // runtime wasn't instrumenting tail exits. If we don't deduce tail calls,
199 // we may potentially never account time for g() -- and this code would have
200 // already bailed out, because `<- f()` doesn't match the current "top" of
201 // stack where we're waiting for the exit to `g()` instead. This is not
202 // ideal and brittle -- so instead we provide a potentially inaccurate
203 // accounting of g() instead, computing it from the exit of f().
204 //
205 // While it might be better that we account the time between `-> g()` and
206 // `-> h()` as the proper accounting of time for g() here, this introduces
207 // complexity to do correctly (need to backtrack, etc.).
208 //
209 // FIXME: Potentially implement the more complex deduction algorithm?
210 auto I = std::next(Parent).base();
211 for (auto &E : make_range(I, ThreadStack.end())) {
212 recordLatency(E.first, diff(E.second, Record.TSC));
213 }
214 ThreadStack.erase(I, ThreadStack.end());
215 break;
216 }
217 }
218
219 return true;
220 }
221
222 namespace {
223
224 // We consolidate the data into a struct which we can output in various forms.
225 struct ResultRow {
226 uint64_t Count;
227 double Min;
228 double Median;
229 double Pct90;
230 double Pct99;
231 double Max;
232 double Sum;
233 std::string DebugInfo;
234 std::string Function;
235 };
236
getStats(std::vector<uint64_t> & Timings)237 ResultRow getStats(std::vector<uint64_t> &Timings) {
238 assert(!Timings.empty());
239 ResultRow R;
240 R.Sum = std::accumulate(Timings.begin(), Timings.end(), 0.0);
241 auto MinMax = std::minmax_element(Timings.begin(), Timings.end());
242 R.Min = *MinMax.first;
243 R.Max = *MinMax.second;
244 R.Count = Timings.size();
245
246 auto MedianOff = Timings.size() / 2;
247 std::nth_element(Timings.begin(), Timings.begin() + MedianOff, Timings.end());
248 R.Median = Timings[MedianOff];
249
250 auto Pct90Off = std::floor(Timings.size() * 0.9);
251 std::nth_element(Timings.begin(), Timings.begin() + Pct90Off, Timings.end());
252 R.Pct90 = Timings[Pct90Off];
253
254 auto Pct99Off = std::floor(Timings.size() * 0.99);
255 std::nth_element(Timings.begin(), Timings.begin() + Pct99Off, Timings.end());
256 R.Pct99 = Timings[Pct99Off];
257 return R;
258 }
259
260 } // namespace
261
262 using TupleType = std::tuple<int32_t, uint64_t, ResultRow>;
263
264 template <typename F>
sortByKey(std::vector<TupleType> & Results,F Fn)265 static void sortByKey(std::vector<TupleType> &Results, F Fn) {
266 bool ASC = AccountSortOrder == SortDirection::ASCENDING;
267 llvm::sort(Results, [=](const TupleType &L, const TupleType &R) {
268 return ASC ? Fn(L) < Fn(R) : Fn(L) > Fn(R);
269 });
270 }
271
272 template <class F>
exportStats(const XRayFileHeader & Header,F Fn) const273 void LatencyAccountant::exportStats(const XRayFileHeader &Header, F Fn) const {
274 std::vector<TupleType> Results;
275 Results.reserve(FunctionLatencies.size());
276 for (auto FT : FunctionLatencies) {
277 const auto &FuncId = FT.first;
278 auto &Timings = FT.second;
279 Results.emplace_back(FuncId, Timings.size(), getStats(Timings));
280 auto &Row = std::get<2>(Results.back());
281 if (Header.CycleFrequency) {
282 double CycleFrequency = Header.CycleFrequency;
283 Row.Min /= CycleFrequency;
284 Row.Median /= CycleFrequency;
285 Row.Pct90 /= CycleFrequency;
286 Row.Pct99 /= CycleFrequency;
287 Row.Max /= CycleFrequency;
288 Row.Sum /= CycleFrequency;
289 }
290
291 Row.Function = FuncIdHelper.SymbolOrNumber(FuncId);
292 Row.DebugInfo = FuncIdHelper.FileLineAndColumn(FuncId);
293 }
294
295 // Sort the data according to user-provided flags.
296 switch (AccountSortOutput) {
297 case SortField::FUNCID:
298 sortByKey(Results, [](const TupleType &X) { return std::get<0>(X); });
299 break;
300 case SortField::COUNT:
301 sortByKey(Results, [](const TupleType &X) { return std::get<1>(X); });
302 break;
303 case SortField::MIN:
304 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Min; });
305 break;
306 case SortField::MED:
307 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Median; });
308 break;
309 case SortField::PCT90:
310 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Pct90; });
311 break;
312 case SortField::PCT99:
313 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Pct99; });
314 break;
315 case SortField::MAX:
316 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Max; });
317 break;
318 case SortField::SUM:
319 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Sum; });
320 break;
321 case SortField::FUNC:
322 llvm_unreachable("Not implemented");
323 }
324
325 if (AccountTop > 0) {
326 auto MaxTop =
327 std::min(AccountTop.getValue(), static_cast<int>(Results.size()));
328 Results.erase(Results.begin() + MaxTop, Results.end());
329 }
330
331 for (const auto &R : Results)
332 Fn(std::get<0>(R), std::get<1>(R), std::get<2>(R));
333 }
334
exportStatsAsText(raw_ostream & OS,const XRayFileHeader & Header) const335 void LatencyAccountant::exportStatsAsText(raw_ostream &OS,
336 const XRayFileHeader &Header) const {
337 OS << "Functions with latencies: " << FunctionLatencies.size() << "\n";
338
339 // We spend some effort to make the text output more readable, so we do the
340 // following formatting decisions for each of the fields:
341 //
342 // - funcid: 32-bit, but we can determine the largest number and be
343 // between
344 // a minimum of 5 characters, up to 9 characters, right aligned.
345 // - count: 64-bit, but we can determine the largest number and be
346 // between
347 // a minimum of 5 characters, up to 9 characters, right aligned.
348 // - min, median, 90pct, 99pct, max: double precision, but we want to keep
349 // the values in seconds, with microsecond precision (0.000'001), so we
350 // have at most 6 significant digits, with the whole number part to be
351 // at
352 // least 1 character. For readability we'll right-align, with full 9
353 // characters each.
354 // - debug info, function name: we format this as a concatenation of the
355 // debug info and the function name.
356 //
357 static constexpr char StatsHeaderFormat[] =
358 "{0,+9} {1,+10} [{2,+9}, {3,+9}, {4,+9}, {5,+9}, {6,+9}] {7,+9}";
359 static constexpr char StatsFormat[] =
360 R"({0,+9} {1,+10} [{2,+9:f6}, {3,+9:f6}, {4,+9:f6}, {5,+9:f6}, {6,+9:f6}] {7,+9:f6})";
361 OS << llvm::formatv(StatsHeaderFormat, "funcid", "count", "min", "med", "90p",
362 "99p", "max", "sum")
363 << llvm::formatv(" {0,-12}\n", "function");
364 exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {
365 OS << llvm::formatv(StatsFormat, FuncId, Count, Row.Min, Row.Median,
366 Row.Pct90, Row.Pct99, Row.Max, Row.Sum)
367 << " " << Row.DebugInfo << ": " << Row.Function << "\n";
368 });
369 }
370
exportStatsAsCSV(raw_ostream & OS,const XRayFileHeader & Header) const371 void LatencyAccountant::exportStatsAsCSV(raw_ostream &OS,
372 const XRayFileHeader &Header) const {
373 OS << "funcid,count,min,median,90%ile,99%ile,max,sum,debug,function\n";
374 exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {
375 OS << FuncId << ',' << Count << ',' << Row.Min << ',' << Row.Median << ','
376 << Row.Pct90 << ',' << Row.Pct99 << ',' << Row.Max << "," << Row.Sum
377 << ",\"" << Row.DebugInfo << "\",\"" << Row.Function << "\"\n";
378 });
379 }
380
381 using namespace llvm::xray;
382
383 namespace llvm {
384 template <> struct format_provider<llvm::xray::RecordTypes> {
formatllvm::format_provider385 static void format(const llvm::xray::RecordTypes &T, raw_ostream &Stream,
386 StringRef Style) {
387 switch (T) {
388 case RecordTypes::ENTER:
389 Stream << "enter";
390 break;
391 case RecordTypes::ENTER_ARG:
392 Stream << "enter-arg";
393 break;
394 case RecordTypes::EXIT:
395 Stream << "exit";
396 break;
397 case RecordTypes::TAIL_EXIT:
398 Stream << "tail-exit";
399 break;
400 case RecordTypes::CUSTOM_EVENT:
401 Stream << "custom-event";
402 break;
403 case RecordTypes::TYPED_EVENT:
404 Stream << "typed-event";
405 break;
406 }
407 }
408 };
409 } // namespace llvm
410
__anonac6918070f02() 411 static CommandRegistration Unused(&Account, []() -> Error {
412 InstrumentationMap Map;
413 if (!AccountInstrMap.empty()) {
414 auto InstrumentationMapOrError = loadInstrumentationMap(AccountInstrMap);
415 if (!InstrumentationMapOrError)
416 return joinErrors(make_error<StringError>(
417 Twine("Cannot open instrumentation map '") +
418 AccountInstrMap + "'",
419 std::make_error_code(std::errc::invalid_argument)),
420 InstrumentationMapOrError.takeError());
421 Map = std::move(*InstrumentationMapOrError);
422 }
423
424 std::error_code EC;
425 raw_fd_ostream OS(AccountOutput, EC, sys::fs::OpenFlags::F_Text);
426 if (EC)
427 return make_error<StringError>(
428 Twine("Cannot open file '") + AccountOutput + "' for writing.", EC);
429
430 const auto &FunctionAddresses = Map.getFunctionAddresses();
431 symbolize::LLVMSymbolizer::Options Opts(
432 symbolize::FunctionNameKind::LinkageName, true, true, false, "");
433 symbolize::LLVMSymbolizer Symbolizer(Opts);
434 llvm::xray::FuncIdConversionHelper FuncIdHelper(AccountInstrMap, Symbolizer,
435 FunctionAddresses);
436 xray::LatencyAccountant FCA(FuncIdHelper, AccountDeduceSiblingCalls);
437 auto TraceOrErr = loadTraceFile(AccountInput);
438 if (!TraceOrErr)
439 return joinErrors(
440 make_error<StringError>(
441 Twine("Failed loading input file '") + AccountInput + "'",
442 std::make_error_code(std::errc::executable_format_error)),
443 TraceOrErr.takeError());
444
445 auto &T = *TraceOrErr;
446 for (const auto &Record : T) {
447 if (FCA.accountRecord(Record))
448 continue;
449 errs()
450 << "Error processing record: "
451 << llvm::formatv(
452 R"({{type: {0}; cpu: {1}; record-type: {2}; function-id: {3}; tsc: {4}; thread-id: {5}; process-id: {6}}})",
453 Record.RecordType, Record.CPU, Record.Type, Record.FuncId,
454 Record.TSC, Record.TId, Record.PId)
455 << '\n';
456 for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) {
457 errs() << "Thread ID: " << ThreadStack.first << "\n";
458 if (ThreadStack.second.empty()) {
459 errs() << " (empty stack)\n";
460 continue;
461 }
462 auto Level = ThreadStack.second.size();
463 for (const auto &Entry : llvm::reverse(ThreadStack.second))
464 errs() << " #" << Level-- << "\t"
465 << FuncIdHelper.SymbolOrNumber(Entry.first) << '\n';
466 }
467 if (!AccountKeepGoing)
468 return make_error<StringError>(
469 Twine("Failed accounting function calls in file '") + AccountInput +
470 "'.",
471 std::make_error_code(std::errc::executable_format_error));
472 }
473 switch (AccountOutputFormat) {
474 case AccountOutputFormats::TEXT:
475 FCA.exportStatsAsText(OS, T.getFileHeader());
476 break;
477 case AccountOutputFormats::CSV:
478 FCA.exportStatsAsCSV(OS, T.getFileHeader());
479 break;
480 }
481
482 return Error::success();
483 });
484