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