llvm/tools/llvm-xray/xray-account.cpp

   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
  28 using namespace llvm;
  29 using namespace llvm::xray;
  30
  31 static cl::SubCommand Account("account", "Function call accounting");
  32 static cl::opt<std::string> AccountInput(cl::Positional,
  33                                          cl::desc("<xray log file>"),
  34                                          cl::Required, cl::sub(Account));
  35 static cl::opt<bool>
  36     AccountKeepGoing("keep-going", cl::desc("Keep going on errors encountered"),
  37                      cl::sub(Account), cl::init(false));
  38 static cl::alias AccountKeepGoing2("k", cl::aliasopt(AccountKeepGoing),
  39                                    cl::desc("Alias for -keep_going"));
  40 static cl::opt<bool> AccountRecursiveCallsOnly(
  41     "recursive-calls-only", cl::desc("Only count the calls that are recursive"),
  42     cl::sub(Account), cl::init(false));
  43 static 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(false));
  47 static cl::alias
  48     AccountDeduceSiblingCalls2("d", cl::aliasopt(AccountDeduceSiblingCalls),
  49                                cl::desc("Alias for -deduce_sibling_calls"));
  50 static cl::opt<std::string>
  51     AccountOutput("output", cl::value_desc("output file"), cl::init("-"),
  52                   cl::desc("output file; use '-' for stdout"),
  53                   cl::sub(Account));
  54 static cl::alias AccountOutput2("o", cl::aliasopt(AccountOutput),
  55                                 cl::desc("Alias for -output"));
  56 enum class AccountOutputFormats { TEXT, CSV };
  57 static 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));
  64 static cl::alias AccountOutputFormat2("f", cl::desc("Alias of -format"),
  65                                       cl::aliasopt(AccountOutputFormat));
  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", "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")));
  91 static cl::alias AccountSortOutput2("s", cl::aliasopt(AccountSortOutput),
  92                                     cl::desc("Alias for -sort"));
  93
  94 enum class SortDirection {
  95   ASCENDING,
  96   DESCENDING,
  97 };
  98 static cl::opt<SortDirection> AccountSortOrder(
  99     "sortorder", cl::desc("sort ordering"), cl::init(SortDirection::ASCENDING),
 100     cl::values(clEnumValN(SortDirection::ASCENDING, "asc", "ascending"),
 101                clEnumValN(SortDirection::DESCENDING, "dsc", "descending")),
 102     cl::sub(Account));
 103 static cl::alias AccountSortOrder2("r", cl::aliasopt(AccountSortOrder),
 104                                    cl::desc("Alias for -sortorder"));
 105
 106 static cl::opt<int> AccountTop("top", cl::desc("only show the top N results"),
 107                                cl::value_desc("N"), cl::sub(Account),
 108                                cl::init(-1));
 109 static cl::alias AccountTop2("p", cl::desc("Alias for -top"),
 110                              cl::aliasopt(AccountTop));
 111
 112 static 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(""));
 118 static cl::alias AccountInstrMap2("m", cl::aliasopt(AccountInstrMap),
 119                                   cl::desc("Alias for -instr_map"));
 120
 121 namespace {
 122
 123 template <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
 130 template <class T> T diff(T L, T R) { return std::max(L, R) - std::min(L, R); }
 131
 132 } // namespace
 133
 134 using RecursionStatus = LatencyAccountant::FunctionStack::RecursionStatus;
 135 RecursionStatus &RecursionStatus::operator++() {
 136   auto Depth = Bitfield::get<RecursionStatus::Depth>(Storage);
 137   assert(Depth >= 0 && Depth < std::numeric_limits<decltype(Depth)>::max());
 138   ++Depth;
 139   Bitfield::set<RecursionStatus::Depth>(Storage, 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>(Storage,
 143                                                 true); // Storage |= INT_MIN
 144   return *this;
 145 }
 146 RecursionStatus &RecursionStatus::operator--() {
 147   auto Depth = Bitfield::get<RecursionStatus::Depth>(Storage);
 148   assert(Depth > 0);
 149   --Depth;
 150   Bitfield::set<RecursionStatus::Depth>(Storage, 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>(Storage, false); // Storage = 0
 154   return *this;
 155 }
 156 bool RecursionStatus::isRecursive() const {
 157   return Bitfield::get<RecursionStatus::IsRecursive>(Storage); // Storage s< 0
 158 }
 159
 160 bool LatencyAccountant::accountRecord(const XRayRecord &Record) {
 161   setMinMax(PerThreadMinMaxTSC[Record.TId], Record.TSC);
 162   setMinMax(PerCPUMinMaxTSC[Record.CPU], 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(Record.FuncId, 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(Top.first, diff(Top.second, 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(llvm::reverse(ThreadStack.Stack),
 207                       [&](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(std::next(Parent).base(), ThreadStack.Stack.end());
 242     for (auto &E : R) {
 243       if (!ThreadStack.RecursionDepth ||
 244           (*ThreadStack.RecursionDepth)[E.first].isRecursive())
 245         recordLatency(E.first, diff(E.second, Record.TSC));
 246     }
 247     for (auto &Top : reverse(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
 259 namespace {
 260
 261 // We consolidate the data into a struct which we can output in various forms.
 262 struct 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
 274 ResultRow getStats(MutableArrayRef<uint64_t> Timings) {
 275   assert(!Timings.empty());
 276   ResultRow R;
 277   R.Sum = std::accumulate(Timings.begin(), Timings.end(), 0.0);
 278   auto MinMax = std::minmax_element(Timings.begin(), 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(Timings.begin(), Timings.begin() + MedianOff, Timings.end());
 285   R.Median = Timings[MedianOff];
 286
 287   auto Pct90Off = std::floor(Timings.size() * 0.9);
 288   std::nth_element(Timings.begin(), Timings.begin() + (uint64_t)Pct90Off,
 289                    Timings.end());
 290   R.Pct90 = Timings[Pct90Off];
 291
 292   auto Pct99Off = std::floor(Timings.size() * 0.99);
 293   std::nth_element(Timings.begin(), Timings.begin() + (uint64_t)Pct99Off,
 294                    Timings.end());
 295   R.Pct99 = Timings[Pct99Off];
 296   return R;
 297 }
 298
 299 } // namespace
 300
 301 using TupleType = std::tuple<int32_t, uint64_t, ResultRow>;
 302
 303 template <typename F>
 304 static 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
 311 template <class F>
 312 void LatencyAccountant::exportStats(const XRayFileHeader &Header, F Fn) const {
 313   std::vector<TupleType> Results;
 314   Results.reserve(FunctionLatencies.size());
 315   for (auto FT : FunctionLatencies) {
 316     const auto &FuncId = FT.first;
 317     auto &Timings = FT.second;
 318     Results.emplace_back(FuncId, Timings.size(), getStats(Timings));
 319     auto &Row = std::get<2>(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>(X); });
 338     break;
 339   case SortField::COUNT:
 340     sortByKey(Results, [](const TupleType &X) { return std::get<1>(X); });
 341     break;
 342   case SortField::MIN:
 343     sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Min; });
 344     break;
 345   case SortField::MED:
 346     sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Median; });
 347     break;
 348   case SortField::PCT90:
 349     sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Pct90; });
 350     break;
 351   case SortField::PCT99:
 352     sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Pct99; });
 353     break;
 354   case SortField::MAX:
 355     sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Max; });
 356     break;
 357   case SortField::SUM:
 358     sortByKey(Results, [](const TupleType &X) { return std::get<2>(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(AccountTop.getValue(), static_cast<int>(Results.size()));
 367     Results.erase(Results.begin() + MaxTop, Results.end());
 368   }
 369
 370   for (const auto &R : Results)
 371     Fn(std::get<0>(R), std::get<1>(R), std::get<2>(R));
 372 }
 373
 374 void 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(StatsHeaderFormat, "funcid", "count", "min", "med", "90p",
 401                       "99p", "max", "sum")
 402      << llvm::formatv("  {0,-12}\n", "function");
 403   exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {
 404     OS << llvm::formatv(StatsFormat, FuncId, Count, Row.Min, Row.Median,
 405                         Row.Pct90, Row.Pct99, Row.Max, Row.Sum)
 406        << "  " << Row.DebugInfo << ": " << Row.Function << "\n";
 407   });
 408 }
 409
 410 void 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, [&](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
 420 using namespace llvm::xray;
 421
 422 namespace llvm {
 423 template <> 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
 450 static CommandRegistration Unused(&Account, []() -> Error {
 451   InstrumentationMap Map;
 452   if (!AccountInstrMap.empty()) {
 453     auto InstrumentationMapOrError = loadInstrumentationMap(AccountInstrMap);
 454     if (!InstrumentationMapOrError)
 455       return joinErrors(make_error<StringError>(
 456                             Twine("Cannot open instrumentation map '") +
 457                                 AccountInstrMap + "'",
 458                             std::make_error_code(std::errc::invalid_argument)),
 459                         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         Twine("Cannot open file '") + AccountOutput + "' for writing.", 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(AccountInput);
 476   if (!TraceOrErr)
 477     return joinErrors(
 478         make_error<StringError>(
 479             Twine("Failed loading input file '") + AccountInput + "'",
 480             std::make_error_code(std::errc::executable_format_error)),
 481         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                R"({{type: {0}; cpu: {1}; record-type: {2}; function-id: {3}; tsc: {4}; thread-id: {5}; process-id: {6}}})",
 491                Record.RecordType, Record.CPU, Record.Type, Record.FuncId,
 492                Record.TSC, Record.TId, 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(ThreadStack.second.Stack))
 502         errs() << "  #" << Level-- << "\t"
 503                << FuncIdHelper.SymbolOrNumber(Entry.first) << '\n';
 504     }
 505     if (!AccountKeepGoing)
 506       return make_error<StringError>(
 507           Twine("Failed accounting function calls in file '") + AccountInput +
 508               "'.",
 509           std::make_error_code(std::errc::executable_format_error));
 510   }
 511   switch (AccountOutputFormat) {
 512   case AccountOutputFormats::TEXT:
 513     FCA.exportStatsAsText(OS, T.getFileHeader());
 514     break;
 515   case AccountOutputFormats::CSV:
 516     FCA.exportStatsAsCSV(OS, T.getFileHeader());
 517     break;
 518   }
 519
 520   return Error::success();
 521 });