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 }); 522