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