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 using namespace llvm; 27 using namespace llvm::xray; 28 29 static cl::SubCommand Account("account", "Function call accounting"); 30 static cl::opt<std::string> AccountInput(cl::Positional, 31 cl::desc("<xray log file>"), 32 cl::Required, cl::sub(Account)); 33 static cl::opt<bool> 34 AccountKeepGoing("keep-going", cl::desc("Keep going on errors encountered"), 35 cl::sub(Account), cl::init(false)); 36 static cl::alias AccountKeepGoing2("k", cl::aliasopt(AccountKeepGoing), 37 cl::desc("Alias for -keep_going"), 38 cl::sub(Account)); 39 static cl::opt<bool> AccountDeduceSiblingCalls( 40 "deduce-sibling-calls", 41 cl::desc("Deduce sibling calls when unrolling function call stacks"), 42 cl::sub(Account), cl::init(false)); 43 static cl::alias 44 AccountDeduceSiblingCalls2("d", cl::aliasopt(AccountDeduceSiblingCalls), 45 cl::desc("Alias for -deduce_sibling_calls"), 46 cl::sub(Account)); 47 static cl::opt<std::string> 48 AccountOutput("output", cl::value_desc("output file"), cl::init("-"), 49 cl::desc("output file; use '-' for stdout"), 50 cl::sub(Account)); 51 static cl::alias AccountOutput2("o", cl::aliasopt(AccountOutput), 52 cl::desc("Alias for -output"), 53 cl::sub(Account)); 54 enum class AccountOutputFormats { TEXT, CSV }; 55 static cl::opt<AccountOutputFormats> 56 AccountOutputFormat("format", cl::desc("output format"), 57 cl::values(clEnumValN(AccountOutputFormats::TEXT, 58 "text", "report stats in text"), 59 clEnumValN(AccountOutputFormats::CSV, "csv", 60 "report stats in csv")), 61 cl::sub(Account)); 62 static cl::alias AccountOutputFormat2("f", cl::desc("Alias of -format"), 63 cl::aliasopt(AccountOutputFormat), 64 cl::sub(Account)); 65 66 enum class SortField { 67 FUNCID, 68 COUNT, 69 MIN, 70 MED, 71 PCT90, 72 PCT99, 73 MAX, 74 SUM, 75 FUNC, 76 }; 77 78 static cl::opt<SortField> AccountSortOutput( 79 "sort", cl::desc("sort output by this field"), cl::value_desc("field"), 80 cl::sub(Account), cl::init(SortField::FUNCID), 81 cl::values(clEnumValN(SortField::FUNCID, "funcid", "function id"), 82 clEnumValN(SortField::COUNT, "count", "funciton call counts"), 83 clEnumValN(SortField::MIN, "min", "minimum function durations"), 84 clEnumValN(SortField::MED, "med", "median function durations"), 85 clEnumValN(SortField::PCT90, "90p", "90th percentile durations"), 86 clEnumValN(SortField::PCT99, "99p", "99th percentile durations"), 87 clEnumValN(SortField::MAX, "max", "maximum function durations"), 88 clEnumValN(SortField::SUM, "sum", "sum of call durations"), 89 clEnumValN(SortField::FUNC, "func", "function names"))); 90 static cl::alias AccountSortOutput2("s", cl::aliasopt(AccountSortOutput), 91 cl::desc("Alias for -sort"), 92 cl::sub(Account)); 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 cl::sub(Account)); 106 107 static cl::opt<int> AccountTop("top", cl::desc("only show the top N results"), 108 cl::value_desc("N"), cl::sub(Account), 109 cl::init(-1)); 110 static cl::alias AccountTop2("p", cl::desc("Alias for -top"), 111 cl::aliasopt(AccountTop), cl::sub(Account)); 112 113 static cl::opt<std::string> 114 AccountInstrMap("instr_map", 115 cl::desc("binary with the instrumentation map, or " 116 "a separate instrumentation map"), 117 cl::value_desc("binary with xray_instr_map"), 118 cl::sub(Account), cl::init("")); 119 static cl::alias AccountInstrMap2("m", cl::aliasopt(AccountInstrMap), 120 cl::desc("Alias for -instr_map"), 121 cl::sub(Account)); 122 123 namespace { 124 125 template <class T, class U> void setMinMax(std::pair<T, T> &MM, U &&V) { 126 if (MM.first == 0 || MM.second == 0) 127 MM = std::make_pair(std::forward<U>(V), std::forward<U>(V)); 128 else 129 MM = std::make_pair(std::min(MM.first, V), std::max(MM.second, V)); 130 } 131 132 template <class T> T diff(T L, T R) { return std::max(L, R) - std::min(L, R); } 133 134 } // namespace 135 136 bool LatencyAccountant::accountRecord(const XRayRecord &Record) { 137 setMinMax(PerThreadMinMaxTSC[Record.TId], Record.TSC); 138 setMinMax(PerCPUMinMaxTSC[Record.CPU], Record.TSC); 139 140 if (CurrentMaxTSC == 0) 141 CurrentMaxTSC = Record.TSC; 142 143 if (Record.TSC < CurrentMaxTSC) 144 return false; 145 146 auto &ThreadStack = PerThreadFunctionStack[Record.TId]; 147 switch (Record.Type) { 148 case RecordTypes::CUSTOM_EVENT: 149 case RecordTypes::TYPED_EVENT: 150 // TODO: Support custom and typed event accounting in the future. 151 return true; 152 case RecordTypes::ENTER: 153 case RecordTypes::ENTER_ARG: { 154 ThreadStack.emplace_back(Record.FuncId, Record.TSC); 155 break; 156 } 157 case RecordTypes::EXIT: 158 case RecordTypes::TAIL_EXIT: { 159 if (ThreadStack.empty()) 160 return false; 161 162 if (ThreadStack.back().first == Record.FuncId) { 163 const auto &Top = ThreadStack.back(); 164 recordLatency(Top.first, diff(Top.second, Record.TSC)); 165 ThreadStack.pop_back(); 166 break; 167 } 168 169 if (!DeduceSiblingCalls) 170 return false; 171 172 // Look for the parent up the stack. 173 auto Parent = 174 std::find_if(ThreadStack.rbegin(), ThreadStack.rend(), 175 [&](const std::pair<const int32_t, uint64_t> &E) { 176 return E.first == Record.FuncId; 177 }); 178 if (Parent == ThreadStack.rend()) 179 return false; 180 181 // Account time for this apparently sibling call exit up the stack. 182 // Considering the following case: 183 // 184 // f() 185 // g() 186 // h() 187 // 188 // We might only ever see the following entries: 189 // 190 // -> f() 191 // -> g() 192 // -> h() 193 // <- h() 194 // <- f() 195 // 196 // Now we don't see the exit to g() because some older version of the XRay 197 // runtime wasn't instrumenting tail exits. If we don't deduce tail calls, 198 // we may potentially never account time for g() -- and this code would have 199 // already bailed out, because `<- f()` doesn't match the current "top" of 200 // stack where we're waiting for the exit to `g()` instead. This is not 201 // ideal and brittle -- so instead we provide a potentially inaccurate 202 // accounting of g() instead, computing it from the exit of f(). 203 // 204 // While it might be better that we account the time between `-> g()` and 205 // `-> h()` as the proper accounting of time for g() here, this introduces 206 // complexity to do correctly (need to backtrack, etc.). 207 // 208 // FIXME: Potentially implement the more complex deduction algorithm? 209 auto I = std::next(Parent).base(); 210 for (auto &E : make_range(I, ThreadStack.end())) { 211 recordLatency(E.first, diff(E.second, Record.TSC)); 212 } 213 ThreadStack.erase(I, ThreadStack.end()); 214 break; 215 } 216 } 217 218 return true; 219 } 220 221 namespace { 222 223 // We consolidate the data into a struct which we can output in various forms. 224 struct ResultRow { 225 uint64_t Count; 226 double Min; 227 double Median; 228 double Pct90; 229 double Pct99; 230 double Max; 231 double Sum; 232 std::string DebugInfo; 233 std::string Function; 234 }; 235 236 ResultRow getStats(std::vector<uint64_t> &Timings) { 237 assert(!Timings.empty()); 238 ResultRow R; 239 R.Sum = std::accumulate(Timings.begin(), Timings.end(), 0.0); 240 auto MinMax = std::minmax_element(Timings.begin(), Timings.end()); 241 R.Min = *MinMax.first; 242 R.Max = *MinMax.second; 243 R.Count = Timings.size(); 244 245 auto MedianOff = Timings.size() / 2; 246 std::nth_element(Timings.begin(), Timings.begin() + MedianOff, Timings.end()); 247 R.Median = Timings[MedianOff]; 248 249 auto Pct90Off = std::floor(Timings.size() * 0.9); 250 std::nth_element(Timings.begin(), Timings.begin() + Pct90Off, Timings.end()); 251 R.Pct90 = Timings[Pct90Off]; 252 253 auto Pct99Off = std::floor(Timings.size() * 0.99); 254 std::nth_element(Timings.begin(), Timings.begin() + Pct99Off, Timings.end()); 255 R.Pct99 = Timings[Pct99Off]; 256 return R; 257 } 258 259 } // namespace 260 261 using TupleType = std::tuple<int32_t, uint64_t, ResultRow>; 262 263 template <typename F> 264 static void sortByKey(std::vector<TupleType> &Results, F Fn) { 265 bool ASC = AccountSortOrder == SortDirection::ASCENDING; 266 llvm::sort(Results, [=](const TupleType &L, const TupleType &R) { 267 return ASC ? Fn(L) < Fn(R) : Fn(L) > Fn(R); 268 }); 269 } 270 271 template <class F> 272 void LatencyAccountant::exportStats(const XRayFileHeader &Header, F Fn) const { 273 std::vector<TupleType> Results; 274 Results.reserve(FunctionLatencies.size()); 275 for (auto FT : FunctionLatencies) { 276 const auto &FuncId = FT.first; 277 auto &Timings = FT.second; 278 Results.emplace_back(FuncId, Timings.size(), getStats(Timings)); 279 auto &Row = std::get<2>(Results.back()); 280 if (Header.CycleFrequency) { 281 double CycleFrequency = Header.CycleFrequency; 282 Row.Min /= CycleFrequency; 283 Row.Median /= CycleFrequency; 284 Row.Pct90 /= CycleFrequency; 285 Row.Pct99 /= CycleFrequency; 286 Row.Max /= CycleFrequency; 287 Row.Sum /= CycleFrequency; 288 } 289 290 Row.Function = FuncIdHelper.SymbolOrNumber(FuncId); 291 Row.DebugInfo = FuncIdHelper.FileLineAndColumn(FuncId); 292 } 293 294 // Sort the data according to user-provided flags. 295 switch (AccountSortOutput) { 296 case SortField::FUNCID: 297 sortByKey(Results, [](const TupleType &X) { return std::get<0>(X); }); 298 break; 299 case SortField::COUNT: 300 sortByKey(Results, [](const TupleType &X) { return std::get<1>(X); }); 301 break; 302 case SortField::MIN: 303 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Min; }); 304 break; 305 case SortField::MED: 306 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Median; }); 307 break; 308 case SortField::PCT90: 309 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Pct90; }); 310 break; 311 case SortField::PCT99: 312 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Pct99; }); 313 break; 314 case SortField::MAX: 315 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Max; }); 316 break; 317 case SortField::SUM: 318 sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Sum; }); 319 break; 320 case SortField::FUNC: 321 llvm_unreachable("Not implemented"); 322 } 323 324 if (AccountTop > 0) { 325 auto MaxTop = 326 std::min(AccountTop.getValue(), static_cast<int>(Results.size())); 327 Results.erase(Results.begin() + MaxTop, Results.end()); 328 } 329 330 for (const auto &R : Results) 331 Fn(std::get<0>(R), std::get<1>(R), std::get<2>(R)); 332 } 333 334 void LatencyAccountant::exportStatsAsText(raw_ostream &OS, 335 const XRayFileHeader &Header) const { 336 OS << "Functions with latencies: " << FunctionLatencies.size() << "\n"; 337 338 // We spend some effort to make the text output more readable, so we do the 339 // following formatting decisions for each of the fields: 340 // 341 // - funcid: 32-bit, but we can determine the largest number and be 342 // between 343 // a minimum of 5 characters, up to 9 characters, right aligned. 344 // - count: 64-bit, but we can determine the largest number and be 345 // between 346 // a minimum of 5 characters, up to 9 characters, right aligned. 347 // - min, median, 90pct, 99pct, max: double precision, but we want to keep 348 // the values in seconds, with microsecond precision (0.000'001), so we 349 // have at most 6 significant digits, with the whole number part to be 350 // at 351 // least 1 character. For readability we'll right-align, with full 9 352 // characters each. 353 // - debug info, function name: we format this as a concatenation of the 354 // debug info and the function name. 355 // 356 static constexpr char StatsHeaderFormat[] = 357 "{0,+9} {1,+10} [{2,+9}, {3,+9}, {4,+9}, {5,+9}, {6,+9}] {7,+9}"; 358 static constexpr char StatsFormat[] = 359 R"({0,+9} {1,+10} [{2,+9:f6}, {3,+9:f6}, {4,+9:f6}, {5,+9:f6}, {6,+9:f6}] {7,+9:f6})"; 360 OS << llvm::formatv(StatsHeaderFormat, "funcid", "count", "min", "med", "90p", 361 "99p", "max", "sum") 362 << llvm::formatv(" {0,-12}\n", "function"); 363 exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) { 364 OS << llvm::formatv(StatsFormat, FuncId, Count, Row.Min, Row.Median, 365 Row.Pct90, Row.Pct99, Row.Max, Row.Sum) 366 << " " << Row.DebugInfo << ": " << Row.Function << "\n"; 367 }); 368 } 369 370 void LatencyAccountant::exportStatsAsCSV(raw_ostream &OS, 371 const XRayFileHeader &Header) const { 372 OS << "funcid,count,min,median,90%ile,99%ile,max,sum,debug,function\n"; 373 exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) { 374 OS << FuncId << ',' << Count << ',' << Row.Min << ',' << Row.Median << ',' 375 << Row.Pct90 << ',' << Row.Pct99 << ',' << Row.Max << "," << Row.Sum 376 << ",\"" << Row.DebugInfo << "\",\"" << Row.Function << "\"\n"; 377 }); 378 } 379 380 using namespace llvm::xray; 381 382 namespace llvm { 383 template <> struct format_provider<llvm::xray::RecordTypes> { 384 static void format(const llvm::xray::RecordTypes &T, raw_ostream &Stream, 385 StringRef Style) { 386 switch (T) { 387 case RecordTypes::ENTER: 388 Stream << "enter"; 389 break; 390 case RecordTypes::ENTER_ARG: 391 Stream << "enter-arg"; 392 break; 393 case RecordTypes::EXIT: 394 Stream << "exit"; 395 break; 396 case RecordTypes::TAIL_EXIT: 397 Stream << "tail-exit"; 398 break; 399 case RecordTypes::CUSTOM_EVENT: 400 Stream << "custom-event"; 401 break; 402 case RecordTypes::TYPED_EVENT: 403 Stream << "typed-event"; 404 break; 405 } 406 } 407 }; 408 } // namespace llvm 409 410 static CommandRegistration Unused(&Account, []() -> Error { 411 InstrumentationMap Map; 412 if (!AccountInstrMap.empty()) { 413 auto InstrumentationMapOrError = loadInstrumentationMap(AccountInstrMap); 414 if (!InstrumentationMapOrError) 415 return joinErrors(make_error<StringError>( 416 Twine("Cannot open instrumentation map '") + 417 AccountInstrMap + "'", 418 std::make_error_code(std::errc::invalid_argument)), 419 InstrumentationMapOrError.takeError()); 420 Map = std::move(*InstrumentationMapOrError); 421 } 422 423 std::error_code EC; 424 raw_fd_ostream OS(AccountOutput, EC, sys::fs::OpenFlags::F_Text); 425 if (EC) 426 return make_error<StringError>( 427 Twine("Cannot open file '") + AccountOutput + "' for writing.", EC); 428 429 const auto &FunctionAddresses = Map.getFunctionAddresses(); 430 symbolize::LLVMSymbolizer Symbolizer; 431 llvm::xray::FuncIdConversionHelper FuncIdHelper(AccountInstrMap, Symbolizer, 432 FunctionAddresses); 433 xray::LatencyAccountant FCA(FuncIdHelper, AccountDeduceSiblingCalls); 434 auto TraceOrErr = loadTraceFile(AccountInput); 435 if (!TraceOrErr) 436 return joinErrors( 437 make_error<StringError>( 438 Twine("Failed loading input file '") + AccountInput + "'", 439 std::make_error_code(std::errc::executable_format_error)), 440 TraceOrErr.takeError()); 441 442 auto &T = *TraceOrErr; 443 for (const auto &Record : T) { 444 if (FCA.accountRecord(Record)) 445 continue; 446 errs() 447 << "Error processing record: " 448 << llvm::formatv( 449 R"({{type: {0}; cpu: {1}; record-type: {2}; function-id: {3}; tsc: {4}; thread-id: {5}; process-id: {6}}})", 450 Record.RecordType, Record.CPU, Record.Type, Record.FuncId, 451 Record.TSC, Record.TId, Record.PId) 452 << '\n'; 453 for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) { 454 errs() << "Thread ID: " << ThreadStack.first << "\n"; 455 if (ThreadStack.second.empty()) { 456 errs() << " (empty stack)\n"; 457 continue; 458 } 459 auto Level = ThreadStack.second.size(); 460 for (const auto &Entry : llvm::reverse(ThreadStack.second)) 461 errs() << " #" << Level-- << "\t" 462 << FuncIdHelper.SymbolOrNumber(Entry.first) << '\n'; 463 } 464 if (!AccountKeepGoing) 465 return make_error<StringError>( 466 Twine("Failed accounting function calls in file '") + AccountInput + 467 "'.", 468 std::make_error_code(std::errc::executable_format_error)); 469 } 470 switch (AccountOutputFormat) { 471 case AccountOutputFormats::TEXT: 472 FCA.exportStatsAsText(OS, T.getFileHeader()); 473 break; 474 case AccountOutputFormats::CSV: 475 FCA.exportStatsAsCSV(OS, T.getFileHeader()); 476 break; 477 } 478 479 return Error::success(); 480 }); 481