Index: tools/CMakeLists.txt =================================================================== --- tools/CMakeLists.txt +++ tools/CMakeLists.txt @@ -39,6 +39,7 @@ add_llvm_tool_subdirectory(llvm-config) add_llvm_tool_subdirectory(llvm-lto) add_llvm_tool_subdirectory(llvm-profdata) +add_llvm_tool_subdirectory(xray) # Projects supported via LLVM_EXTERNAL_*_SOURCE_DIR need to be explicitly # specified. Index: tools/xray/CMakeLists.txt =================================================================== --- /dev/null +++ tools/xray/CMakeLists.txt @@ -0,0 +1,9 @@ +set(LLVM_LINK_COMPONENTS + ${LLVM_TARGETS_TO_BUILD} + Support + DebugInfoDWARF + Symbolize + Object) + +add_llvm_tool(xray-fc-account + xray-fc-account.cc) Index: tools/xray/xray-fc-account.cc =================================================================== --- /dev/null +++ tools/xray/xray-fc-account.cc @@ -0,0 +1,358 @@ +//===- xray-fc-account.cc - XRay Function Call Accounting Tool ------------===// +// +// The LLVM Compiler Infrastructure +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// +// +// This file implements the Function Call Accounting tool that takes an XRay +// trace and generates function call accounting statistics for that given trace. +// +//===----------------------------------------------------------------------===// + +#include +#include +#include +#include +#include +#include +#include +#include + +#include "llvm/DebugInfo/Symbolize/Symbolize.h" +#include "llvm/Object/ELF.h" +#include "llvm/Object/ObjectFile.h" +#include "llvm/Support/CommandLine.h" +#include "llvm/Support/ELF.h" +#include "llvm/Support/raw_ostream.h" + +using namespace llvm; + +static StringRef ToolName; + +static cl::opt Input(cl::Positional, cl::desc(""), + cl::Required); + +static cl::opt BinaryInstrMap( + "instr_map", + cl::desc("file containing an xray instrumentation map section"), + cl::value_desc("filename"), cl::Optional); +static cl::alias BinaryInstrMap2("m", cl::desc("Alias for -instr_map"), + cl::aliasopt(BinaryInstrMap)); +static cl::opt Verbose( + "verbose", + cl::desc( + "play-by-play logging of encountered records, useful for debugging"), + cl::init(false)); +static cl::alias Verbose2("v", cl::desc("Alias for -verbose"), + cl::aliasopt(Verbose)); + +LLVM_ATTRIBUTE_NORETURN static void fail(Twine Error) { + outs() << ToolName << ": " << Error << ".\n"; + exit(1); +} + +class FileCloser { + int Fd; + +public: + explicit FileCloser(int Fd) : Fd(Fd) {} + + ~FileCloser() noexcept { + if (Fd != -1) + close(Fd); + } +}; + +namespace __xray { + +// FIXME: Make this available in a common header between compiler-rt and this +// tool. +struct alignas(32) XRayRecord { + // Get the full 8 bytes of the TSC when we get the log record. + uint64_t TSC = 0; + + // The thread ID for the currently running thread. + pid_t TId = 0; + + // The CPU where the thread is running. We assume number of CPUs <= 256. + uint8_t CPU = 0; + + // The type of the event. Usually either ENTER = 0 or EXIT = 1. + uint8_t Type = 0; + + // The function ID for the record. + int32_t FuncId = 0; +}; + +// FIXME: Make this available in a common header between compiler-rt and this +// tool. +struct XRaySledEntry { + uint64_t Address; + uint64_t Function; + unsigned char Kind; + unsigned char AlwaysInstrument; + unsigned char Padding[14]; +}; +} + +std::unordered_map LoadBinaryInstr() { + std::unordered_map InstrMap; + if (BinaryInstrMap.empty()) { + errs() << ToolName << ": instrumentation map not provided, using raw " + "function IDs in output.\n"; + return InstrMap; + } + + auto ObjectFile = object::ObjectFile::createObjectFile(BinaryInstrMap); + + // FIXME: Maybe support other ELF formats. For now, 64-bit Little Endian only. + if (!ObjectFile || !ObjectFile->getBinary()->isELF()) + fail("File format not supported (only does ELF)."); + + // Find the section named "xray_instr_map". + StringRef Contents = ""; + for (const auto &Section : ObjectFile->getBinary()->sections()) { + StringRef Name = ""; + if (Section.getName(Name)) + continue; + + if (Name != "xray_instr_map") + continue; + + // Iterate through the elements of the section, coercing it into + // __xray::XraySledEntry objects. + if (Section.getContents(Contents)) + fail("Failed to get contents of 'xray_instr_map' section."); + + break; + } + + if (Contents.empty()) + fail("Failed to find XRay instrumentation map."); + + // Treat Contents as though it were an array of __xray::XRaySledEntry + // elements. + const __xray::XRaySledEntry *Sleds = + reinterpret_cast(Contents.data()); + size_t Entries = Contents.size() / sizeof(__xray::XRaySledEntry); + + // We replicate the function id generation scheme implemented in the runtime + // here. Ideally we should be able to break it out, or output this map from + // the runtime, but that's a design point we can discuss later on. For now, we + // replicate the logic and move on. + int32_t FuncId = 1; + uint64_t CurFn = 0; + for (size_t I = 0; I < Entries; ++I) { + const auto &Sled = Sleds[I]; + auto F = Sled.Function; + if (CurFn == 0) { + CurFn = F; + InstrMap[FuncId] = F; + } + if (F != CurFn) { + ++FuncId; + CurFn = F; + InstrMap[FuncId] = F; + } + } + return InstrMap; +} + +using FunctionAddressMap = std::unordered_map; + +std::string SymbolOrNumber(symbolize::LLVMSymbolizer &Symbolizer, + const FunctionAddressMap &FunctionAddresses, + int32_t FuncId) { + std::ostringstream F; + auto It = FunctionAddresses.find(FuncId); + if (It == FunctionAddresses.end()) { + F << "#" << FuncId; + return F.str(); + } + + auto ResOrErr = Symbolizer.symbolizeCode(BinaryInstrMap, It->second); + if (!ResOrErr || ResOrErr.get().FunctionName == "") { + F << "@(" << std::hex << It->second << ")"; + } else { + auto &DI = ResOrErr.get(); + F << DI.FunctionName; + } + return F.str(); +} + +std::string FileLineAndColumn(symbolize::LLVMSymbolizer &Symbolizer, + const FunctionAddressMap &FunctionAddresses, + int32_t FuncId) { + auto It = FunctionAddresses.find(FuncId); + if (It == FunctionAddresses.end()) { + return "(unknown)"; + } + std::ostringstream F; + auto ResOrErr = Symbolizer.symbolizeCode(BinaryInstrMap, It->second); + if (!ResOrErr || ResOrErr.get().FileName == "") + return "(unknown)"; + auto &DI = ResOrErr.get(); + F << DI.FileName << ":" << DI.Line << "," << DI.Column; + return F.str(); +} + +int main(int argc, char *argv[]) { + ToolName = argv[0]; + cl::ParseCommandLineOptions( + argc, argv, "XRay Function Call Accounting (xray-fc-account)\n\n" + " This program takes an XRay trace file and does some basic " + "function call accounting statistics.\n"); + + if (Input.empty()) + fail("No input file provided."); + + std::unordered_map FunctionAddresses = LoadBinaryInstr(); + outs() << "Loaded " << FunctionAddresses.size() + << " entries for the instrumentation map.\n"; + + int Fd = open(Input.c_str(), O_RDONLY); + while (Fd == -1 && errno == EINTR) { + Fd = open(Input.c_str(), O_RDONLY); + } + if (Fd == -1) + fail(Twine("Failed to open file '") + Input + "'; errno=" + Twine(errno)); + FileCloser FC(Fd); + + symbolize::LLVMSymbolizer::Options Opts( + symbolize::FunctionNameKind::LinkageName, true, true, false, ""); + symbolize::LLVMSymbolizer Symbolizer(Opts); + + __xray::XRayRecord Record; + std::map>> FunctionStack; + std::map> FunctionTimings; + uint64_t CurTSC = 0; + while (auto ReadBytes = read(Fd, &Record, sizeof(__xray::XRayRecord))) { + if (ReadBytes == -1) { + if (errno == EINTR) + continue; + fail(Twine("Failed to read file '") + Input + "'; errno=" + Twine(errno)); + } + + if (CurTSC == 0) + CurTSC = Record.TSC; + + if (Verbose) { + auto FuncAddr = FunctionAddresses.find(Record.FuncId); + outs() << "Record: [tid=" << Record.TId << ",cpu=" << int32_t{Record.CPU} + << "] " << Record.TSC << ": " << (Record.Type == 0 ? "E" : "X") + << Record.FuncId << "@("; + if (FuncAddr == FunctionAddresses.end()) { + outs() << "unknown"; + } else { + outs().write_hex(FuncAddr->second); + } + outs() << ") " + << SymbolOrNumber(Symbolizer, FunctionAddresses, Record.FuncId) + << "\n"; + } + + if (Record.Type == 0) + FunctionStack[Record.TId].push_back({Record.FuncId, Record.TSC}); + + if (Record.Type == 1) { + if (Record.TSC < CurTSC) + fail("Encountered TSC before previous TSC; bailing out"); + if (FunctionStack[Record.TId].back().first != Record.FuncId) { + // This could be a tail call, so look up the stack to see whether we've + // found an entry that shouldn't be there. + auto &ThreadFuncStack = FunctionStack[Record.TId]; + auto Parent = + std::find_if(ThreadFuncStack.rbegin(), ThreadFuncStack.rend(), + [&Record](const std::pair &Entry) { + return Entry.first == Record.FuncId; + }); + if (Parent != ThreadFuncStack.rend()) { + for (auto It = ThreadFuncStack.rbegin(); It != Parent; ++It) { + const auto &Top = *It; + int64_t Timing = std::max(Top.second, Record.TSC) - + std::min(Top.second, Record.TSC); + auto &Timings = FunctionTimings[Top.first]; + Timings.push_back(Timing); + } + auto Skipped = std::distance(ThreadFuncStack.rbegin(), Parent); + while (Skipped) { + ThreadFuncStack.pop_back(); + --Skipped; + } + } else { + errs() << ToolName << ": Encountered X" << Record.FuncId << "(" + << SymbolOrNumber(Symbolizer, FunctionAddresses, Record.FuncId) + << ") not matching E" << FunctionStack[Record.TId].back().first + << "(" + << SymbolOrNumber(Symbolizer, FunctionAddresses, + FunctionStack[Record.TId].back().first) + << ")\n"; + errs() << "Current stack dump:\n"; + for (auto &ThreadStack : FunctionStack) { + errs() << "Thread ID: " << ThreadStack.first << "\n"; + auto Level = ThreadStack.second.size(); + while (!ThreadStack.second.empty()) { + errs() << "#" << Level-- << "\t" + << SymbolOrNumber(Symbolizer, FunctionAddresses, + ThreadStack.second.back().first) + << '\n'; + ThreadStack.second.pop_back(); + } + } + fail("Corrupted input file found."); + } + } else { + const auto &Top = FunctionStack[Record.TId].back(); + int64_t Timing = + std::max(Top.second, Record.TSC) - std::min(Top.second, Record.TSC); + auto &Timings = FunctionTimings[Record.FuncId]; + Timings.push_back(Timing); + FunctionStack[Record.TId].pop_back(); + } + } + CurTSC = Record.TSC; + } + + // We then want to generate the output such that we show: + // Function ID count min, median,90pct, 99pct, max + outs() << "count\t[min,median,90%ile,99%ile,max]\tdebug\tfunction\n"; + + for (auto &FT : FunctionTimings) { + const auto &FuncId = FT.first; + auto &Timings = FT.second; + outs() << Timings.size() << "\t"; + std::nth_element(Timings.begin(), Timings.begin(), Timings.end()); + auto Min = Timings.front(); + auto MedianOff = std::distance(Timings.begin(), Timings.end()) / 2; + std::nth_element(Timings.begin(), Timings.begin() + (MedianOff), + Timings.end()); + auto Median = Timings[MedianOff]; + auto Pct90Off = + std::floor(std::distance(Timings.begin(), Timings.end()) * 0.9); + std::nth_element(Timings.begin(), Timings.begin() + Pct90Off, + Timings.end()); + auto Pct90 = Timings[Pct90Off]; + auto Pct99Off = + std::floor(std::distance(Timings.begin(), Timings.end()) * 0.99); + std::nth_element(Timings.begin(), Timings.begin() + Pct99Off, + Timings.end()); + auto Pct99 = Timings[Pct99Off]; + std::nth_element(Timings.begin(), + Timings.begin() + + std::distance(Timings.begin(), Timings.end()), + Timings.end()); + auto Max = Timings.back(); + outs() << "[" << Min << ", " << Median << ", " << Pct90 << ", " << Pct99 + << ", " << Max << "] " + << FileLineAndColumn(Symbolizer, FunctionAddresses, FuncId) << "\t"; + if (FunctionAddresses.count(FuncId)) { + outs() << SymbolOrNumber(Symbolizer, FunctionAddresses, FuncId) << "\t"; + } else { + outs() << "#" << FuncId << "\t"; + } + outs() << "\n"; + } +}