517 lines · 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-exception6//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(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(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(false));47static cl::alias48 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("-"),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(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(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(-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(""));118static cl::alias AccountInstrMap2("m", cl::aliasopt(AccountInstrMap),119 cl::desc("Alias for -instr_map"));120 121template <class T, class U> static void setMinMax(std::pair<T, T> &MM, U &&V) {122 if (MM.first == 0 || MM.second == 0)123 MM = std::make_pair(std::forward<U>(V), std::forward<U>(V));124 else125 MM = std::make_pair(std::min(MM.first, V), std::max(MM.second, V));126}127 128template <class T> static T diff(T L, T R) {129 return std::max(L, R) - std::min(L, R);130}131 132using RecursionStatus = LatencyAccountant::FunctionStack::RecursionStatus;133RecursionStatus &RecursionStatus::operator++() {134 auto Depth = Bitfield::get<RecursionStatus::Depth>(Storage);135 assert(Depth >= 0 && Depth < std::numeric_limits<decltype(Depth)>::max());136 ++Depth;137 Bitfield::set<RecursionStatus::Depth>(Storage, Depth); // ++Storage138 // Did this function just (maybe indirectly) call itself the first time?139 if (!isRecursive() && Depth == 2) // Storage == 2 / Storage s> 1140 Bitfield::set<RecursionStatus::IsRecursive>(Storage,141 true); // Storage |= INT_MIN142 return *this;143}144 145RecursionStatus &RecursionStatus::operator--() {146 auto Depth = Bitfield::get<RecursionStatus::Depth>(Storage);147 assert(Depth > 0);148 --Depth;149 Bitfield::set<RecursionStatus::Depth>(Storage, Depth); // --Storage150 // Did we leave a function that previouly (maybe indirectly) called itself?151 if (isRecursive() && Depth == 0) // Storage == INT_MIN152 Bitfield::set<RecursionStatus::IsRecursive>(Storage, false); // Storage = 0153 return *this;154}155 156bool RecursionStatus::isRecursive() const {157 return Bitfield::get<RecursionStatus::IsRecursive>(Storage); // Storage s< 0158}159 160bool 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 XRay229 // 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 have231 // already bailed out, because `<- f()` doesn't match the current "top" of232 // stack where we're waiting for the exit to `g()` instead. This is not233 // ideal and brittle -- so instead we provide a potentially inaccurate234 // 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()` and237 // `-> h()` as the proper accounting of time for g() here, this introduces238 // 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 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} // namespace274 275static ResultRow getStats(MutableArrayRef<uint64_t> Timings) {276 assert(!Timings.empty());277 ResultRow R;278 R.Sum = std::accumulate(Timings.begin(), Timings.end(), 0.0);279 auto MinMax = std::minmax_element(Timings.begin(), Timings.end());280 R.Min = *MinMax.first;281 R.Max = *MinMax.second;282 R.Count = Timings.size();283 284 auto MedianOff = Timings.size() / 2;285 std::nth_element(Timings.begin(), Timings.begin() + MedianOff, Timings.end());286 R.Median = Timings[MedianOff];287 288 auto Pct90Off = std::floor(Timings.size() * 0.9);289 std::nth_element(Timings.begin(), Timings.begin() + (uint64_t)Pct90Off,290 Timings.end());291 R.Pct90 = Timings[Pct90Off];292 293 auto Pct99Off = std::floor(Timings.size() * 0.99);294 std::nth_element(Timings.begin(), Timings.begin() + (uint64_t)Pct99Off,295 Timings.end());296 R.Pct99 = Timings[Pct99Off];297 return R;298}299 300using TupleType = std::tuple<int32_t, uint64_t, ResultRow>;301 302template <typename F>303static void sortByKey(std::vector<TupleType> &Results, F Fn) {304 bool ASC = AccountSortOrder == SortDirection::ASCENDING;305 llvm::sort(Results, [=](const TupleType &L, const TupleType &R) {306 return ASC ? Fn(L) < Fn(R) : Fn(L) > Fn(R);307 });308}309 310template <class F>311void LatencyAccountant::exportStats(const XRayFileHeader &Header, F Fn) const {312 std::vector<TupleType> Results;313 Results.reserve(FunctionLatencies.size());314 for (auto FT : FunctionLatencies) {315 const auto &FuncId = FT.first;316 auto &Timings = FT.second;317 Results.emplace_back(FuncId, Timings.size(), getStats(Timings));318 auto &Row = std::get<2>(Results.back());319 if (Header.CycleFrequency) {320 double CycleFrequency = Header.CycleFrequency;321 Row.Min /= CycleFrequency;322 Row.Median /= CycleFrequency;323 Row.Pct90 /= CycleFrequency;324 Row.Pct99 /= CycleFrequency;325 Row.Max /= CycleFrequency;326 Row.Sum /= CycleFrequency;327 }328 329 Row.Function = FuncIdHelper.SymbolOrNumber(FuncId);330 Row.DebugInfo = FuncIdHelper.FileLineAndColumn(FuncId);331 }332 333 // Sort the data according to user-provided flags.334 switch (AccountSortOutput) {335 case SortField::FUNCID:336 sortByKey(Results, [](const TupleType &X) { return std::get<0>(X); });337 break;338 case SortField::COUNT:339 sortByKey(Results, [](const TupleType &X) { return std::get<1>(X); });340 break;341 case SortField::MIN:342 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Min; });343 break;344 case SortField::MED:345 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Median; });346 break;347 case SortField::PCT90:348 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Pct90; });349 break;350 case SortField::PCT99:351 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Pct99; });352 break;353 case SortField::MAX:354 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Max; });355 break;356 case SortField::SUM:357 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Sum; });358 break;359 case SortField::FUNC:360 llvm_unreachable("Not implemented");361 }362 363 if (AccountTop > 0) {364 auto MaxTop =365 std::min(AccountTop.getValue(), static_cast<int>(Results.size()));366 Results.erase(Results.begin() + MaxTop, Results.end());367 }368 369 for (const auto &R : Results)370 Fn(std::get<0>(R), std::get<1>(R), std::get<2>(R));371}372 373void LatencyAccountant::exportStatsAsText(raw_ostream &OS,374 const XRayFileHeader &Header) const {375 OS << "Functions with latencies: " << FunctionLatencies.size() << "\n";376 377 // We spend some effort to make the text output more readable, so we do the378 // following formatting decisions for each of the fields:379 //380 // - funcid: 32-bit, but we can determine the largest number and be381 // between382 // a minimum of 5 characters, up to 9 characters, right aligned.383 // - count: 64-bit, but we can determine the largest number and be384 // between385 // a minimum of 5 characters, up to 9 characters, right aligned.386 // - min, median, 90pct, 99pct, max: double precision, but we want to keep387 // the values in seconds, with microsecond precision (0.000'001), so we388 // have at most 6 significant digits, with the whole number part to be389 // at390 // least 1 character. For readability we'll right-align, with full 9391 // characters each.392 // - debug info, function name: we format this as a concatenation of the393 // debug info and the function name.394 //395 static constexpr char StatsHeaderFormat[] =396 "{0,+9} {1,+10} [{2,+9}, {3,+9}, {4,+9}, {5,+9}, {6,+9}] {7,+9}";397 static constexpr char StatsFormat[] =398 R"({0,+9} {1,+10} [{2,+9:f6}, {3,+9:f6}, {4,+9:f6}, {5,+9:f6}, {6,+9:f6}] {7,+9:f6})";399 OS << llvm::formatv(StatsHeaderFormat, "funcid", "count", "min", "med", "90p",400 "99p", "max", "sum")401 << llvm::formatv(" {0,-12}\n", "function");402 exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {403 OS << llvm::formatv(StatsFormat, FuncId, Count, Row.Min, Row.Median,404 Row.Pct90, Row.Pct99, Row.Max, Row.Sum)405 << " " << Row.DebugInfo << ": " << Row.Function << "\n";406 });407}408 409void LatencyAccountant::exportStatsAsCSV(raw_ostream &OS,410 const XRayFileHeader &Header) const {411 OS << "funcid,count,min,median,90%ile,99%ile,max,sum,debug,function\n";412 exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {413 OS << FuncId << ',' << Count << ',' << Row.Min << ',' << Row.Median << ','414 << Row.Pct90 << ',' << Row.Pct99 << ',' << Row.Max << "," << Row.Sum415 << ",\"" << Row.DebugInfo << "\",\"" << Row.Function << "\"\n";416 });417}418 419template <> struct llvm::format_provider<RecordTypes> {420 static void format(const RecordTypes &T, raw_ostream &Stream,421 StringRef Style) {422 switch (T) {423 case RecordTypes::ENTER:424 Stream << "enter";425 break;426 case RecordTypes::ENTER_ARG:427 Stream << "enter-arg";428 break;429 case RecordTypes::EXIT:430 Stream << "exit";431 break;432 case RecordTypes::TAIL_EXIT:433 Stream << "tail-exit";434 break;435 case RecordTypes::CUSTOM_EVENT:436 Stream << "custom-event";437 break;438 case RecordTypes::TYPED_EVENT:439 Stream << "typed-event";440 break;441 }442 }443};444 445static CommandRegistration Unused(&Account, []() -> Error {446 InstrumentationMap Map;447 if (!AccountInstrMap.empty()) {448 auto InstrumentationMapOrError = loadInstrumentationMap(AccountInstrMap);449 if (!InstrumentationMapOrError)450 return joinErrors(make_error<StringError>(451 Twine("Cannot open instrumentation map '") +452 AccountInstrMap + "'",453 std::make_error_code(std::errc::invalid_argument)),454 InstrumentationMapOrError.takeError());455 Map = std::move(*InstrumentationMapOrError);456 }457 458 std::error_code EC;459 raw_fd_ostream OS(AccountOutput, EC, sys::fs::OpenFlags::OF_TextWithCRLF);460 if (EC)461 return make_error<StringError>(462 Twine("Cannot open file '") + AccountOutput + "' for writing.", EC);463 464 const auto &FunctionAddresses = Map.getFunctionAddresses();465 symbolize::LLVMSymbolizer Symbolizer;466 FuncIdConversionHelper FuncIdHelper(AccountInstrMap, Symbolizer,467 FunctionAddresses);468 LatencyAccountant FCA(FuncIdHelper, AccountRecursiveCallsOnly,469 AccountDeduceSiblingCalls);470 auto TraceOrErr = loadTraceFile(AccountInput);471 if (!TraceOrErr)472 return joinErrors(473 make_error<StringError>(474 Twine("Failed loading input file '") + AccountInput + "'",475 std::make_error_code(std::errc::executable_format_error)),476 TraceOrErr.takeError());477 478 auto &T = *TraceOrErr;479 for (const auto &Record : T) {480 if (FCA.accountRecord(Record))481 continue;482 errs()483 << "Error processing record: "484 << llvm::formatv(485 R"({{type: {0}; cpu: {1}; record-type: {2}; function-id: {3}; tsc: {4}; thread-id: {5}; process-id: {6}}})",486 Record.RecordType, Record.CPU, Record.Type, Record.FuncId,487 Record.TSC, Record.TId, Record.PId)488 << '\n';489 for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) {490 errs() << "Thread ID: " << ThreadStack.first << "\n";491 if (ThreadStack.second.Stack.empty()) {492 errs() << " (empty stack)\n";493 continue;494 }495 auto Level = ThreadStack.second.Stack.size();496 for (const auto &Entry : llvm::reverse(ThreadStack.second.Stack))497 errs() << " #" << Level-- << "\t"498 << FuncIdHelper.SymbolOrNumber(Entry.first) << '\n';499 }500 if (!AccountKeepGoing)501 return make_error<StringError>(502 Twine("Failed accounting function calls in file '") + AccountInput +503 "'.",504 std::make_error_code(std::errc::executable_format_error));505 }506 switch (AccountOutputFormat) {507 case AccountOutputFormats::TEXT:508 FCA.exportStatsAsText(OS, T.getFileHeader());509 break;510 case AccountOutputFormats::CSV:511 FCA.exportStatsAsCSV(OS, T.getFileHeader());512 break;513 }514 515 return Error::success();516});517