1 //===- xray-stacks.cpp: XRay Function Call Stack 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 stack-based accounting. It takes XRay traces, and 10 // collates statistics across these traces to show a breakdown of time spent 11 // at various points of the stack to provide insight into which functions 12 // spend the most time in terms of a call stack. We provide a few 13 // sorting/filtering options for zero'ing in on the useful stacks. 14 // 15 //===----------------------------------------------------------------------===// 16 17 #include <forward_list> 18 #include <numeric> 19 20 #include "func-id-helper.h" 21 #include "trie-node.h" 22 #include "xray-registry.h" 23 #include "llvm/ADT/StringExtras.h" 24 #include "llvm/Support/CommandLine.h" 25 #include "llvm/Support/Errc.h" 26 #include "llvm/Support/ErrorHandling.h" 27 #include "llvm/Support/FormatAdapters.h" 28 #include "llvm/Support/FormatVariadic.h" 29 #include "llvm/XRay/Graph.h" 30 #include "llvm/XRay/InstrumentationMap.h" 31 #include "llvm/XRay/Trace.h" 32 33 using namespace llvm; 34 using namespace llvm::xray; 35 36 static cl::SubCommand Stack("stack", "Call stack accounting"); 37 static cl::list<std::string> StackInputs(cl::Positional, 38 cl::desc("<xray trace>"), cl::Required, 39 cl::sub(Stack), cl::OneOrMore); 40 41 static cl::opt<bool> 42 StackKeepGoing("keep-going", cl::desc("Keep going on errors encountered"), 43 cl::sub(Stack), cl::init(false)); 44 static cl::alias StackKeepGoing2("k", cl::aliasopt(StackKeepGoing), 45 cl::desc("Alias for -keep-going"), 46 cl::sub(Stack)); 47 48 // TODO: Does there need to be an option to deduce tail or sibling calls? 49 50 static cl::opt<std::string> StacksInstrMap( 51 "instr_map", 52 cl::desc("instrumentation map used to identify function ids. " 53 "Currently supports elf file instrumentation maps."), 54 cl::sub(Stack), cl::init("")); 55 static cl::alias StacksInstrMap2("m", cl::aliasopt(StacksInstrMap), 56 cl::desc("Alias for -instr_map"), 57 cl::sub(Stack)); 58 59 static cl::opt<bool> 60 SeparateThreadStacks("per-thread-stacks", 61 cl::desc("Report top stacks within each thread id"), 62 cl::sub(Stack), cl::init(false)); 63 64 static cl::opt<bool> 65 AggregateThreads("aggregate-threads", 66 cl::desc("Aggregate stack times across threads"), 67 cl::sub(Stack), cl::init(false)); 68 69 static cl::opt<bool> 70 DumpAllStacks("all-stacks", 71 cl::desc("Dump sum of timings for all stacks. " 72 "By default separates stacks per-thread."), 73 cl::sub(Stack), cl::init(false)); 74 static cl::alias DumpAllStacksShort("all", cl::aliasopt(DumpAllStacks), 75 cl::desc("Alias for -all-stacks"), 76 cl::sub(Stack)); 77 78 // TODO(kpw): Add other interesting formats. Perhaps chrome trace viewer format 79 // possibly with aggregations or just a linear trace of timings. 80 enum StackOutputFormat { HUMAN, FLAMETOOL }; 81 82 static cl::opt<StackOutputFormat> StacksOutputFormat( 83 "stack-format", 84 cl::desc("The format that output stacks should be " 85 "output in. Only applies with all-stacks."), 86 cl::values( 87 clEnumValN(HUMAN, "human", 88 "Human readable output. Only valid without -all-stacks."), 89 clEnumValN(FLAMETOOL, "flame", 90 "Format consumable by Brendan Gregg's FlameGraph tool. " 91 "Only valid with -all-stacks.")), 92 cl::sub(Stack), cl::init(HUMAN)); 93 94 // Types of values for each stack in a CallTrie. 95 enum class AggregationType { 96 TOTAL_TIME, // The total time spent in a stack and its callees. 97 INVOCATION_COUNT // The number of times the stack was invoked. 98 }; 99 100 static cl::opt<AggregationType> RequestedAggregation( 101 "aggregation-type", 102 cl::desc("The type of aggregation to do on call stacks."), 103 cl::values( 104 clEnumValN( 105 AggregationType::TOTAL_TIME, "time", 106 "Capture the total time spent in an all invocations of a stack."), 107 clEnumValN(AggregationType::INVOCATION_COUNT, "count", 108 "Capture the number of times a stack was invoked. " 109 "In flamegraph mode, this count also includes invocations " 110 "of all callees.")), 111 cl::sub(Stack), cl::init(AggregationType::TOTAL_TIME)); 112 113 /// A helper struct to work with formatv and XRayRecords. Makes it easier to 114 /// use instrumentation map names or addresses in formatted output. 115 struct format_xray_record : public FormatAdapter<XRayRecord> { 116 explicit format_xray_record(XRayRecord record, 117 const FuncIdConversionHelper &conv) 118 : FormatAdapter<XRayRecord>(std::move(record)), Converter(&conv) {} 119 void format(raw_ostream &Stream, StringRef Style) override { 120 Stream << formatv( 121 "{FuncId: \"{0}\", ThreadId: \"{1}\", RecordType: \"{2}\"}", 122 Converter->SymbolOrNumber(Item.FuncId), Item.TId, 123 DecodeRecordType(Item.RecordType)); 124 } 125 126 private: 127 Twine DecodeRecordType(uint16_t recordType) { 128 switch (recordType) { 129 case 0: 130 return Twine("Fn Entry"); 131 case 1: 132 return Twine("Fn Exit"); 133 default: 134 // TODO: Add Tail exit when it is added to llvm/XRay/XRayRecord.h 135 return Twine("Unknown"); 136 } 137 } 138 139 const FuncIdConversionHelper *Converter; 140 }; 141 142 /// The stack command will take a set of XRay traces as arguments, and collects 143 /// information about the stacks of instrumented functions that appear in the 144 /// traces. We track the following pieces of information: 145 /// 146 /// - Total time: amount of time/cycles accounted for in the traces. 147 /// - Stack count: number of times a specific stack appears in the 148 /// traces. Only instrumented functions show up in stacks. 149 /// - Cumulative stack time: amount of time spent in a stack accumulated 150 /// across the invocations in the traces. 151 /// - Cumulative local time: amount of time spent in each instrumented 152 /// function showing up in a specific stack, accumulated across the traces. 153 /// 154 /// Example output for the kind of data we'd like to provide looks like the 155 /// following: 156 /// 157 /// Total time: 3.33234 s 158 /// Stack ID: ... 159 /// Stack Count: 2093 160 /// # Function Local Time (%) Stack Time (%) 161 /// 0 main 2.34 ms 0.07% 3.33234 s 100% 162 /// 1 foo() 3.30000 s 99.02% 3.33 s 99.92% 163 /// 2 bar() 30 ms 0.90% 30 ms 0.90% 164 /// 165 /// We can also show distributions of the function call durations with 166 /// statistics at each level of the stack. This works by doing the following 167 /// algorithm: 168 /// 169 /// 1. When unwinding, record the duration of each unwound function associated 170 /// with the path up to which the unwinding stops. For example: 171 /// 172 /// Step Duration (? means has start time) 173 /// 174 /// push a <start time> a = ? 175 /// push b <start time> a = ?, a->b = ? 176 /// push c <start time> a = ?, a->b = ?, a->b->c = ? 177 /// pop c <end time> a = ?, a->b = ?, emit duration(a->b->c) 178 /// pop b <end time> a = ?, emit duration(a->b) 179 /// push c <start time> a = ?, a->c = ? 180 /// pop c <end time> a = ?, emit duration(a->c) 181 /// pop a <end time> emit duration(a) 182 /// 183 /// 2. We then account for the various stacks we've collected, and for each of 184 /// them will have measurements that look like the following (continuing 185 /// with the above simple example): 186 /// 187 /// c : [<id("a->b->c"), [durations]>, <id("a->c"), [durations]>] 188 /// b : [<id("a->b"), [durations]>] 189 /// a : [<id("a"), [durations]>] 190 /// 191 /// This allows us to compute, for each stack id, and each function that 192 /// shows up in the stack, some important statistics like: 193 /// 194 /// - median 195 /// - 99th percentile 196 /// - mean + stddev 197 /// - count 198 /// 199 /// 3. For cases where we don't have durations for some of the higher levels 200 /// of the stack (perhaps instrumentation wasn't activated when the stack was 201 /// entered), we can mark them appropriately. 202 /// 203 /// Computing this data also allows us to implement lookup by call stack nodes, 204 /// so that we can find functions that show up in multiple stack traces and 205 /// show the statistical properties of that function in various contexts. We 206 /// can compute information similar to the following: 207 /// 208 /// Function: 'c' 209 /// Stacks: 2 / 2 210 /// Stack ID: ... 211 /// Stack Count: ... 212 /// # Function ... 213 /// 0 a ... 214 /// 1 b ... 215 /// 2 c ... 216 /// 217 /// Stack ID: ... 218 /// Stack Count: ... 219 /// # Function ... 220 /// 0 a ... 221 /// 1 c ... 222 /// ----------------... 223 /// 224 /// Function: 'b' 225 /// Stacks: 1 / 2 226 /// Stack ID: ... 227 /// Stack Count: ... 228 /// # Function ... 229 /// 0 a ... 230 /// 1 b ... 231 /// 2 c ... 232 /// 233 /// 234 /// To do this we require a Trie data structure that will allow us to represent 235 /// all the call stacks of instrumented functions in an easily traversible 236 /// manner when we do the aggregations and lookups. For instrumented call 237 /// sequences like the following: 238 /// 239 /// a() 240 /// b() 241 /// c() 242 /// d() 243 /// c() 244 /// 245 /// We will have a representation like so: 246 /// 247 /// a -> b -> c 248 /// | | 249 /// | +--> d 250 /// | 251 /// +--> c 252 /// 253 /// We maintain a sequence of durations on the leaves and in the internal nodes 254 /// as we go through and process every record from the XRay trace. We also 255 /// maintain an index of unique functions, and provide a means of iterating 256 /// through all the instrumented call stacks which we know about. 257 258 struct StackDuration { 259 llvm::SmallVector<int64_t, 4> TerminalDurations; 260 llvm::SmallVector<int64_t, 4> IntermediateDurations; 261 }; 262 263 StackDuration mergeStackDuration(const StackDuration &Left, 264 const StackDuration &Right) { 265 StackDuration Data{}; 266 Data.TerminalDurations.reserve(Left.TerminalDurations.size() + 267 Right.TerminalDurations.size()); 268 Data.IntermediateDurations.reserve(Left.IntermediateDurations.size() + 269 Right.IntermediateDurations.size()); 270 // Aggregate the durations. 271 for (auto duration : Left.TerminalDurations) 272 Data.TerminalDurations.push_back(duration); 273 for (auto duration : Right.TerminalDurations) 274 Data.TerminalDurations.push_back(duration); 275 276 for (auto duration : Left.IntermediateDurations) 277 Data.IntermediateDurations.push_back(duration); 278 for (auto duration : Right.IntermediateDurations) 279 Data.IntermediateDurations.push_back(duration); 280 return Data; 281 } 282 283 using StackTrieNode = TrieNode<StackDuration>; 284 285 template <AggregationType AggType> 286 std::size_t GetValueForStack(const StackTrieNode *Node); 287 288 // When computing total time spent in a stack, we're adding the timings from 289 // its callees and the timings from when it was a leaf. 290 template <> 291 std::size_t 292 GetValueForStack<AggregationType::TOTAL_TIME>(const StackTrieNode *Node) { 293 auto TopSum = std::accumulate(Node->ExtraData.TerminalDurations.begin(), 294 Node->ExtraData.TerminalDurations.end(), 0uLL); 295 return std::accumulate(Node->ExtraData.IntermediateDurations.begin(), 296 Node->ExtraData.IntermediateDurations.end(), TopSum); 297 } 298 299 // Calculates how many times a function was invoked. 300 // TODO: Hook up option to produce stacks 301 template <> 302 std::size_t 303 GetValueForStack<AggregationType::INVOCATION_COUNT>(const StackTrieNode *Node) { 304 return Node->ExtraData.TerminalDurations.size() + 305 Node->ExtraData.IntermediateDurations.size(); 306 } 307 308 // Make sure there are implementations for each enum value. 309 template <AggregationType T> struct DependentFalseType : std::false_type {}; 310 311 template <AggregationType AggType> 312 std::size_t GetValueForStack(const StackTrieNode *Node) { 313 static_assert(DependentFalseType<AggType>::value, 314 "No implementation found for aggregation type provided."); 315 return 0; 316 } 317 318 class StackTrie { 319 // Avoid the magic number of 4 propagated through the code with an alias. 320 // We use this SmallVector to track the root nodes in a call graph. 321 using RootVector = SmallVector<StackTrieNode *, 4>; 322 323 // We maintain pointers to the roots of the tries we see. 324 DenseMap<uint32_t, RootVector> Roots; 325 326 // We make sure all the nodes are accounted for in this list. 327 std::forward_list<StackTrieNode> NodeStore; 328 329 // A map of thread ids to pairs call stack trie nodes and their start times. 330 DenseMap<uint32_t, SmallVector<std::pair<StackTrieNode *, uint64_t>, 8>> 331 ThreadStackMap; 332 333 StackTrieNode *createTrieNode(uint32_t ThreadId, int32_t FuncId, 334 StackTrieNode *Parent) { 335 NodeStore.push_front(StackTrieNode{FuncId, Parent, {}, {{}, {}}}); 336 auto I = NodeStore.begin(); 337 auto *Node = &*I; 338 if (!Parent) 339 Roots[ThreadId].push_back(Node); 340 return Node; 341 } 342 343 StackTrieNode *findRootNode(uint32_t ThreadId, int32_t FuncId) { 344 const auto &RootsByThread = Roots[ThreadId]; 345 auto I = find_if(RootsByThread, 346 [&](StackTrieNode *N) { return N->FuncId == FuncId; }); 347 return (I == RootsByThread.end()) ? nullptr : *I; 348 } 349 350 public: 351 enum class AccountRecordStatus { 352 OK, // Successfully processed 353 ENTRY_NOT_FOUND, // An exit record had no matching call stack entry 354 UNKNOWN_RECORD_TYPE 355 }; 356 357 struct AccountRecordState { 358 // We keep track of whether the call stack is currently unwinding. 359 bool wasLastRecordExit; 360 361 static AccountRecordState CreateInitialState() { return {false}; } 362 }; 363 364 AccountRecordStatus accountRecord(const XRayRecord &R, 365 AccountRecordState *state) { 366 auto &TS = ThreadStackMap[R.TId]; 367 switch (R.Type) { 368 case RecordTypes::CUSTOM_EVENT: 369 case RecordTypes::TYPED_EVENT: 370 return AccountRecordStatus::OK; 371 case RecordTypes::ENTER: 372 case RecordTypes::ENTER_ARG: { 373 state->wasLastRecordExit = false; 374 // When we encounter a new function entry, we want to record the TSC for 375 // that entry, and the function id. Before doing so we check the top of 376 // the stack to see if there are callees that already represent this 377 // function. 378 if (TS.empty()) { 379 auto *Root = findRootNode(R.TId, R.FuncId); 380 TS.emplace_back(Root ? Root : createTrieNode(R.TId, R.FuncId, nullptr), 381 R.TSC); 382 return AccountRecordStatus::OK; 383 } 384 385 auto &Top = TS.back(); 386 auto I = find_if(Top.first->Callees, 387 [&](StackTrieNode *N) { return N->FuncId == R.FuncId; }); 388 if (I == Top.first->Callees.end()) { 389 // We didn't find the callee in the stack trie, so we're going to 390 // add to the stack then set up the pointers properly. 391 auto N = createTrieNode(R.TId, R.FuncId, Top.first); 392 Top.first->Callees.emplace_back(N); 393 394 // Top may be invalidated after this statement. 395 TS.emplace_back(N, R.TSC); 396 } else { 397 // We found the callee in the stack trie, so we'll use that pointer 398 // instead, add it to the stack associated with the TSC. 399 TS.emplace_back(*I, R.TSC); 400 } 401 return AccountRecordStatus::OK; 402 } 403 case RecordTypes::EXIT: 404 case RecordTypes::TAIL_EXIT: { 405 bool wasLastRecordExit = state->wasLastRecordExit; 406 state->wasLastRecordExit = true; 407 // The exit case is more interesting, since we want to be able to deduce 408 // missing exit records. To do that properly, we need to look up the stack 409 // and see whether the exit record matches any of the entry records. If it 410 // does match, we attempt to record the durations as we pop the stack to 411 // where we see the parent. 412 if (TS.empty()) { 413 // Short circuit, and say we can't find it. 414 415 return AccountRecordStatus::ENTRY_NOT_FOUND; 416 } 417 418 auto FunctionEntryMatch = find_if( 419 reverse(TS), [&](const std::pair<StackTrieNode *, uint64_t> &E) { 420 return E.first->FuncId == R.FuncId; 421 }); 422 auto status = AccountRecordStatus::OK; 423 if (FunctionEntryMatch == TS.rend()) { 424 status = AccountRecordStatus::ENTRY_NOT_FOUND; 425 } else { 426 // Account for offset of 1 between reverse and forward iterators. We 427 // want the forward iterator to include the function that is exited. 428 ++FunctionEntryMatch; 429 } 430 auto I = FunctionEntryMatch.base(); 431 for (auto &E : make_range(I, TS.end() - 1)) 432 E.first->ExtraData.IntermediateDurations.push_back( 433 std::max(E.second, R.TSC) - std::min(E.second, R.TSC)); 434 auto &Deepest = TS.back(); 435 if (wasLastRecordExit) 436 Deepest.first->ExtraData.IntermediateDurations.push_back( 437 std::max(Deepest.second, R.TSC) - std::min(Deepest.second, R.TSC)); 438 else 439 Deepest.first->ExtraData.TerminalDurations.push_back( 440 std::max(Deepest.second, R.TSC) - std::min(Deepest.second, R.TSC)); 441 TS.erase(I, TS.end()); 442 return status; 443 } 444 } 445 return AccountRecordStatus::UNKNOWN_RECORD_TYPE; 446 } 447 448 bool isEmpty() const { return Roots.empty(); } 449 450 void printStack(raw_ostream &OS, const StackTrieNode *Top, 451 FuncIdConversionHelper &FN) { 452 // Traverse the pointers up to the parent, noting the sums, then print 453 // in reverse order (callers at top, callees down bottom). 454 SmallVector<const StackTrieNode *, 8> CurrentStack; 455 for (auto *F = Top; F != nullptr; F = F->Parent) 456 CurrentStack.push_back(F); 457 int Level = 0; 458 OS << formatv("{0,-5} {1,-60} {2,+12} {3,+16}\n", "lvl", "function", 459 "count", "sum"); 460 for (auto *F : 461 reverse(make_range(CurrentStack.begin() + 1, CurrentStack.end()))) { 462 auto Sum = std::accumulate(F->ExtraData.IntermediateDurations.begin(), 463 F->ExtraData.IntermediateDurations.end(), 0LL); 464 auto FuncId = FN.SymbolOrNumber(F->FuncId); 465 OS << formatv("#{0,-4} {1,-60} {2,+12} {3,+16}\n", Level++, 466 FuncId.size() > 60 ? FuncId.substr(0, 57) + "..." : FuncId, 467 F->ExtraData.IntermediateDurations.size(), Sum); 468 } 469 auto *Leaf = *CurrentStack.begin(); 470 auto LeafSum = 471 std::accumulate(Leaf->ExtraData.TerminalDurations.begin(), 472 Leaf->ExtraData.TerminalDurations.end(), 0LL); 473 auto LeafFuncId = FN.SymbolOrNumber(Leaf->FuncId); 474 OS << formatv("#{0,-4} {1,-60} {2,+12} {3,+16}\n", Level++, 475 LeafFuncId.size() > 60 ? LeafFuncId.substr(0, 57) + "..." 476 : LeafFuncId, 477 Leaf->ExtraData.TerminalDurations.size(), LeafSum); 478 OS << "\n"; 479 } 480 481 /// Prints top stacks for each thread. 482 void printPerThread(raw_ostream &OS, FuncIdConversionHelper &FN) { 483 for (auto iter : Roots) { 484 OS << "Thread " << iter.first << ":\n"; 485 print(OS, FN, iter.second); 486 OS << "\n"; 487 } 488 } 489 490 /// Prints timing sums for each stack in each threads. 491 template <AggregationType AggType> 492 void printAllPerThread(raw_ostream &OS, FuncIdConversionHelper &FN, 493 StackOutputFormat format) { 494 for (auto iter : Roots) { 495 uint32_t threadId = iter.first; 496 RootVector &perThreadRoots = iter.second; 497 bool reportThreadId = true; 498 printAll<AggType>(OS, FN, perThreadRoots, threadId, reportThreadId); 499 } 500 } 501 502 /// Prints top stacks from looking at all the leaves and ignoring thread IDs. 503 /// Stacks that consist of the same function IDs but were called in different 504 /// thread IDs are not considered unique in this printout. 505 void printIgnoringThreads(raw_ostream &OS, FuncIdConversionHelper &FN) { 506 RootVector RootValues; 507 508 // Function to pull the values out of a map iterator. 509 using RootsType = decltype(Roots.begin())::value_type; 510 auto MapValueFn = [](const RootsType &Value) { return Value.second; }; 511 512 for (const auto &RootNodeRange : 513 make_range(map_iterator(Roots.begin(), MapValueFn), 514 map_iterator(Roots.end(), MapValueFn))) { 515 for (auto *RootNode : RootNodeRange) 516 RootValues.push_back(RootNode); 517 } 518 519 print(OS, FN, RootValues); 520 } 521 522 /// Creates a merged list of Tries for unique stacks that disregards their 523 /// thread IDs. 524 RootVector mergeAcrossThreads(std::forward_list<StackTrieNode> &NodeStore) { 525 RootVector MergedByThreadRoots; 526 for (auto MapIter : Roots) { 527 const auto &RootNodeVector = MapIter.second; 528 for (auto *Node : RootNodeVector) { 529 auto MaybeFoundIter = 530 find_if(MergedByThreadRoots, [Node](StackTrieNode *elem) { 531 return Node->FuncId == elem->FuncId; 532 }); 533 if (MaybeFoundIter == MergedByThreadRoots.end()) { 534 MergedByThreadRoots.push_back(Node); 535 } else { 536 MergedByThreadRoots.push_back(mergeTrieNodes( 537 **MaybeFoundIter, *Node, nullptr, NodeStore, mergeStackDuration)); 538 MergedByThreadRoots.erase(MaybeFoundIter); 539 } 540 } 541 } 542 return MergedByThreadRoots; 543 } 544 545 /// Print timing sums for all stacks merged by Thread ID. 546 template <AggregationType AggType> 547 void printAllAggregatingThreads(raw_ostream &OS, FuncIdConversionHelper &FN, 548 StackOutputFormat format) { 549 std::forward_list<StackTrieNode> AggregatedNodeStore; 550 RootVector MergedByThreadRoots = mergeAcrossThreads(AggregatedNodeStore); 551 bool reportThreadId = false; 552 printAll<AggType>(OS, FN, MergedByThreadRoots, 553 /*threadId*/ 0, reportThreadId); 554 } 555 556 /// Merges the trie by thread id before printing top stacks. 557 void printAggregatingThreads(raw_ostream &OS, FuncIdConversionHelper &FN) { 558 std::forward_list<StackTrieNode> AggregatedNodeStore; 559 RootVector MergedByThreadRoots = mergeAcrossThreads(AggregatedNodeStore); 560 print(OS, FN, MergedByThreadRoots); 561 } 562 563 // TODO: Add a format option when more than one are supported. 564 template <AggregationType AggType> 565 void printAll(raw_ostream &OS, FuncIdConversionHelper &FN, 566 RootVector RootValues, uint32_t ThreadId, bool ReportThread) { 567 SmallVector<const StackTrieNode *, 16> S; 568 for (const auto *N : RootValues) { 569 S.clear(); 570 S.push_back(N); 571 while (!S.empty()) { 572 auto *Top = S.pop_back_val(); 573 printSingleStack<AggType>(OS, FN, ReportThread, ThreadId, Top); 574 for (const auto *C : Top->Callees) 575 S.push_back(C); 576 } 577 } 578 } 579 580 /// Prints values for stacks in a format consumable for the flamegraph.pl 581 /// tool. This is a line based format that lists each level in the stack 582 /// hierarchy in a semicolon delimited form followed by a space and a numeric 583 /// value. If breaking down by thread, the thread ID will be added as the 584 /// root level of the stack. 585 template <AggregationType AggType> 586 void printSingleStack(raw_ostream &OS, FuncIdConversionHelper &Converter, 587 bool ReportThread, uint32_t ThreadId, 588 const StackTrieNode *Node) { 589 if (ReportThread) 590 OS << "thread_" << ThreadId << ";"; 591 SmallVector<const StackTrieNode *, 5> lineage{}; 592 lineage.push_back(Node); 593 while (lineage.back()->Parent != nullptr) 594 lineage.push_back(lineage.back()->Parent); 595 while (!lineage.empty()) { 596 OS << Converter.SymbolOrNumber(lineage.back()->FuncId) << ";"; 597 lineage.pop_back(); 598 } 599 OS << " " << GetValueForStack<AggType>(Node) << "\n"; 600 } 601 602 void print(raw_ostream &OS, FuncIdConversionHelper &FN, 603 RootVector RootValues) { 604 // Go through each of the roots, and traverse the call stack, producing the 605 // aggregates as you go along. Remember these aggregates and stacks, and 606 // show summary statistics about: 607 // 608 // - Total number of unique stacks 609 // - Top 10 stacks by count 610 // - Top 10 stacks by aggregate duration 611 SmallVector<std::pair<const StackTrieNode *, uint64_t>, 11> 612 TopStacksByCount; 613 SmallVector<std::pair<const StackTrieNode *, uint64_t>, 11> TopStacksBySum; 614 auto greater_second = 615 [](const std::pair<const StackTrieNode *, uint64_t> &A, 616 const std::pair<const StackTrieNode *, uint64_t> &B) { 617 return A.second > B.second; 618 }; 619 uint64_t UniqueStacks = 0; 620 for (const auto *N : RootValues) { 621 SmallVector<const StackTrieNode *, 16> S; 622 S.emplace_back(N); 623 624 while (!S.empty()) { 625 auto *Top = S.pop_back_val(); 626 627 // We only start printing the stack (by walking up the parent pointers) 628 // when we get to a leaf function. 629 if (!Top->ExtraData.TerminalDurations.empty()) { 630 ++UniqueStacks; 631 auto TopSum = 632 std::accumulate(Top->ExtraData.TerminalDurations.begin(), 633 Top->ExtraData.TerminalDurations.end(), 0uLL); 634 { 635 auto E = std::make_pair(Top, TopSum); 636 TopStacksBySum.insert( 637 llvm::lower_bound(TopStacksBySum, E, greater_second), E); 638 if (TopStacksBySum.size() == 11) 639 TopStacksBySum.pop_back(); 640 } 641 { 642 auto E = 643 std::make_pair(Top, Top->ExtraData.TerminalDurations.size()); 644 TopStacksByCount.insert(std::lower_bound(TopStacksByCount.begin(), 645 TopStacksByCount.end(), E, 646 greater_second), 647 E); 648 if (TopStacksByCount.size() == 11) 649 TopStacksByCount.pop_back(); 650 } 651 } 652 for (const auto *C : Top->Callees) 653 S.push_back(C); 654 } 655 } 656 657 // Now print the statistics in the end. 658 OS << "\n"; 659 OS << "Unique Stacks: " << UniqueStacks << "\n"; 660 OS << "Top 10 Stacks by leaf sum:\n\n"; 661 for (const auto &P : TopStacksBySum) { 662 OS << "Sum: " << P.second << "\n"; 663 printStack(OS, P.first, FN); 664 } 665 OS << "\n"; 666 OS << "Top 10 Stacks by leaf count:\n\n"; 667 for (const auto &P : TopStacksByCount) { 668 OS << "Count: " << P.second << "\n"; 669 printStack(OS, P.first, FN); 670 } 671 OS << "\n"; 672 } 673 }; 674 675 std::string CreateErrorMessage(StackTrie::AccountRecordStatus Error, 676 const XRayRecord &Record, 677 const FuncIdConversionHelper &Converter) { 678 switch (Error) { 679 case StackTrie::AccountRecordStatus::ENTRY_NOT_FOUND: 680 return formatv("Found record {0} with no matching function entry\n", 681 format_xray_record(Record, Converter)); 682 default: 683 return formatv("Unknown error type for record {0}\n", 684 format_xray_record(Record, Converter)); 685 } 686 } 687 688 static CommandRegistration Unused(&Stack, []() -> Error { 689 // Load each file provided as a command-line argument. For each one of them 690 // account to a single StackTrie, and just print the whole trie for now. 691 StackTrie ST; 692 InstrumentationMap Map; 693 if (!StacksInstrMap.empty()) { 694 auto InstrumentationMapOrError = loadInstrumentationMap(StacksInstrMap); 695 if (!InstrumentationMapOrError) 696 return joinErrors( 697 make_error<StringError>( 698 Twine("Cannot open instrumentation map: ") + StacksInstrMap, 699 std::make_error_code(std::errc::invalid_argument)), 700 InstrumentationMapOrError.takeError()); 701 Map = std::move(*InstrumentationMapOrError); 702 } 703 704 if (SeparateThreadStacks && AggregateThreads) 705 return make_error<StringError>( 706 Twine("Can't specify options for per thread reporting and reporting " 707 "that aggregates threads."), 708 std::make_error_code(std::errc::invalid_argument)); 709 710 if (!DumpAllStacks && StacksOutputFormat != HUMAN) 711 return make_error<StringError>( 712 Twine("Can't specify a non-human format without -all-stacks."), 713 std::make_error_code(std::errc::invalid_argument)); 714 715 if (DumpAllStacks && StacksOutputFormat == HUMAN) 716 return make_error<StringError>( 717 Twine("You must specify a non-human format when reporting with " 718 "-all-stacks."), 719 std::make_error_code(std::errc::invalid_argument)); 720 721 symbolize::LLVMSymbolizer Symbolizer; 722 FuncIdConversionHelper FuncIdHelper(StacksInstrMap, Symbolizer, 723 Map.getFunctionAddresses()); 724 // TODO: Someday, support output to files instead of just directly to 725 // standard output. 726 for (const auto &Filename : StackInputs) { 727 auto TraceOrErr = loadTraceFile(Filename); 728 if (!TraceOrErr) { 729 if (!StackKeepGoing) 730 return joinErrors( 731 make_error<StringError>( 732 Twine("Failed loading input file '") + Filename + "'", 733 std::make_error_code(std::errc::invalid_argument)), 734 TraceOrErr.takeError()); 735 logAllUnhandledErrors(TraceOrErr.takeError(), errs()); 736 continue; 737 } 738 auto &T = *TraceOrErr; 739 StackTrie::AccountRecordState AccountRecordState = 740 StackTrie::AccountRecordState::CreateInitialState(); 741 for (const auto &Record : T) { 742 auto error = ST.accountRecord(Record, &AccountRecordState); 743 if (error != StackTrie::AccountRecordStatus::OK) { 744 if (!StackKeepGoing) 745 return make_error<StringError>( 746 CreateErrorMessage(error, Record, FuncIdHelper), 747 make_error_code(errc::illegal_byte_sequence)); 748 errs() << CreateErrorMessage(error, Record, FuncIdHelper); 749 } 750 } 751 } 752 if (ST.isEmpty()) { 753 return make_error<StringError>( 754 "No instrumented calls were accounted in the input file.", 755 make_error_code(errc::result_out_of_range)); 756 } 757 758 // Report the stacks in a long form mode for another tool to analyze. 759 if (DumpAllStacks) { 760 if (AggregateThreads) { 761 switch (RequestedAggregation) { 762 case AggregationType::TOTAL_TIME: 763 ST.printAllAggregatingThreads<AggregationType::TOTAL_TIME>( 764 outs(), FuncIdHelper, StacksOutputFormat); 765 break; 766 case AggregationType::INVOCATION_COUNT: 767 ST.printAllAggregatingThreads<AggregationType::INVOCATION_COUNT>( 768 outs(), FuncIdHelper, StacksOutputFormat); 769 break; 770 } 771 } else { 772 switch (RequestedAggregation) { 773 case AggregationType::TOTAL_TIME: 774 ST.printAllPerThread<AggregationType::TOTAL_TIME>(outs(), FuncIdHelper, 775 StacksOutputFormat); 776 break; 777 case AggregationType::INVOCATION_COUNT: 778 ST.printAllPerThread<AggregationType::INVOCATION_COUNT>( 779 outs(), FuncIdHelper, StacksOutputFormat); 780 break; 781 } 782 } 783 return Error::success(); 784 } 785 786 // We're only outputting top stacks. 787 if (AggregateThreads) { 788 ST.printAggregatingThreads(outs(), FuncIdHelper); 789 } else if (SeparateThreadStacks) { 790 ST.printPerThread(outs(), FuncIdHelper); 791 } else { 792 ST.printIgnoringThreads(outs(), FuncIdHelper); 793 } 794 return Error::success(); 795 }); 796