Index: tools/llvm-xray/CMakeLists.txt =================================================================== --- tools/llvm-xray/CMakeLists.txt +++ tools/llvm-xray/CMakeLists.txt @@ -15,6 +15,7 @@ xray-extract.cc xray-graph.cc xray-graph-diff.cc + xray-stacks.cc xray-registry.cc) add_llvm_tool(llvm-xray llvm-xray.cc ${LLVM_XRAY_TOOLS}) Index: tools/llvm-xray/xray-stacks.cc =================================================================== --- /dev/null +++ tools/llvm-xray/xray-stacks.cc @@ -0,0 +1,424 @@ +//===- xray-stacks.cc - XRay Function Call Stack Accounting ---------------===// +// +// The LLVM Compiler Infrastructure +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// +// +// This file implements stack-based accounting. It takes XRay traces, and +// collates statistics across these traces to show a breakdown of time spent +// at various points of the stack to provide insight into which functions +// spend the most time in terms of a call stack. We provide a few +// sorting/filtering options for zero'ing in on the useful stacks. +// +//===----------------------------------------------------------------------===// + +#include +#include + +#include "func-id-helper.h" +#include "xray-registry.h" +#include "llvm/ADT/StringExtras.h" +#include "llvm/Support/CommandLine.h" +#include "llvm/Support/ErrorHandling.h" +#include "llvm/Support/FormatAdapters.h" +#include "llvm/Support/FormatVariadic.h" +#include "llvm/XRay/Graph.h" +#include "llvm/XRay/InstrumentationMap.h" +#include "llvm/XRay/Trace.h" + +using namespace llvm; +using namespace llvm::xray; + +static cl::SubCommand Stack("stack", "Call stack accounting"); +static cl::list StackInputs(cl::Positional, + cl::desc(""), cl::Required, + cl::sub(Stack), cl::OneOrMore); + +static cl::opt + StackKeepGoing("keep-going", cl::desc("Keep going on errors encountered"), + cl::sub(Stack), cl::init(false)); +static cl::alias StackKeepGoing2("k", cl::aliasopt(StackKeepGoing), + cl::desc("Alias for -keep-going"), + cl::sub(Stack)); + +static cl::opt StackDeduceSiblingCalls( + "deduce-sibling-calls", + cl::desc("Deduce sibling calls when unrolling function call stacks"), + cl::sub(Stack), cl::init(false)); +static cl::alias + StackDeduceSiblingCalls2("d", cl::aliasopt(StackDeduceSiblingCalls), + cl::desc("Alias for -deduce-sibling-calls"), + cl::sub(Stack)); + +static cl::opt StacksInstrMap( + "instr_map", cl::desc("instrumentation map used to identify function ids"), + cl::sub(Stack), cl::init("")); +static cl::alias StacksInstrMap2("m", cl::aliasopt(StacksInstrMap), + cl::desc("Alias for -instr_map"), + cl::sub(Stack)); + +// The stack command will take a set of XRay traces as arguments, and collects +// information about the stack traces that appear in the traces. We track the +// following pieces of information: +// +// - Total time: amount of time/cycles accounted for in the traces. +// - Stack count: number of times a specific stack trace appears in the +// traces. +// - Cumulative stack time: amount of time accumulated by a stack trace +// showing up across the traces. +// - Cumulative local time: amount of time accumulated by each function +// showing up in a specific stack trace, across the traces. +// +// Example output for the kind of data we'd like to provide looks like the +// following: +// +// Total time: 3.33234 s +// Stack ID: ... +// Stack Count: 2093 +// # Function Local Time (%) Stack Time (%) +// 0 main 2.34 ms 0.07% 3.33234 s 100% +// 1 foo() 3.30000 s 99.02% 3.33 s 99.92% +// 2 bar() 30 ms 0.90% 30 ms 0.90% +// +// We can also show distributions of the function call durations with statistics +// at each level of the stack. This works by doing the following algorithm: +// +// 1. When unwinding record the durations of each unwound functions associated +// with the path up to which the unwinding stops. For example: +// +// push a +// push b +// push c +// pop c +// pop b +// push c <-- before this, record durations for path a->b->c +// pop c +// pop a <-- stack emmpty, record durations for a->c +// +// 2. We then account for the various stacks we've collected, and for each of +// them will have measurements that look like the following (continuing +// with the above simple example): +// +// c : [b->c"), [durations]>, c"), [durations]>] +// b : [b->c"), [durations]>] +// a : [c"), [durations]>] +// +// This allows us to compute, for each stack id, and each function that +// shows up in the stack, some important statistics like: +// +// - median +// - 99th percentile +// - mean + stddev +// - count +// +// 3. For cases where we don't have durations for some of the higher levels of +// the stack, we can mark them appropriately. +// +// Computing this data also allows us to do this in reverse, so that we can +// find leaf functions that show up in multiple stack traces and show the +// statistical properties of that function in various contexts. We can show +// information similar to the following: +// +// Function: 'c' +// Stacks: 2 / 2 +// Stack ID: ... +// Stack Count: ... +// # Function ... +// 0 a ... +// 1 b ... +// 2 c ... +// +// Stack ID: ... +// Stack Count: ... +// # Function ... +// 0 a ... +// 1 c ... +// ----------------... +// +// Function: 'b' +// Stacks: 1 / 2 +// Stack ID: ... +// Stack Count: ... +// # Function ... +// 0 a ... +// 1 b ... +// 2 c ... +// +// +// To do this we're going to need a Trie data structure that will allow us to +// represent all the call stacks in an easily traversible manner later on when +// we do the aggregations and lookups. For the call sequences like the +// following: +// +// a() +// b() +// c() +// d() +// c() +// +// We will have a representation like so: +// +// a -> b -> c +// | | +// | +--> d +// | +// +--> c +// +// We maintain a sequence of durations on the leaves and in the internal nodes +// as we go through and process every record from the XRay trace. We also +// maintain an index of unique functions, and provide a means of iterating +// through all the call stacks which we know about. +class StackTrie { + struct TrieNode { + int32_t FuncId; + TrieNode *Parent; + SmallVector Callees; + SmallVector Durations; + }; + + // We maintain a pointer to the roots of the tries we see. + SmallVector Roots; + + // We make sure all the nodes are accounted for in this list. + std::list NodeStore; + + DenseMap, 8>> + ThreadStackMap; + + DenseMap> FuncIdIndex; + + TrieNode *createTrieNode(int32_t FuncId, TrieNode *Parent) { + auto I = + NodeStore.insert(NodeStore.end(), TrieNode{FuncId, Parent, {}, {}}); + auto Node = &*I; + if (Parent == nullptr) { + Roots.emplace_back(Node); + } + FuncIdIndex[FuncId].emplace_back(Node); + return Node; + } + + TrieNode *findRoot(int32_t FuncId) { + for (auto Node : Roots) + if (Node->FuncId == FuncId) + return Node; + return nullptr; + } + +public: + bool accountRecord(const XRayRecord &R) { + auto &TS = ThreadStackMap[R.TId]; + switch (R.Type) { + case RecordTypes::ENTER: { + // When we encounter a new function entry, we want to record the TSC for + // that entry, and the function id. Before doing so we check the top of + // the stack to see if there are callees that already represent this + // function. + if (TS.empty()) { + if (auto Root = findRoot(R.FuncId)) { + TS.emplace_back(Root, R.TSC); + } else { + TS.emplace_back(createTrieNode(R.FuncId, nullptr), R.TSC); + } + return true; + } + + auto &Top = TS.back(); + auto I = find_if(Top.first->Callees, + [&](TrieNode *N) { return N->FuncId == R.FuncId; }); + if (I == Top.first->Callees.end()) { + // We didn't find the callee in the stack trie, so we're going to + // add to the stack then set up the pointers properly. + auto N = createTrieNode(R.FuncId, Top.first); + Top.first->Callees.emplace_back(N); + + // Top may be invalidated after this statment. + TS.emplace_back(N, R.TSC); + } else { + // We found the callee in the stack trie, so we'll use that pointer + // instead, add it to the stack associated with the TSC. + TS.emplace_back(*I, R.TSC); + } + break; + } + case RecordTypes::EXIT: { + // The exit case is more interesting, since we want to be able to deduce + // missing exit records. To do that properly, we need to look up the stack + // and see whether the exit record matches any of the entry records. If it + // does match, we attempt to record the durations as we pop the stack to + // where we see the parent. + if (TS.empty()) { + // Short circuit, and say we can't find it. + return false; + } + + auto Parent = + find_if(reverse(TS), [&](const std::pair &E) { + return E.first->FuncId == R.FuncId; + }); + if (Parent == TS.rend()) { + // Clear the thread-stack and record the duration all the way. + for (auto &P : TS) + P.first->Durations.push_back(std::max(P.second, R.TSC) - + std::min(P.second, R.TSC)); + TS.clear(); + // Still return false because it's an error, potentially in the data. + return false; + } + auto I = std::next(Parent).base(); + for (auto &E : make_range(I, TS.end())) + E.first->Durations.push_back(std::max(E.second, R.TSC) - + std::min(E.second, R.TSC)); + TS.erase(I, TS.end()); + break; + } + } + return true; + } + + void printStack(raw_ostream &OS, const TrieNode *Top, + FuncIdConversionHelper &FN) { + // Traverse the pointers up to the parent, noting the sums, then print + // in reverse order (callers at top, callees down bottom). + SmallVector CurrentStack; + for (auto F = Top; F != nullptr; F = F->Parent) + CurrentStack.push_back(F); + int Level = 0; + OS << formatv("{0,-5} {1,-60} {2,+12} {3,+16}\n", "lvl", "function", + "count", "sum"); + for (auto F : reverse(CurrentStack)) { + auto Sum = std::accumulate(F->Durations.begin(), F->Durations.end(), 0LL); + auto Fn = FN.SymbolOrNumber(F->FuncId); + OS << formatv("#{0,-4} {1,-60} {2,+12} {3,+16}\n", Level++, + Fn.size() > 60 ? Fn.substr(0, 57) + "..." : Fn, + F->Durations.size(), Sum); + } + OS << "\n"; + } + + void print(raw_ostream &OS, FuncIdConversionHelper &FN) { + // Go through each of the roots, and traverse the call stack, producing the + // aggregates as you go along. Remember these aggregates and stacks, and + // show summary statistics about: + // + // - Total number of unique stacks + // - Top 10 stacks by count + // - Top 10 stacks by aggregate duration + SmallVector, 11> TopStacksByCount; + SmallVector, 11> TopStacksBySum; + auto greater_second = [](const std::pair &A, + const std::pair &B) { + return A.second > B.second; + }; + uint64_t UniqueStacks = 0; + for (const auto *N : Roots) { + SmallVector S; + S.emplace_back(N); + + while (!S.empty()) { + auto Top = S.pop_back_val(); + + // We only start printing the stack (by walking up the parent pointers) + // when we get to a leaf function. + if (Top->Callees.empty()) { + ++UniqueStacks; + auto TopSum = std::accumulate(Top->Durations.begin(), + Top->Durations.end(), 0uLL); + { + auto E = std::make_pair(Top, TopSum); + TopStacksBySum.insert(std::lower_bound(TopStacksBySum.begin(), + TopStacksBySum.end(), E, + greater_second), + E); + if (TopStacksBySum.size() == 11) + TopStacksBySum.pop_back(); + } + { + auto E = std::make_pair(Top, Top->Durations.size()); + TopStacksByCount.insert(std::lower_bound(TopStacksByCount.begin(), + TopStacksByCount.end(), E, + greater_second), + E); + if (TopStacksByCount.size() == 11) + TopStacksByCount.pop_back(); + } + + // printStack(OS, Top, FN); + } + for (const auto *C : Top->Callees) + S.emplace_back(C); + } + } + + // Now print the statistics in the end. + OS << "\n"; + OS << "Unique Stacks: " << UniqueStacks << "\n"; + OS << "Top 10 Stacks by leaf sum:\n\n"; + for (const auto &P : TopStacksBySum) { + OS << "Sum: " << P.second << "\n"; + printStack(OS, P.first, FN); + } + OS << "\n"; + OS << "Top 10 Stacks by leaf count:\n\n"; + for (const auto &P : TopStacksByCount) { + OS << "Count: " << P.second << "\n"; + printStack(OS, P.first, FN); + } + OS << "\n"; + } +}; + +static CommandRegistration Unused(&Stack, []() -> Error { + // Load each file provided as a command-line argument. For each one of them + // account to a single StackTrie, and just print the whole trie for now. + StackTrie ST; + InstrumentationMap Map; + if (!StacksInstrMap.empty()) { + auto InstrumentationMapOrError = loadInstrumentationMap(StacksInstrMap); + if (!InstrumentationMapOrError) + return joinErrors( + make_error( + Twine("Cannot open instrumentation map: ") + StacksInstrMap, + std::make_error_code(std::errc::invalid_argument)), + InstrumentationMapOrError.takeError()); + Map = std::move(*InstrumentationMapOrError); + } + + symbolize::LLVMSymbolizer::Options Opts( + symbolize::FunctionNameKind::LinkageName, true, true, false, ""); + symbolize::LLVMSymbolizer Symbolizer(Opts); + FuncIdConversionHelper FuncIdHelper(StacksInstrMap, Symbolizer, + Map.getFunctionAddresses()); + // TODO: Someday, support output to files instead of just directly to + // standard output. + for (const auto &Filename : StackInputs) { + auto TraceOrErr = loadTraceFile(Filename); + if (!TraceOrErr) { + if (!StackKeepGoing) + return joinErrors( + make_error( + Twine("Failed loading input file '") + Filename + "'", + std::make_error_code(std::errc::invalid_argument)), + TraceOrErr.takeError()); + logAllUnhandledErrors(TraceOrErr.takeError(), errs(), ""); + continue; + } + auto &T = *TraceOrErr; + DenseMap, 8>> + ThreadStacks; + for (const auto &Record : T) { + if (!ST.accountRecord(Record)) { + // FIXME: Print the error. + if (!StackKeepGoing) { + // FIXME: Return an error. + } + } + } + } + + ST.print(outs(), FuncIdHelper); + return Error::success(); +});