1 //===- xray-account.h - XRay Function Call Accounting ---------------------===//
3 // The LLVM Compiler Infrastructure
5 // This file is distributed under the University of Illinois Open Source
6 // License. See LICENSE.TXT for details.
8 //===----------------------------------------------------------------------===//
10 // This file implements basic function call accounting from an XRay trace.
12 //===----------------------------------------------------------------------===//
17 #include <system_error>
20 #include "xray-account.h"
21 #include "xray-extract.h"
22 #include "xray-registry.h"
23 #include "llvm/Support/ErrorHandling.h"
24 #include "llvm/Support/FormatVariadic.h"
25 #include "llvm/XRay/Trace.h"
28 using namespace llvm::xray;
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));
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"),
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));
45 AccountDeduceSiblingCalls2("d", cl::aliasopt(AccountDeduceSiblingCalls),
46 cl::desc("Alias for -deduce_sibling_calls"),
48 static cl::opt<std::string>
49 AccountOutput("output", cl::value_desc("output file"), cl::init("-"),
50 cl::desc("output file; use '-' for stdout"),
52 static cl::alias AccountOutput2("o", cl::aliasopt(AccountOutput),
53 cl::desc("Alias for -output"),
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")),
63 static cl::alias AccountOutputFormat2("f", cl::desc("Alias of -format"),
64 cl::aliasopt(AccountOutputFormat),
67 enum class SortField {
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"),
95 enum class SortDirection {
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")),
104 static cl::alias AccountSortOrder2("r", cl::aliasopt(AccountSortOrder),
105 cl::desc("Alias for -sortorder"),
108 static cl::opt<int> AccountTop("top", cl::desc("only show the top N results"),
109 cl::value_desc("N"), cl::sub(Account),
111 static cl::alias AccountTop2("p", cl::desc("Alias for -top"),
112 cl::aliasopt(AccountTop), cl::sub(Account));
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"),
123 static cl::opt<InstrumentationMapExtractor::InputFormats> InstrMapFormat(
124 "instr-map-format", cl::desc("format of instrumentation map"),
125 cl::values(clEnumValN(InstrumentationMapExtractor::InputFormats::ELF, "elf",
126 "instrumentation map in an ELF header"),
127 clEnumValN(InstrumentationMapExtractor::InputFormats::YAML,
128 "yaml", "instrumentation map in YAML")),
129 cl::sub(Account), cl::init(InstrumentationMapExtractor::InputFormats::ELF));
130 static cl::alias InstrMapFormat2("t", cl::aliasopt(InstrMapFormat),
131 cl::desc("Alias for -instr-map-format"),
136 template <class T, class U> void setMinMax(std::pair<T, T> &MM, U &&V) {
137 if (MM.first == 0 || MM.second == 0)
138 MM = std::make_pair(std::forward<U>(V), std::forward<U>(V));
140 MM = std::make_pair(std::min(MM.first, V), std::max(MM.second, V));
143 template <class T> T diff(T L, T R) { return std::max(L, R) - std::min(L, R); }
147 bool LatencyAccountant::accountRecord(const XRayRecord &Record) {
148 setMinMax(PerThreadMinMaxTSC[Record.TId], Record.TSC);
149 setMinMax(PerCPUMinMaxTSC[Record.CPU], Record.TSC);
151 if (CurrentMaxTSC == 0)
152 CurrentMaxTSC = Record.TSC;
154 if (Record.TSC < CurrentMaxTSC)
157 auto &ThreadStack = PerThreadFunctionStack[Record.TId];
158 switch (Record.Type) {
159 case RecordTypes::ENTER: {
161 ThreadStack.emplace_back(Record.FuncId, Record.TSC);
164 case RecordTypes::EXIT: {
166 if (ThreadStack.back().first == Record.FuncId) {
167 const auto &Top = ThreadStack.back();
168 recordLatency(Top.first, diff(Top.second, Record.TSC));
169 ThreadStack.pop_back();
173 if (!DeduceSiblingCalls)
176 // Look for the parent up the stack.
178 std::find_if(ThreadStack.rbegin(), ThreadStack.rend(),
179 [&](const std::pair<const int32_t, uint64_t> &E) {
180 return E.first == Record.FuncId;
182 if (Parent == ThreadStack.rend())
185 // Account time for this apparently sibling call exit up the stack.
186 // Considering the following case:
192 // We might only ever see the following entries:
200 // Now we don't see the exit to g() because some older version of the XRay
201 // runtime wasn't instrumenting tail exits. If we don't deduce tail calls,
202 // we may potentially never account time for g() -- and this code would have
203 // already bailed out, because `<- f()` doesn't match the current "top" of
204 // stack where we're waiting for the exit to `g()` instead. This is not
205 // ideal and brittle -- so instead we provide a potentially inaccurate
206 // accounting of g() instead, computing it from the exit of f().
208 // While it might be better that we account the time between `-> g()` and
209 // `-> h()` as the proper accounting of time for g() here, this introduces
210 // complexity to do correctly (need to backtrack, etc.).
212 // FIXME: Potentially implement the more complex deduction algorithm?
213 auto I = std::next(Parent).base();
214 for (auto &E : make_range(I, ThreadStack.end())) {
215 recordLatency(E.first, diff(E.second, Record.TSC));
217 ThreadStack.erase(I, ThreadStack.end());
227 // We consolidate the data into a struct which we can output in various forms.
236 std::string DebugInfo;
237 std::string Function;
240 ResultRow getStats(std::vector<uint64_t> &Timings) {
241 assert(!Timings.empty());
243 R.Sum = std::accumulate(Timings.begin(), Timings.end(), 0.0);
244 auto MinMax = std::minmax_element(Timings.begin(), Timings.end());
245 R.Min = *MinMax.first;
246 R.Max = *MinMax.second;
247 auto MedianOff = Timings.size() / 2;
248 std::nth_element(Timings.begin(), Timings.begin() + MedianOff, Timings.end());
249 R.Median = Timings[MedianOff];
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 auto Pct99Off = std::floor(Timings.size() * 0.99);
254 std::nth_element(Timings.begin(), Timings.begin() + Pct90Off, Timings.end());
255 R.Pct99 = Timings[Pct99Off];
256 R.Count = Timings.size();
263 void LatencyAccountant::exportStats(const XRayFileHeader &Header, F Fn) const {
264 using TupleType = std::tuple<int32_t, uint64_t, ResultRow>;
265 std::vector<TupleType> Results;
266 Results.reserve(FunctionLatencies.size());
267 for (auto FT : FunctionLatencies) {
268 const auto &FuncId = FT.first;
269 auto &Timings = FT.second;
270 Results.emplace_back(FuncId, Timings.size(), getStats(Timings));
271 auto &Row = std::get<2>(Results.back());
272 if (Header.CycleFrequency) {
273 double CycleFrequency = Header.CycleFrequency;
274 Row.Min /= CycleFrequency;
275 Row.Median /= CycleFrequency;
276 Row.Pct90 /= CycleFrequency;
277 Row.Pct99 /= CycleFrequency;
278 Row.Max /= CycleFrequency;
279 Row.Sum /= CycleFrequency;
282 Row.Function = FuncIdHelper.SymbolOrNumber(FuncId);
283 Row.DebugInfo = FuncIdHelper.FileLineAndColumn(FuncId);
286 // Sort the data according to user-provided flags.
287 switch (AccountSortOutput) {
288 case SortField::FUNCID:
289 std::sort(Results.begin(), Results.end(),
290 [](const TupleType &L, const TupleType &R) {
291 if (AccountSortOrder == SortDirection::ASCENDING)
292 return std::get<0>(L) < std::get<0>(R);
293 if (AccountSortOrder == SortDirection::DESCENDING)
294 return std::get<0>(L) > std::get<0>(R);
295 llvm_unreachable("Unknown sort direction");
298 case SortField::COUNT:
299 std::sort(Results.begin(), Results.end(),
300 [](const TupleType &L, const TupleType &R) {
301 if (AccountSortOrder == SortDirection::ASCENDING)
302 return std::get<1>(L) < std::get<1>(R);
303 if (AccountSortOrder == SortDirection::DESCENDING)
304 return std::get<1>(L) > std::get<1>(R);
305 llvm_unreachable("Unknown sort direction");
309 // Here we need to look into the ResultRow for the rest of the data that
310 // we want to sort by.
311 std::sort(Results.begin(), Results.end(),
312 [&](const TupleType &L, const TupleType &R) {
313 auto &LR = std::get<2>(L);
314 auto &RR = std::get<2>(R);
315 switch (AccountSortOutput) {
316 case SortField::COUNT:
317 if (AccountSortOrder == SortDirection::ASCENDING)
318 return LR.Count < RR.Count;
319 if (AccountSortOrder == SortDirection::DESCENDING)
320 return LR.Count > RR.Count;
321 llvm_unreachable("Unknown sort direction");
323 if (AccountSortOrder == SortDirection::ASCENDING)
324 return LR.Min < RR.Min;
325 if (AccountSortOrder == SortDirection::DESCENDING)
326 return LR.Min > RR.Min;
327 llvm_unreachable("Unknown sort direction");
329 if (AccountSortOrder == SortDirection::ASCENDING)
330 return LR.Median < RR.Median;
331 if (AccountSortOrder == SortDirection::DESCENDING)
332 return LR.Median > RR.Median;
333 llvm_unreachable("Unknown sort direction");
334 case SortField::PCT90:
335 if (AccountSortOrder == SortDirection::ASCENDING)
336 return LR.Pct90 < RR.Pct90;
337 if (AccountSortOrder == SortDirection::DESCENDING)
338 return LR.Pct90 > RR.Pct90;
339 llvm_unreachable("Unknown sort direction");
340 case SortField::PCT99:
341 if (AccountSortOrder == SortDirection::ASCENDING)
342 return LR.Pct99 < RR.Pct99;
343 if (AccountSortOrder == SortDirection::DESCENDING)
344 return LR.Pct99 > RR.Pct99;
345 llvm_unreachable("Unknown sort direction");
347 if (AccountSortOrder == SortDirection::ASCENDING)
348 return LR.Max < RR.Max;
349 if (AccountSortOrder == SortDirection::DESCENDING)
350 return LR.Max > RR.Max;
351 llvm_unreachable("Unknown sort direction");
353 if (AccountSortOrder == SortDirection::ASCENDING)
354 return LR.Sum < RR.Sum;
355 if (AccountSortOrder == SortDirection::DESCENDING)
356 return LR.Sum > RR.Sum;
357 llvm_unreachable("Unknown sort direction");
359 llvm_unreachable("Unsupported sort order");
366 Results.erase(Results.begin() + AccountTop.getValue(), Results.end());
368 for (const auto &R : Results)
369 Fn(std::get<0>(R), std::get<1>(R), std::get<2>(R));
372 void LatencyAccountant::exportStatsAsText(raw_ostream &OS,
373 const XRayFileHeader &Header) const {
374 OS << "Functions with latencies: " << FunctionLatencies.size() << "\n";
376 // We spend some effort to make the text output more readable, so we do the
377 // following formatting decisions for each of the fields:
379 // - funcid: 32-bit, but we can determine the largest number and be
381 // a minimum of 5 characters, up to 9 characters, right aligned.
382 // - count: 64-bit, but we can determine the largest number and be
384 // a minimum of 5 characters, up to 9 characters, right aligned.
385 // - min, median, 90pct, 99pct, max: double precision, but we want to keep
386 // the values in seconds, with microsecond precision (0.000'001), so we
387 // have at most 6 significant digits, with the whole number part to be
389 // least 1 character. For readability we'll right-align, with full 9
391 // - debug info, function name: we format this as a concatenation of the
392 // debug info and the function name.
394 static constexpr char StatsHeaderFormat[] =
395 "{0,+9} {1,+10} [{2,+9}, {3,+9}, {4,+9}, {5,+9}, {6,+9}] {7,+9}";
396 static constexpr char StatsFormat[] =
397 R"({0,+9} {1,+10} [{2,+9:f6}, {3,+9:f6}, {4,+9:f6}, {5,+9:f6}, {6,+9:f6}] {7,+9:f6})";
398 OS << llvm::formatv(StatsHeaderFormat, "funcid", "count", "min", "med", "90p",
400 << llvm::formatv(" {0,-12}\n", "function");
401 exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {
402 OS << llvm::formatv(StatsFormat, FuncId, Count, Row.Min, Row.Median,
403 Row.Pct90, Row.Pct99, Row.Max, Row.Sum)
404 << " " << Row.DebugInfo << ": " << Row.Function << "\n";
408 void LatencyAccountant::exportStatsAsCSV(raw_ostream &OS,
409 const XRayFileHeader &Header) const {
410 OS << "funcid,count,min,median,90%ile,99%ile,max,sum,debug,function\n";
411 exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {
412 OS << FuncId << ',' << Count << ',' << Row.Min << ',' << Row.Median << ','
413 << Row.Pct90 << ',' << Row.Pct99 << ',' << Row.Max << "," << Row.Sum
414 << ",\"" << Row.DebugInfo << "\",\"" << Row.Function << "\"\n";
418 using namespace llvm::xray;
420 static CommandRegistration Unused(&Account, []() -> Error {
422 auto EC = sys::fs::openFileForRead(AccountInput, Fd);
424 return make_error<StringError>(
425 Twine("Cannot open file '") + AccountInput + "'", EC);
427 Error Err = Error::success();
428 xray::InstrumentationMapExtractor Extractor(AccountInstrMap, InstrMapFormat,
430 if (auto E = handleErrors(
431 std::move(Err), [&](std::unique_ptr<StringError> SE) -> Error {
432 if (SE->convertToErrorCode() == std::errc::no_such_file_or_directory)
433 return Error::success();
434 return Error(std::move(SE));
438 raw_fd_ostream OS(AccountOutput, EC, sys::fs::OpenFlags::F_Text);
440 return make_error<StringError>(
441 Twine("Cannot open file '") + AccountOutput + "' for writing.", EC);
443 const auto &FunctionAddresses = Extractor.getFunctionAddresses();
444 symbolize::LLVMSymbolizer::Options Opts(
445 symbolize::FunctionNameKind::LinkageName, true, true, false, "");
446 symbolize::LLVMSymbolizer Symbolizer(Opts);
447 llvm::xray::FuncIdConversionHelper FuncIdHelper(AccountInstrMap, Symbolizer,
449 xray::LatencyAccountant FCA(FuncIdHelper, AccountDeduceSiblingCalls);
450 if (auto TraceOrErr = loadTraceFile(AccountInput)) {
451 auto &T = *TraceOrErr;
452 for (const auto &Record : T) {
453 if (FCA.accountRecord(Record))
455 for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) {
456 errs() << "Thread ID: " << ThreadStack.first << "\n";
457 auto Level = ThreadStack.second.size();
458 for (const auto &Entry : llvm::reverse(ThreadStack.second))
459 errs() << "#" << Level-- << "\t"
460 << FuncIdHelper.SymbolOrNumber(Entry.first) << '\n';
462 if (!AccountKeepGoing)
463 return make_error<StringError>(
464 Twine("Failed accounting function calls in file '") + AccountInput +
466 std::make_error_code(std::errc::executable_format_error));
468 switch (AccountOutputFormat) {
469 case AccountOutputFormats::TEXT:
470 FCA.exportStatsAsText(OS, T.getFileHeader());
472 case AccountOutputFormats::CSV:
473 FCA.exportStatsAsCSV(OS, T.getFileHeader());
478 make_error<StringError>(
479 Twine("Failed loading input file '") + AccountInput + "'",
480 std::make_error_code(std::errc::executable_format_error)),
481 TraceOrErr.takeError());
484 return Error::success();