Index: test/tools/llvm-xray/X86/Inputs/simple-instrmap.yaml =================================================================== --- /dev/null +++ test/tools/llvm-xray/X86/Inputs/simple-instrmap.yaml @@ -0,0 +1,10 @@ +# This is a simple instrumentation map with bogus addresses and offsets, but +# follow the recommended format. +--- +- { id: 1, address: 0x1, function: 0x1, kind: function-enter, always-instrument: true} +- { id: 1, address: 0x2, function: 0x1, kind: function-exit, always-instrument: true} +- { id: 2, address: 0x2, function: 0x2, kind: function-enter, always-instrument: true} +- { id: 2, address: 0x3, function: 0x2, kind: function-exit, always-instrument: true} +- { id: 3, address: 0x3, function: 0x3, kind: function-enter, always-instrument: true} +- { id: 3, address: 0x4, function: 0x3, kind: function-exit, always-instrument: true} +... Index: test/tools/llvm-xray/X86/account-deduce-tail-call.yaml =================================================================== --- /dev/null +++ test/tools/llvm-xray/X86/account-deduce-tail-call.yaml @@ -0,0 +1,36 @@ +#RUN: llvm-xray account %s -i=yaml -o - -m %S/Inputs/simple-instrmap.yaml -t yaml -d | FileCheck %s +--- +header: + version: 1 + type: 0 + constant-tsc: true + nonstop-tsc: true + cycle-frequency: 0 +records: +# Here we reconstruct the following call trace: +# +# f1() +# f2() +# f3() +# +# But we find that we're missing an exit record for f2() because it's +# tail-called f3(). We make sure that if we see a trace like this that we can +# deduce tail calls, and account the time (potentially wrongly) to f2() when +# f1() exits. That is because we don't go back to f3()'s entry record to +# properly do the math on the timing of f2(). +# +# Note that by default, tail/sibling call deduction is disabled, and is enabled +# with a flag "-d" or "-deduce-sibling-calls". +# + - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-enter, tsc: 10000 } + - { type: 0, func-id: 2, cpu: 1, thread: 111, kind: function-enter, tsc: 10001 } + - { type: 0, func-id: 3, cpu: 1, thread: 111, kind: function-enter, tsc: 10002 } + - { type: 0, func-id: 3, cpu: 1, thread: 111, kind: function-exit, tsc: 10003 } + - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-exit, tsc: 10004 } +... + +#CHECK: Functions with latencies: 3 +#CHECK-NEXT: funcid count [min, median, 90%ile, 99%ile, max] debug function +#CHECK-NEXT: 1 1 [4.{{.*}}, 4.{{.*}}, 4.{{.*}}, 4.{{.*}}, 4.{{.*}}] {{.*}} {{.*}} +#CHECK-NEXT: 2 1 [3.{{.*}}, 3.{{.*}}, 3.{{.*}}, 3.{{.*}}, 3.{{.*}}] {{.*}} {{.*}} +#CHECK-NEXT: 3 1 [1.{{.*}}, 1.{{.*}}, 1.{{.*}}, 1.{{.*}}, 1.{{.*}}] {{.*}} {{.*}} Index: test/tools/llvm-xray/X86/account-simple-case.yaml =================================================================== --- /dev/null +++ test/tools/llvm-xray/X86/account-simple-case.yaml @@ -0,0 +1,18 @@ +#RUN: llvm-xray account %s -i=yaml -o - -m %S/Inputs/simple-instrmap.yaml -t yaml | FileCheck %s +--- +header: + version: 1 + type: 0 + constant-tsc: true + nonstop-tsc: true + cycle-frequency: 2601000000 +records: + - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-enter, + tsc: 10001 } + - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-exit, + tsc: 10100 } +... + +#CHECK: Functions with latencies: 1 +#CHECK-NEXT: funcid count [min, median, 90%ile, 99%ile, max] debug function +#CHECK-NEXT: 1 1 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}} Index: tools/llvm-xray/CMakeLists.txt =================================================================== --- tools/llvm-xray/CMakeLists.txt +++ tools/llvm-xray/CMakeLists.txt @@ -7,6 +7,7 @@ set(LLVM_XRAY_TOOLS func-id-helper.cc + xray-account.cc xray-converter.cc xray-extract.cc xray-extract.cc Index: tools/llvm-xray/func-id-helper.cc =================================================================== --- tools/llvm-xray/func-id-helper.cc +++ tools/llvm-xray/func-id-helper.cc @@ -11,8 +11,8 @@ // //===----------------------------------------------------------------------===// -#include #include "func-id-helper.h" +#include using namespace llvm; using namespace xray; @@ -26,12 +26,14 @@ } auto ResOrErr = Symbolizer.symbolizeCode(BinaryInstrMap, It->second); - if (!ResOrErr || ResOrErr.get().FunctionName == "") { - F << "@(" << std::hex << It->second << ")"; - } else { + if (ResOrErr) { auto &DI = ResOrErr.get(); F << DI.FunctionName; + return F.str(); } + handleAllErrors(ResOrErr.takeError(), [&](const ErrorInfoBase &) { + F << "@(" << std::hex << It->second << ")"; + }); return F.str(); } Index: tools/llvm-xray/xray-account.h =================================================================== --- /dev/null +++ tools/llvm-xray/xray-account.h @@ -0,0 +1,104 @@ +//===- xray-account.h - XRay Function Call Accounting ---------------------===// +// +// The LLVM Compiler Infrastructure +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// +// +// This file defines the interface for performing some basic function call +// accounting from an XRay trace. +// +//===----------------------------------------------------------------------===// +#ifndef LLVM_TOOLS_LLVM_XRAY_XRAY_ACCOUNT_H +#define LLVM_TOOLS_LLVM_XRAY_XRAY_ACCOUNT_H + +#include +#include +#include + +#include "func-id-helper.h" +#include "xray-record.h" +#include "llvm/Support/raw_ostream.h" + +namespace llvm { +namespace xray { + +class LatencyAccountant { +public: + typedef std::map> FunctionLatencyMap; + typedef std::map> PerThreadMinMaxTSCMap; + typedef std::map> PerCPUMinMaxTSCMap; + typedef std::vector> FunctionStack; + typedef std::map PerThreadFunctionStackMap; + +private: + PerThreadFunctionStackMap PerThreadFunctionStack; + FunctionLatencyMap FunctionLatencies; + PerThreadMinMaxTSCMap PerThreadMinMaxTSC; + PerCPUMinMaxTSCMap PerCPUMinMaxTSC; + FuncIdConversionHelper &FuncIdHelper; + + bool DeduceSiblingCalls = false; + uint64_t CurrentMaxTSC = 0; + + void recordLatency(int32_t FuncId, uint64_t Latency) { + FunctionLatencies[FuncId].push_back(Latency); + } + +public: + explicit LatencyAccountant(FuncIdConversionHelper &FuncIdHelper, + bool DeduceSiblingCalls) + : FuncIdHelper(FuncIdHelper), DeduceSiblingCalls(DeduceSiblingCalls) {} + + const FunctionLatencyMap &getFunctionLatencies() const { + return FunctionLatencies; + } + + const PerThreadMinMaxTSCMap &getPerThreadMinMaxTSC() const { + return PerThreadMinMaxTSC; + } + + const PerCPUMinMaxTSCMap &getPerCPUMinMaxTSC() const { + return PerCPUMinMaxTSC; + } + + /// Returns false in case we fail to account the provided record. This happens + /// in the following cases: + /// + /// - An exit record does not match any entry records for the same function. + /// If we've been set to deduce sibling calls, we try walking up the stack + /// and recording times for the higher level functions. + /// - A record has a TSC that's before the latest TSC that has been + /// recorded. We still record the TSC for the min-max. + /// + bool accountRecord(const XRayRecord &Record); + + const FunctionStack *getThreadFunctionStack(pid_t TId) const { + auto I = PerThreadFunctionStack.find(TId); + if (I == PerThreadFunctionStack.end()) + return nullptr; + return &I->second; + } + + const PerThreadFunctionStackMap &getPerThreadFunctionStack() const { + return PerThreadFunctionStack; + } + + // Output Functions + // ================ + + void exportStatsAsTEXT(raw_ostream &OS, const XRayFileHeader &Header) const; + void exportStatsAsCSV(raw_ostream &OS, const XRayFileHeader &Header) const; + +private: + // Internal helper to implement common parts of the exportStatsAs... + // functions. + template void exportStats(const XRayFileHeader &Header, F fn) const; +}; + +} // namespace xray +} // namespace llvm + +#endif // LLVM_TOOLS_LLVM_XRAY_XRAY_ACCOUNT_H Index: tools/llvm-xray/xray-account.cc =================================================================== --- /dev/null +++ tools/llvm-xray/xray-account.cc @@ -0,0 +1,350 @@ +//===- xray-account.h - XRay Function Call 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 basic function call accounting from an XRay trace. +// +//===----------------------------------------------------------------------===// + +#include +#include + +#include "xray-account.h" +#include "xray-extract.h" +#include "xray-log-reader.h" +#include "xray-registry.h" +#include "llvm/Support/ErrorHandling.h" + +using namespace llvm; +using namespace llvm::xray; + +static cl::SubCommand Account("account", "Function call accounting"); +static cl::opt AccountInput(cl::Positional, + cl::desc(""), + cl::Required, cl::sub(Account)); +static cl::opt + AccountKeepGoing("keep_going", cl::desc("Keep going on errors encountered"), + cl::sub(Account), cl::init(false)); +static cl::alias AccountKeepGoing2("k", cl::aliasopt(AccountKeepGoing), + cl::desc("Alias for -keep_going"), + cl::sub(Account)); +static cl::opt AccountDeduceSiblingCalls( + "deduce-sibling-calls", + cl::desc("Deduce sibling calls when unrolling function call stacks"), + cl::sub(Account), cl::init(false)); +static cl::alias + AccountDeduceSiblingCalls2("d", cl::aliasopt(AccountDeduceSiblingCalls), + cl::desc("Alias for -deduce_sibling_calls"), + cl::sub(Account)); +static cl::opt + AccountOutput("output", cl::value_desc("output file"), cl::init("-"), + cl::desc("output file; use '-' for stdout"), + cl::sub(Account)); +static cl::alias AccountOutput2("o", cl::aliasopt(AccountOutput), + cl::desc("Alias for -output"), + cl::sub(Account)); +enum class AccountOutputFormats { TEXT, CSV }; +static cl::opt + AccountOutputFormat("format", cl::desc("output format"), + cl::values(clEnumValN(AccountOutputFormats::TEXT, + "text", "report stats in text"), + clEnumValN(AccountOutputFormats::CSV, "csv", + "report stats in csv")), + cl::sub(Account)); +static cl::alias AccountOutputFormat2("f", cl::desc("Alias of -format"), + cl::aliasopt(AccountOutputFormat), + cl::sub(Account)); +enum class AccountInputFormats { RAW, YAML }; +static cl::opt AccountInputFormat( + "input-format", cl::desc("input format"), + cl::values(clEnumValN(AccountInputFormats::RAW, "binary", + "input in binary"), + clEnumValN(AccountInputFormats::YAML, "yaml", "input in yaml")), + cl::sub(Account)); +static cl::alias AccountInputFormat2("i", cl::desc("Alias for -input-format"), + cl::aliasopt(AccountInputFormat), + cl::sub(Account)); + +static cl::opt + AccountInstrMap("instr_map", + cl::desc("binary with the instrumentation map, or " + "a separate instrumentation map"), + cl::value_desc("binary with xray_instr_map"), + cl::sub(Account), cl::init("")); +static cl::alias AccountInstrMap2("m", cl::aliasopt(AccountInstrMap), + cl::desc("Alias for -instr_map"), + cl::sub(Account)); +static cl::opt InstrMapFormat( + "instr-map-format", cl::desc("format of instrumentation map"), + cl::values(clEnumValN(InstrumentationMapExtractor::InputFormats::ELF, "elf", + "instrumentation map in an ELF header"), + clEnumValN(InstrumentationMapExtractor::InputFormats::YAML, + "yaml", "instrumentation map in YAML")), + cl::sub(Account), cl::init(InstrumentationMapExtractor::InputFormats::ELF)); +static cl::alias InstrMapFormat2("t", cl::aliasopt(InstrMapFormat), + cl::desc("Alias for -instr-map-format"), + cl::sub(Account)); + +namespace { + +template void setMinMax(std::pair &MM, U &&V) { + if (MM.first == 0 || MM.second == 0) + MM = std::make_pair(std::forward(V), std::forward(V)); + else + MM = std::make_pair(std::min(MM.first, V), std::max(MM.second, V)); +} + +template T diff(T L, T R) { return std::max(L, R) - std::min(L, R); } + +} // namespace + +bool LatencyAccountant::accountRecord(const XRayRecord &Record) { + setMinMax(PerThreadMinMaxTSC[Record.TId], Record.TSC); + setMinMax(PerCPUMinMaxTSC[Record.CPU], Record.TSC); + + if (CurrentMaxTSC == 0) + CurrentMaxTSC = Record.TSC; + + if (Record.TSC < CurrentMaxTSC) + return false; + + auto &ThreadStack = PerThreadFunctionStack[Record.TId]; + switch (Record.Type) { + case 0: { + // Function Enter + ThreadStack.push_back({Record.FuncId, Record.TSC}); + break; + } + case 1: { + // Function Exit + if (ThreadStack.back().first != Record.FuncId) { + if (!DeduceSiblingCalls) + return false; + auto Parent = + std::find_if(ThreadStack.rbegin(), ThreadStack.rend(), + [&](const std::pair &E) { + return E.first == Record.FuncId; + }); + if (Parent != ThreadStack.rend()) { + // We found a matching entry for this function. + auto I = ThreadStack.rbegin(); + while (I <= Parent) { + const auto &Top = *I; + recordLatency(Top.first, diff(Top.second, Record.TSC)); + ThreadStack.pop_back(); + I = ThreadStack.rbegin(); + } + return true; + } + + // We didn't find a matching entry for this exit + return false; + } + + // We did find that the top of the function call stack matches this exit. + assert(ThreadStack.back().first == Record.FuncId); + const auto &Top = ThreadStack.back(); + recordLatency(Top.first, diff(Top.second, Record.TSC)); + ThreadStack.pop_back(); + break; + } + default: + llvm_unreachable("Unsupported record type."); + return false; + } + + return true; +} + +namespace { + +// We consolidate the data into a struct which we can output in various forms. +struct ResultRow { + uint64_t Count; + double Min; + double Median; + double Pct90; + double Pct99; + double Max; + std::string DebugInfo; + std::string Function; +}; + +ResultRow getStats(std::vector &Timings) { + ResultRow R; + std::nth_element(Timings.begin(), Timings.end(), Timings.end()); + R.Min = Timings.front(); + auto MedianOff = Timings.size() / 2; + std::nth_element(Timings.begin(), Timings.begin() + MedianOff, Timings.end()); + R.Median = Timings[MedianOff]; + auto Pct90Off = std::floor(Timings.size() * 0.9); + std::nth_element(Timings.begin(), Timings.begin() + Pct90Off, Timings.end()); + R.Pct90 = Timings[Pct90Off]; + auto Pct99Off = std::floor(Timings.size() * 0.99); + std::nth_element(Timings.begin(), Timings.begin() + Pct90Off, Timings.end()); + R.Pct99 = Timings[Pct99Off]; + R.Max = *std::max_element(Timings.begin(), Timings.end()); + R.Count = Timings.size(); + return R; +} + +} // namespace + +template +void LatencyAccountant::exportStats(const XRayFileHeader &Header, F Fn) const { + for (auto FT : FunctionLatencies) { + const auto &FuncId = FT.first; + auto &Timings = FT.second; + ResultRow Row = getStats(Timings); + if (Header.CycleFrequency) { + double CycleFrequency = Header.CycleFrequency; + Row.Min /= CycleFrequency; + Row.Median /= CycleFrequency; + Row.Pct90 /= CycleFrequency; + Row.Pct99 /= CycleFrequency; + Row.Max /= CycleFrequency; + } + + Row.Function = FuncIdHelper.SymbolOrNumber(FuncId); + Row.DebugInfo = FuncIdHelper.FileLineAndColumn(FuncId); + Fn(FuncId, Timings.size(), Row); + } +} + +void LatencyAccountant::exportStatsAsTEXT(raw_ostream &OS, + const XRayFileHeader &Header) const { + OS << "Functions with latencies: " << FunctionLatencies.size() << "\n"; + OS << "funcid\t\tcount\t\t[min, median, 90%ile, 99%ile, " + "max]\tdebug\t\tfunction\n"; + exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) { + OS << FuncId << "\t\t" << Count << "\t\t[" << Row.Min << ", " << Row.Median + << ", " << Row.Pct90 << ", " << Row.Pct99 << ", " << Row.Max << "] " + << Row.DebugInfo << " " << Row.Function << "\n"; + }); +} + +void LatencyAccountant::exportStatsAsCSV(raw_ostream &OS, + const XRayFileHeader &Header) const { + OS << "funcid,count,min,median,90%ile,99%ile,max,debug,function\n"; + exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) { + OS << FuncId << ',' << Count << ',' << Row.Min << ',' << Row.Median << ',' + << Row.Pct90 << ',' << Row.Pct99 << ',' << Row.Max << ",\"" + << Row.DebugInfo << "\",\"" << Row.Function << "\"\n"; + }); +} + +namespace llvm { +namespace xray { + +static CommandRegistration Unused(&Account, [] { + int Fd; + auto EC = sys::fs::openFileForRead(AccountInput, Fd); + if (EC) { + errs() << "Cannot open file '" << AccountInput << "' for reading.\n"; + return 1; + } + raw_fd_ostream OS(AccountOutput, EC, sys::fs::OpenFlags::F_Text); + if (EC) { + errs() << "Cannot open file '" << AccountOutput << "' for writing.\n"; + return 1; + } + xray::InstrumentationMapExtractor Extractor(AccountInstrMap, InstrMapFormat, + EC); + if (EC) { + errs() << "Cannot load instrumentation map from '" << AccountInstrMap + << "'\n"; + if (!AccountKeepGoing) + return 1; + } + const auto &FunctionAddresses = Extractor.getFunctionAddresses(); + symbolize::LLVMSymbolizer::Options Opts( + symbolize::FunctionNameKind::LinkageName, true, true, false, ""); + symbolize::LLVMSymbolizer Symbolizer(Opts); + llvm::xray::FuncIdConversionHelper FuncIdHelper(AccountInstrMap, Symbolizer, + FunctionAddresses); + xray::LatencyAccountant FCA(FuncIdHelper, AccountDeduceSiblingCalls); + const llvm::xray::XRayFileHeader *Header = nullptr; + switch (AccountInputFormat) { + case AccountInputFormats::RAW: { + NaiveLogReader LogReader(Fd, EC); + if (EC) { + errs() << "Errors reading file '" << AccountInput << "'.\n"; + return 1; + } + if (LogReader.getFileHeader().Version != 1) { + errs() << "Unsupported XRay file version: " + << LogReader.getFileHeader().Version << '\n'; + return 1; + } + Header = &LogReader.getFileHeader(); + for (const auto &Record : LogReader) { + if (!FCA.accountRecord(Record)) { + for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) { + errs() << "Thread ID: " << ThreadStack.first << "\n"; + auto Level = ThreadStack.second.size(); + for (const auto &Entry : llvm::reverse(ThreadStack.second)) { + errs() << "#" << Level-- << "\t" + << FuncIdHelper.SymbolOrNumber(Entry.first) << '\n'; + } + } + if (!AccountKeepGoing) { + errs() << "Failed accounting function calls in file '" << AccountInput + << "'.\n"; + return 1; + } + } + } + break; + } + case AccountInputFormats::YAML: { + xray::YAMLLogReader LogReader(Fd, EC); + if (EC) { + errs() << "Errors reading file '" << AccountInput << "'.\n"; + return 1; + } + if (LogReader.getFileHeader().Version != 1) { + errs() << "Unsupported XRay file version: " + << LogReader.getFileHeader().Version << '\n'; + return 1; + } + Header = &LogReader.getFileHeader(); + llvm::xray::XRayRecordStorage Buf; + for (const auto &Y : LogReader) { + auto &Record = toXRayRecord(Y, Buf); + if (!FCA.accountRecord(Record)) { + for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) { + errs() << "Thread ID: " << ThreadStack.first << "\n"; + auto Level = ThreadStack.second.size(); + for (const auto &Entry : llvm::reverse(ThreadStack.second)) { + errs() << "#" << Level-- << "\t" + << FuncIdHelper.SymbolOrNumber(Entry.first) << '\n'; + } + } + if (!AccountKeepGoing) { + errs() << "Failed accounting function calls in file '" << AccountInput + << "'.\n"; + return 1; + } + } + } + break; + } + } + switch (AccountOutputFormat) { + case AccountOutputFormats::TEXT: + FCA.exportStatsAsTEXT(OS, *Header); + break; + case AccountOutputFormats::CSV: + FCA.exportStatsAsCSV(OS, *Header); + break; + } + return 0; +}); + +} // namespace xray +} // namespace llvm