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