xray-stacks.cpp 31 KB

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