tools/llvm-xray/xray-account.cpp

   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
 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
 133 template <class T> T diff(T L, T R) { return std::max(L, R) - std::min(L, R); }
 134
 135 } // namespace
 136
 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::ENTER:
 150   case RecordTypes::ENTER_ARG: {
 151     ThreadStack.emplace_back(Record.FuncId, Record.TSC);
 152     break;
 153   }
 154   case RecordTypes::EXIT:
 155   case RecordTypes::TAIL_EXIT: {
 156     if (ThreadStack.empty())
 157       return false;
 158
 159     if (ThreadStack.back().first == Record.FuncId) {
 160       const auto &Top = ThreadStack.back();
 161       recordLatency(Top.first, diff(Top.second, Record.TSC));
 162       ThreadStack.pop_back();
 163       break;
 164     }
 165
 166     if (!DeduceSiblingCalls)
 167       return false;
 168
 169     // Look for the parent up the stack.
 170     auto Parent =
 171         std::find_if(ThreadStack.rbegin(), ThreadStack.rend(),
 172                      [&](const std::pair<const int32_t, uint64_t> &E) {
 173                        return E.first == Record.FuncId;
 174                      });
 175     if (Parent == ThreadStack.rend())
 176       return false;
 177
 178     // Account time for this apparently sibling call exit up the stack.
 179     // Considering the following case:
 180     //
 181     //   f()
 182     //    g()
 183     //      h()
 184     //
 185     // We might only ever see the following entries:
 186     //
 187     //   -> f()
 188     //   -> g()
 189     //   -> h()
 190     //   <- h()
 191     //   <- f()
 192     //
 193     // Now we don't see the exit to g() because some older version of the XRay
 194     // runtime wasn't instrumenting tail exits. If we don't deduce tail calls,
 195     // we may potentially never account time for g() -- and this code would have
 196     // already bailed out, because `<- f()` doesn't match the current "top" of
 197     // stack where we're waiting for the exit to `g()` instead. This is not
 198     // ideal and brittle -- so instead we provide a potentially inaccurate
 199     // accounting of g() instead, computing it from the exit of f().
 200     //
 201     // While it might be better that we account the time between `-> g()` and
 202     // `-> h()` as the proper accounting of time for g() here, this introduces
 203     // complexity to do correctly (need to backtrack, etc.).
 204     //
 205     // FIXME: Potentially implement the more complex deduction algorithm?
 206     auto I = std::next(Parent).base();
 207     for (auto &E : make_range(I, ThreadStack.end())) {
 208       recordLatency(E.first, diff(E.second, Record.TSC));
 209     }
 210     ThreadStack.erase(I, ThreadStack.end());
 211     break;
 212   }
 213   }
 214
 215   return true;
 216 }
 217
 218 namespace {
 219
 220 // We consolidate the data into a struct which we can output in various forms.
 221 struct ResultRow {
 222   uint64_t Count;
 223   double Min;
 224   double Median;
 225   double Pct90;
 226   double Pct99;
 227   double Max;
 228   double Sum;
 229   std::string DebugInfo;
 230   std::string Function;
 231 };
 232
 233 ResultRow getStats(std::vector<uint64_t> &Timings) {
 234   assert(!Timings.empty());
 235   ResultRow R;
 236   R.Sum = std::accumulate(Timings.begin(), Timings.end(), 0.0);
 237   auto MinMax = std::minmax_element(Timings.begin(), Timings.end());
 238   R.Min = *MinMax.first;
 239   R.Max = *MinMax.second;
 240   R.Count = Timings.size();
 241
 242   auto MedianOff = Timings.size() / 2;
 243   std::nth_element(Timings.begin(), Timings.begin() + MedianOff, Timings.end());
 244   R.Median = Timings[MedianOff];
 245
 246   auto Pct90Off = std::floor(Timings.size() * 0.9);
 247   std::nth_element(Timings.begin(), Timings.begin() + Pct90Off, Timings.end());
 248   R.Pct90 = Timings[Pct90Off];
 249
 250   auto Pct99Off = std::floor(Timings.size() * 0.99);
 251   std::nth_element(Timings.begin(), Timings.begin() + Pct99Off, Timings.end());
 252   R.Pct99 = Timings[Pct99Off];
 253   return R;
 254 }
 255
 256 } // namespace
 257
 258 template <class F>
 259 void LatencyAccountant::exportStats(const XRayFileHeader &Header, F Fn) const {
 260   using TupleType = std::tuple<int32_t, uint64_t, ResultRow>;
 261   std::vector<TupleType> Results;
 262   Results.reserve(FunctionLatencies.size());
 263   for (auto FT : FunctionLatencies) {
 264     const auto &FuncId = FT.first;
 265     auto &Timings = FT.second;
 266     Results.emplace_back(FuncId, Timings.size(), getStats(Timings));
 267     auto &Row = std::get<2>(Results.back());
 268     if (Header.CycleFrequency) {
 269       double CycleFrequency = Header.CycleFrequency;
 270       Row.Min /= CycleFrequency;
 271       Row.Median /= CycleFrequency;
 272       Row.Pct90 /= CycleFrequency;
 273       Row.Pct99 /= CycleFrequency;
 274       Row.Max /= CycleFrequency;
 275       Row.Sum /= CycleFrequency;
 276     }
 277
 278     Row.Function = FuncIdHelper.SymbolOrNumber(FuncId);
 279     Row.DebugInfo = FuncIdHelper.FileLineAndColumn(FuncId);
 280   }
 281
 282   // Sort the data according to user-provided flags.
 283   switch (AccountSortOutput) {
 284   case SortField::FUNCID:
 285     llvm::sort(Results.begin(), Results.end(),
 286                [](const TupleType &L, const TupleType &R) {
 287                  if (AccountSortOrder == SortDirection::ASCENDING)
 288                    return std::get<0>(L) < std::get<0>(R);
 289                  if (AccountSortOrder == SortDirection::DESCENDING)
 290                    return std::get<0>(L) > std::get<0>(R);
 291                  llvm_unreachable("Unknown sort direction");
 292                });
 293     break;
 294   case SortField::COUNT:
 295     llvm::sort(Results.begin(), Results.end(),
 296                [](const TupleType &L, const TupleType &R) {
 297                  if (AccountSortOrder == SortDirection::ASCENDING)
 298                    return std::get<1>(L) < std::get<1>(R);
 299                  if (AccountSortOrder == SortDirection::DESCENDING)
 300                    return std::get<1>(L) > std::get<1>(R);
 301                  llvm_unreachable("Unknown sort direction");
 302                });
 303     break;
 304   default:
 305     // Here we need to look into the ResultRow for the rest of the data that
 306     // we want to sort by.
 307     llvm::sort(Results.begin(), Results.end(),
 308                [&](const TupleType &L, const TupleType &R) {
 309                  auto &LR = std::get<2>(L);
 310                  auto &RR = std::get<2>(R);
 311                  switch (AccountSortOutput) {
 312                  case SortField::COUNT:
 313                    if (AccountSortOrder == SortDirection::ASCENDING)
 314                      return LR.Count < RR.Count;
 315                    if (AccountSortOrder == SortDirection::DESCENDING)
 316                      return LR.Count > RR.Count;
 317                    llvm_unreachable("Unknown sort direction");
 318                  case SortField::MIN:
 319                    if (AccountSortOrder == SortDirection::ASCENDING)
 320                      return LR.Min < RR.Min;
 321                    if (AccountSortOrder == SortDirection::DESCENDING)
 322                      return LR.Min > RR.Min;
 323                    llvm_unreachable("Unknown sort direction");
 324                  case SortField::MED:
 325                    if (AccountSortOrder == SortDirection::ASCENDING)
 326                      return LR.Median < RR.Median;
 327                    if (AccountSortOrder == SortDirection::DESCENDING)
 328                      return LR.Median > RR.Median;
 329                    llvm_unreachable("Unknown sort direction");
 330                  case SortField::PCT90:
 331                    if (AccountSortOrder == SortDirection::ASCENDING)
 332                      return LR.Pct90 < RR.Pct90;
 333                    if (AccountSortOrder == SortDirection::DESCENDING)
 334                      return LR.Pct90 > RR.Pct90;
 335                    llvm_unreachable("Unknown sort direction");
 336                  case SortField::PCT99:
 337                    if (AccountSortOrder == SortDirection::ASCENDING)
 338                      return LR.Pct99 < RR.Pct99;
 339                    if (AccountSortOrder == SortDirection::DESCENDING)
 340                      return LR.Pct99 > RR.Pct99;
 341                    llvm_unreachable("Unknown sort direction");
 342                  case SortField::MAX:
 343                    if (AccountSortOrder == SortDirection::ASCENDING)
 344                      return LR.Max < RR.Max;
 345                    if (AccountSortOrder == SortDirection::DESCENDING)
 346                      return LR.Max > RR.Max;
 347                    llvm_unreachable("Unknown sort direction");
 348                  case SortField::SUM:
 349                    if (AccountSortOrder == SortDirection::ASCENDING)
 350                      return LR.Sum < RR.Sum;
 351                    if (AccountSortOrder == SortDirection::DESCENDING)
 352                      return LR.Sum > RR.Sum;
 353                    llvm_unreachable("Unknown sort direction");
 354                  default:
 355                    llvm_unreachable("Unsupported sort order");
 356                  }
 357                });
 358     break;
 359   }
 360
 361   if (AccountTop > 0) {
 362     auto MaxTop =
 363         std::min(AccountTop.getValue(), static_cast<int>(Results.size()));
 364     Results.erase(Results.begin() + MaxTop, Results.end());
 365   }
 366
 367   for (const auto &R : Results)
 368     Fn(std::get<0>(R), std::get<1>(R), std::get<2>(R));
 369 }
 370
 371 void LatencyAccountant::exportStatsAsText(raw_ostream &OS,
 372                                           const XRayFileHeader &Header) const {
 373   OS << "Functions with latencies: " << FunctionLatencies.size() << "\n";
 374
 375   // We spend some effort to make the text output more readable, so we do the
 376   // following formatting decisions for each of the fields:
 377   //
 378   //   - funcid: 32-bit, but we can determine the largest number and be
 379   //   between
 380   //     a minimum of 5 characters, up to 9 characters, right aligned.
 381   //   - count:  64-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   //   - min, median, 90pct, 99pct, max: double precision, but we want to keep
 385   //     the values in seconds, with microsecond precision (0.000'001), so we
 386   //     have at most 6 significant digits, with the whole number part to be
 387   //     at
 388   //     least 1 character. For readability we'll right-align, with full 9
 389   //     characters each.
 390   //   - debug info, function name: we format this as a concatenation of the
 391   //     debug info and the function name.
 392   //
 393   static constexpr char StatsHeaderFormat[] =
 394       "{0,+9} {1,+10} [{2,+9}, {3,+9}, {4,+9}, {5,+9}, {6,+9}] {7,+9}";
 395   static constexpr char StatsFormat[] =
 396       R"({0,+9} {1,+10} [{2,+9:f6}, {3,+9:f6}, {4,+9:f6}, {5,+9:f6}, {6,+9:f6}] {7,+9:f6})";
 397   OS << llvm::formatv(StatsHeaderFormat, "funcid", "count", "min", "med", "90p",
 398                       "99p", "max", "sum")
 399      << llvm::formatv("  {0,-12}\n", "function");
 400   exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {
 401     OS << llvm::formatv(StatsFormat, FuncId, Count, Row.Min, Row.Median,
 402                         Row.Pct90, Row.Pct99, Row.Max, Row.Sum)
 403        << "  " << Row.DebugInfo << ": " << Row.Function << "\n";
 404   });
 405 }
 406
 407 void LatencyAccountant::exportStatsAsCSV(raw_ostream &OS,
 408                                          const XRayFileHeader &Header) const {
 409   OS << "funcid,count,min,median,90%ile,99%ile,max,sum,debug,function\n";
 410   exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {
 411     OS << FuncId << ',' << Count << ',' << Row.Min << ',' << Row.Median << ','
 412        << Row.Pct90 << ',' << Row.Pct99 << ',' << Row.Max << "," << Row.Sum
 413        << ",\"" << Row.DebugInfo << "\",\"" << Row.Function << "\"\n";
 414   });
 415 }
 416
 417 using namespace llvm::xray;
 418
 419 namespace llvm {
 420 template <> struct format_provider<llvm::xray::RecordTypes> {
 421   static void format(const llvm::xray::RecordTypes &T, raw_ostream &Stream,
 422                      StringRef Style) {
 423     switch(T) {
 424       case RecordTypes::ENTER:
 425         Stream << "enter";
 426         break;
 427       case RecordTypes::ENTER_ARG:
 428         Stream << "enter-arg";
 429         break;
 430       case RecordTypes::EXIT:
 431         Stream << "exit";
 432         break;
 433       case RecordTypes::TAIL_EXIT:
 434         Stream << "tail-exit";
 435         break;
 436     }
 437   }
 438 };
 439 } // namespace llvm
 440
 441 static CommandRegistration Unused(&Account, []() -> Error {
 442   InstrumentationMap Map;
 443   if (!AccountInstrMap.empty()) {
 444     auto InstrumentationMapOrError = loadInstrumentationMap(AccountInstrMap);
 445     if (!InstrumentationMapOrError)
 446       return joinErrors(make_error<StringError>(
 447                             Twine("Cannot open instrumentation map '") +
 448                                 AccountInstrMap + "'",
 449                             std::make_error_code(std::errc::invalid_argument)),
 450                         InstrumentationMapOrError.takeError());
 451     Map = std::move(*InstrumentationMapOrError);
 452   }
 453
 454   std::error_code EC;
 455   raw_fd_ostream OS(AccountOutput, EC, sys::fs::OpenFlags::F_Text);
 456   if (EC)
 457     return make_error<StringError>(
 458         Twine("Cannot open file '") + AccountOutput + "' for writing.", EC);
 459
 460   const auto &FunctionAddresses = Map.getFunctionAddresses();
 461   symbolize::LLVMSymbolizer::Options Opts(
 462       symbolize::FunctionNameKind::LinkageName, true, true, false, "");
 463   symbolize::LLVMSymbolizer Symbolizer(Opts);
 464   llvm::xray::FuncIdConversionHelper FuncIdHelper(AccountInstrMap, Symbolizer,
 465                                                   FunctionAddresses);
 466   xray::LatencyAccountant FCA(FuncIdHelper, AccountDeduceSiblingCalls);
 467   auto TraceOrErr = loadTraceFile(AccountInput);
 468   if (!TraceOrErr)
 469     return joinErrors(
 470         make_error<StringError>(
 471             Twine("Failed loading input file '") + AccountInput + "'",
 472             std::make_error_code(std::errc::executable_format_error)),
 473         TraceOrErr.takeError());
 474
 475   auto &T = *TraceOrErr;
 476   for (const auto &Record : T) {
 477     if (FCA.accountRecord(Record))
 478       continue;
 479     errs()
 480         << "Error processing record: "
 481         << llvm::formatv(
 482                R"({{type: {0}; cpu: {1}; record-type: {2}; function-id: {3}; tsc: {4}; thread-id: {5}; process-id: {6}}})",
 483                Record.RecordType, Record.CPU, Record.Type, Record.FuncId,
 484                Record.TSC, Record.TId, Record.PId)
 485         << '\n';
 486     for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) {
 487       errs() << "Thread ID: " << ThreadStack.first << "\n";
 488       if (ThreadStack.second.empty()) {
 489         errs() << "  (empty stack)\n";
 490         continue;
 491       }
 492       auto Level = ThreadStack.second.size();
 493       for (const auto &Entry : llvm::reverse(ThreadStack.second))
 494         errs() << "  #" << Level-- << "\t"
 495                << FuncIdHelper.SymbolOrNumber(Entry.first) << '\n';
 496     }
 497     if (!AccountKeepGoing)
 498       return make_error<StringError>(
 499           Twine("Failed accounting function calls in file '") + AccountInput +
 500               "'.",
 501           std::make_error_code(std::errc::executable_format_error));
 502   }
 503   switch (AccountOutputFormat) {
 504   case AccountOutputFormats::TEXT:
 505     FCA.exportStatsAsText(OS, T.getFileHeader());
 506     break;
 507   case AccountOutputFormats::CSV:
 508     FCA.exportStatsAsCSV(OS, T.getFileHeader());
 509     break;
 510   }
 511
 512   return Error::success();
 513 });