539 lines · cpp
1//===-- xray-graph.cpp: XRay Function Call Graph Renderer -----------------===//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-exception6//7//===----------------------------------------------------------------------===//8//9// Generate a DOT file to represent the function call graph encountered in10// the trace.11//12//===----------------------------------------------------------------------===//13 14#include "xray-graph.h"15#include "xray-registry.h"16#include "llvm/Support/ErrorHandling.h"17#include "llvm/XRay/InstrumentationMap.h"18#include "llvm/XRay/Trace.h"19 20#include <cmath>21 22using namespace llvm;23using namespace llvm::xray;24 25// Setup llvm-xray graph subcommand and its options.26static cl::SubCommand GraphC("graph", "Generate function-call graph");27static cl::opt<std::string> GraphInput(cl::Positional,28 cl::desc("<xray log file>"),29 cl::Required, cl::sub(GraphC));30 31static cl::opt<bool>32 GraphKeepGoing("keep-going", cl::desc("Keep going on errors encountered"),33 cl::sub(GraphC), cl::init(false));34static cl::alias GraphKeepGoing2("k", cl::aliasopt(GraphKeepGoing),35 cl::desc("Alias for -keep-going"));36 37static cl::opt<std::string>38 GraphOutput("output", cl::value_desc("Output file"), cl::init("-"),39 cl::desc("output file; use '-' for stdout"), cl::sub(GraphC));40static cl::alias GraphOutput2("o", cl::aliasopt(GraphOutput),41 cl::desc("Alias for -output"));42 43static cl::opt<std::string>44 GraphInstrMap("instr_map",45 cl::desc("binary with the instrumrntation map, or "46 "a separate instrumentation map"),47 cl::value_desc("binary with xray_instr_map"), cl::sub(GraphC),48 cl::init(""));49static cl::alias GraphInstrMap2("m", cl::aliasopt(GraphInstrMap),50 cl::desc("alias for -instr_map"));51 52static cl::opt<bool> GraphDeduceSiblingCalls(53 "deduce-sibling-calls",54 cl::desc("Deduce sibling calls when unrolling function call stacks"),55 cl::sub(GraphC), cl::init(false));56static cl::alias57 GraphDeduceSiblingCalls2("d", cl::aliasopt(GraphDeduceSiblingCalls),58 cl::desc("Alias for -deduce-sibling-calls"));59 60static cl::opt<GraphRenderer::StatType>61 GraphEdgeLabel("edge-label",62 cl::desc("Output graphs with edges labeled with this field"),63 cl::value_desc("field"), cl::sub(GraphC),64 cl::init(GraphRenderer::StatType::NONE),65 cl::values(clEnumValN(GraphRenderer::StatType::NONE, "none",66 "Do not label Edges"),67 clEnumValN(GraphRenderer::StatType::COUNT,68 "count", "function call counts"),69 clEnumValN(GraphRenderer::StatType::MIN, "min",70 "minimum function durations"),71 clEnumValN(GraphRenderer::StatType::MED, "med",72 "median function durations"),73 clEnumValN(GraphRenderer::StatType::PCT90, "90p",74 "90th percentile durations"),75 clEnumValN(GraphRenderer::StatType::PCT99, "99p",76 "99th percentile durations"),77 clEnumValN(GraphRenderer::StatType::MAX, "max",78 "maximum function durations"),79 clEnumValN(GraphRenderer::StatType::SUM, "sum",80 "sum of call durations")));81static cl::alias GraphEdgeLabel2("e", cl::aliasopt(GraphEdgeLabel),82 cl::desc("Alias for -edge-label"));83 84static cl::opt<GraphRenderer::StatType> GraphVertexLabel(85 "vertex-label",86 cl::desc("Output graphs with vertices labeled with this field"),87 cl::value_desc("field"), cl::sub(GraphC),88 cl::init(GraphRenderer::StatType::NONE),89 cl::values(clEnumValN(GraphRenderer::StatType::NONE, "none",90 "Do not label Vertices"),91 clEnumValN(GraphRenderer::StatType::COUNT, "count",92 "function call counts"),93 clEnumValN(GraphRenderer::StatType::MIN, "min",94 "minimum function durations"),95 clEnumValN(GraphRenderer::StatType::MED, "med",96 "median function durations"),97 clEnumValN(GraphRenderer::StatType::PCT90, "90p",98 "90th percentile durations"),99 clEnumValN(GraphRenderer::StatType::PCT99, "99p",100 "99th percentile durations"),101 clEnumValN(GraphRenderer::StatType::MAX, "max",102 "maximum function durations"),103 clEnumValN(GraphRenderer::StatType::SUM, "sum",104 "sum of call durations")));105static cl::alias GraphVertexLabel2("v", cl::aliasopt(GraphVertexLabel),106 cl::desc("Alias for -edge-label"));107 108static cl::opt<GraphRenderer::StatType> GraphEdgeColorType(109 "color-edges",110 cl::desc("Output graphs with edge colors determined by this field"),111 cl::value_desc("field"), cl::sub(GraphC),112 cl::init(GraphRenderer::StatType::NONE),113 cl::values(clEnumValN(GraphRenderer::StatType::NONE, "none",114 "Do not color Edges"),115 clEnumValN(GraphRenderer::StatType::COUNT, "count",116 "function call counts"),117 clEnumValN(GraphRenderer::StatType::MIN, "min",118 "minimum function durations"),119 clEnumValN(GraphRenderer::StatType::MED, "med",120 "median function durations"),121 clEnumValN(GraphRenderer::StatType::PCT90, "90p",122 "90th percentile durations"),123 clEnumValN(GraphRenderer::StatType::PCT99, "99p",124 "99th percentile durations"),125 clEnumValN(GraphRenderer::StatType::MAX, "max",126 "maximum function durations"),127 clEnumValN(GraphRenderer::StatType::SUM, "sum",128 "sum of call durations")));129static cl::alias GraphEdgeColorType2("c", cl::aliasopt(GraphEdgeColorType),130 cl::desc("Alias for -color-edges"));131 132static cl::opt<GraphRenderer::StatType> GraphVertexColorType(133 "color-vertices",134 cl::desc("Output graphs with vertex colors determined by this field"),135 cl::value_desc("field"), cl::sub(GraphC),136 cl::init(GraphRenderer::StatType::NONE),137 cl::values(clEnumValN(GraphRenderer::StatType::NONE, "none",138 "Do not color vertices"),139 clEnumValN(GraphRenderer::StatType::COUNT, "count",140 "function call counts"),141 clEnumValN(GraphRenderer::StatType::MIN, "min",142 "minimum function durations"),143 clEnumValN(GraphRenderer::StatType::MED, "med",144 "median function durations"),145 clEnumValN(GraphRenderer::StatType::PCT90, "90p",146 "90th percentile durations"),147 clEnumValN(GraphRenderer::StatType::PCT99, "99p",148 "99th percentile durations"),149 clEnumValN(GraphRenderer::StatType::MAX, "max",150 "maximum function durations"),151 clEnumValN(GraphRenderer::StatType::SUM, "sum",152 "sum of call durations")));153static cl::alias GraphVertexColorType2("b", cl::aliasopt(GraphVertexColorType),154 cl::desc("Alias for -edge-label"));155 156template <class T> static T diff(T L, T R) {157 return std::max(L, R) - std::min(L, R);158}159 160// Updates the statistics for a GraphRenderer::TimeStat161static void updateStat(GraphRenderer::TimeStat &S, int64_t L) {162 S.Count++;163 if (S.Min > L || S.Min == 0)164 S.Min = L;165 if (S.Max < L)166 S.Max = L;167 S.Sum += L;168}169 170// Labels in a DOT graph must be legal XML strings so it's necessary to escape171// certain characters.172static std::string escapeString(StringRef Label) {173 std::string Str;174 Str.reserve(Label.size());175 for (const auto C : Label) {176 switch (C) {177 case '&':178 Str.append("&");179 break;180 case '<':181 Str.append("<");182 break;183 case '>':184 Str.append(">");185 break;186 default:187 Str.push_back(C);188 break;189 }190 }191 return Str;192}193 194// Evaluates an XRay record and performs accounting on it.195//196// If the record is an ENTER record it pushes the FuncID and TSC onto a197// structure representing the call stack for that function.198// If the record is an EXIT record it checks computes computes the ammount of199// time the function took to complete and then stores that information in an200// edge of the graph. If there is no matching ENTER record the function tries201// to recover by assuming that there were EXIT records which were missed, for202// example caused by tail call elimination and if the option is enabled then203// then tries to recover from this.204//205// This function will also error if the records are out of order, as the trace206// is expected to be sorted.207//208// The graph generated has an immaginary root for functions called by no-one at209// FuncId 0.210//211// FIXME: Refactor this and account subcommand to reduce code duplication.212Error GraphRenderer::accountRecord(const XRayRecord &Record) {213 using std::make_error_code;214 using std::errc;215 if (CurrentMaxTSC == 0)216 CurrentMaxTSC = Record.TSC;217 218 if (Record.TSC < CurrentMaxTSC)219 return make_error<StringError>("Records not in order",220 make_error_code(errc::invalid_argument));221 222 auto &ThreadStack = PerThreadFunctionStack[Record.TId];223 switch (Record.Type) {224 case RecordTypes::ENTER:225 case RecordTypes::ENTER_ARG: {226 if (Record.FuncId != 0 && G.count(Record.FuncId) == 0)227 G[Record.FuncId].SymbolName = FuncIdHelper.SymbolOrNumber(Record.FuncId);228 ThreadStack.push_back({Record.FuncId, Record.TSC});229 break;230 }231 case RecordTypes::EXIT:232 case RecordTypes::TAIL_EXIT: {233 // FIXME: Refactor this and the account subcommand to reduce code234 // duplication235 if (ThreadStack.size() == 0 || ThreadStack.back().FuncId != Record.FuncId) {236 if (!DeduceSiblingCalls)237 return make_error<StringError>("No matching ENTRY record",238 make_error_code(errc::invalid_argument));239 bool FoundParent =240 llvm::any_of(llvm::reverse(ThreadStack), [&](const FunctionAttr &A) {241 return A.FuncId == Record.FuncId;242 });243 if (!FoundParent)244 return make_error<StringError>(245 "No matching Entry record in stack",246 make_error_code(errc::invalid_argument)); // There is no matching247 // Function for this exit.248 while (ThreadStack.back().FuncId != Record.FuncId) {249 TimestampT D = diff(ThreadStack.back().TSC, Record.TSC);250 VertexIdentifier TopFuncId = ThreadStack.back().FuncId;251 ThreadStack.pop_back();252 assert(ThreadStack.size() != 0);253 EdgeIdentifier EI(ThreadStack.back().FuncId, TopFuncId);254 auto &EA = G[EI];255 EA.Timings.push_back(D);256 updateStat(EA.S, D);257 updateStat(G[TopFuncId].S, D);258 }259 }260 uint64_t D = diff(ThreadStack.back().TSC, Record.TSC);261 ThreadStack.pop_back();262 VertexIdentifier VI = ThreadStack.empty() ? 0 : ThreadStack.back().FuncId;263 EdgeIdentifier EI(VI, Record.FuncId);264 auto &EA = G[EI];265 EA.Timings.push_back(D);266 updateStat(EA.S, D);267 updateStat(G[Record.FuncId].S, D);268 break;269 }270 case RecordTypes::CUSTOM_EVENT:271 case RecordTypes::TYPED_EVENT:272 // TODO: Support custom and typed events in the graph processing?273 break;274 }275 276 return Error::success();277}278 279template <typename U>280void GraphRenderer::getStats(U begin, U end, GraphRenderer::TimeStat &S) {281 if (begin == end) return;282 std::ptrdiff_t MedianOff = S.Count / 2;283 std::nth_element(begin, begin + MedianOff, end);284 S.Median = *(begin + MedianOff);285 std::ptrdiff_t Pct90Off = (S.Count * 9) / 10;286 std::nth_element(begin, begin + Pct90Off, end);287 S.Pct90 = *(begin + Pct90Off);288 std::ptrdiff_t Pct99Off = (S.Count * 99) / 100;289 std::nth_element(begin, begin + Pct99Off, end);290 S.Pct99 = *(begin + Pct99Off);291}292 293void GraphRenderer::updateMaxStats(const GraphRenderer::TimeStat &S,294 GraphRenderer::TimeStat &M) {295 M.Count = std::max(M.Count, S.Count);296 M.Min = std::max(M.Min, S.Min);297 M.Median = std::max(M.Median, S.Median);298 M.Pct90 = std::max(M.Pct90, S.Pct90);299 M.Pct99 = std::max(M.Pct99, S.Pct99);300 M.Max = std::max(M.Max, S.Max);301 M.Sum = std::max(M.Sum, S.Sum);302}303 304void GraphRenderer::calculateEdgeStatistics() {305 assert(!G.edges().empty());306 for (auto &E : G.edges()) {307 auto &A = E.second;308 assert(!A.Timings.empty());309 getStats(A.Timings.begin(), A.Timings.end(), A.S);310 updateMaxStats(A.S, G.GraphEdgeMax);311 }312}313 314void GraphRenderer::calculateVertexStatistics() {315 std::vector<uint64_t> TempTimings;316 for (auto &V : G.vertices()) {317 if (V.first != 0) {318 for (auto &E : G.inEdges(V.first)) {319 auto &A = E.second;320 llvm::append_range(TempTimings, A.Timings);321 }322 getStats(TempTimings.begin(), TempTimings.end(), G[V.first].S);323 updateMaxStats(G[V.first].S, G.GraphVertexMax);324 TempTimings.clear();325 }326 }327}328 329// A Helper function for normalizeStatistics which normalises a single330// TimeStat element.331static void normalizeTimeStat(GraphRenderer::TimeStat &S,332 double CycleFrequency) {333 int64_t OldCount = S.Count;334 S = S / CycleFrequency;335 S.Count = OldCount;336}337 338// Normalises the statistics in the graph for a given TSC frequency.339void GraphRenderer::normalizeStatistics(double CycleFrequency) {340 for (auto &E : G.edges()) {341 auto &S = E.second.S;342 normalizeTimeStat(S, CycleFrequency);343 }344 for (auto &V : G.vertices()) {345 auto &S = V.second.S;346 normalizeTimeStat(S, CycleFrequency);347 }348 349 normalizeTimeStat(G.GraphEdgeMax, CycleFrequency);350 normalizeTimeStat(G.GraphVertexMax, CycleFrequency);351}352 353// Returns a string containing the value of statistic field T354std::string355GraphRenderer::TimeStat::getString(GraphRenderer::StatType T) const {356 std::string St;357 raw_string_ostream S{St};358 double TimeStat::*DoubleStatPtrs[] = {&TimeStat::Min, &TimeStat::Median,359 &TimeStat::Pct90, &TimeStat::Pct99,360 &TimeStat::Max, &TimeStat::Sum};361 switch (T) {362 case GraphRenderer::StatType::NONE:363 break;364 case GraphRenderer::StatType::COUNT:365 S << Count;366 break;367 default:368 S << (*this).*369 DoubleStatPtrs[static_cast<int>(T) -370 static_cast<int>(GraphRenderer::StatType::MIN)];371 break;372 }373 return St;374}375 376// Returns the quotient between the property T of this and another TimeStat as377// a double378double GraphRenderer::TimeStat::getDouble(StatType T) const {379 double retval = 0;380 double TimeStat::*DoubleStatPtrs[] = {&TimeStat::Min, &TimeStat::Median,381 &TimeStat::Pct90, &TimeStat::Pct99,382 &TimeStat::Max, &TimeStat::Sum};383 switch (T) {384 case GraphRenderer::StatType::NONE:385 retval = 0.0;386 break;387 case GraphRenderer::StatType::COUNT:388 retval = static_cast<double>(Count);389 break;390 default:391 retval =392 (*this).*DoubleStatPtrs[static_cast<int>(T) -393 static_cast<int>(GraphRenderer::StatType::MIN)];394 break;395 }396 return retval;397}398 399// Outputs a DOT format version of the Graph embedded in the GraphRenderer400// object on OS. It does this in the expected way by itterating401// through all edges then vertices and then outputting them and their402// annotations.403//404// FIXME: output more information, better presented.405void GraphRenderer::exportGraphAsDOT(raw_ostream &OS, StatType ET, StatType EC,406 StatType VT, StatType VC) {407 OS << "digraph xray {\n";408 409 if (VT != StatType::NONE)410 OS << "node [shape=record];\n";411 412 for (const auto &E : G.edges()) {413 const auto &S = E.second.S;414 OS << "F" << E.first.first << " -> "415 << "F" << E.first.second << " [label=\"" << S.getString(ET) << "\"";416 if (EC != StatType::NONE)417 OS << " color=\""418 << CHelper.getColorString(419 std::sqrt(S.getDouble(EC) / G.GraphEdgeMax.getDouble(EC)))420 << "\"";421 OS << "];\n";422 }423 424 for (const auto &V : G.vertices()) {425 const auto &VA = V.second;426 if (V.first == 0)427 continue;428 OS << "F" << V.first << " [label=\"" << (VT != StatType::NONE ? "{" : "")429 << escapeString(VA.SymbolName.size() > 40430 ? VA.SymbolName.substr(0, 40) + "..."431 : VA.SymbolName);432 if (VT != StatType::NONE)433 OS << "|" << VA.S.getString(VT) << "}\"";434 else435 OS << "\"";436 if (VC != StatType::NONE)437 OS << " color=\""438 << CHelper.getColorString(439 std::sqrt(VA.S.getDouble(VC) / G.GraphVertexMax.getDouble(VC)))440 << "\"";441 OS << "];\n";442 }443 OS << "}\n";444}445 446Expected<GraphRenderer> GraphRenderer::Factory::getGraphRenderer() {447 InstrumentationMap Map;448 if (!GraphInstrMap.empty()) {449 auto InstrumentationMapOrError = loadInstrumentationMap(GraphInstrMap);450 if (!InstrumentationMapOrError)451 return joinErrors(452 make_error<StringError>(453 Twine("Cannot open instrumentation map '") + GraphInstrMap + "'",454 std::make_error_code(std::errc::invalid_argument)),455 InstrumentationMapOrError.takeError());456 Map = std::move(*InstrumentationMapOrError);457 }458 459 const auto &FunctionAddresses = Map.getFunctionAddresses();460 461 symbolize::LLVMSymbolizer Symbolizer;462 const auto &Header = Trace.getFileHeader();463 464 FuncIdConversionHelper FuncIdHelper(InstrMap, Symbolizer, FunctionAddresses);465 466 GraphRenderer GR(FuncIdHelper, DeduceSiblingCalls);467 for (const auto &Record : Trace) {468 auto E = GR.accountRecord(Record);469 if (!E)470 continue;471 472 for (const auto &ThreadStack : GR.getPerThreadFunctionStack()) {473 errs() << "Thread ID: " << ThreadStack.first << "\n";474 auto Level = ThreadStack.second.size();475 for (const auto &Entry : llvm::reverse(ThreadStack.second))476 errs() << "#" << Level-- << "\t"477 << FuncIdHelper.SymbolOrNumber(Entry.FuncId) << '\n';478 }479 480 if (!GraphKeepGoing)481 return joinErrors(make_error<StringError>(482 "Error encountered generating the call graph.",483 std::make_error_code(std::errc::invalid_argument)),484 std::move(E));485 486 handleAllErrors(std::move(E),487 [&](const ErrorInfoBase &E) { E.log(errs()); });488 }489 490 GR.G.GraphEdgeMax = {};491 GR.G.GraphVertexMax = {};492 GR.calculateEdgeStatistics();493 GR.calculateVertexStatistics();494 495 if (Header.CycleFrequency)496 GR.normalizeStatistics(Header.CycleFrequency);497 498 return GR;499}500 501// Here we register and implement the llvm-xray graph subcommand.502// The bulk of this code reads in the options, opens the required files, uses503// those files to create a context for analysing the xray trace, then there is a504// short loop which actually analyses the trace, generates the graph and then505// outputs it as a DOT.506//507// FIXME: include additional filtering and annalysis passes to provide more508// specific useful information.509static CommandRegistration Unused(&GraphC, []() -> Error {510 GraphRenderer::Factory F;511 512 F.KeepGoing = GraphKeepGoing;513 F.DeduceSiblingCalls = GraphDeduceSiblingCalls;514 F.InstrMap = GraphInstrMap;515 516 auto TraceOrErr = loadTraceFile(GraphInput, true);517 518 if (!TraceOrErr)519 return make_error<StringError>(520 Twine("Failed loading input file '") + GraphInput + "'",521 make_error_code(llvm::errc::invalid_argument));522 523 F.Trace = std::move(*TraceOrErr);524 auto GROrError = F.getGraphRenderer();525 if (!GROrError)526 return GROrError.takeError();527 auto &GR = *GROrError;528 529 std::error_code EC;530 raw_fd_ostream OS(GraphOutput, EC, sys::fs::OpenFlags::OF_TextWithCRLF);531 if (EC)532 return make_error<StringError>(533 Twine("Cannot open file '") + GraphOutput + "' for writing.", EC);534 535 GR.exportGraphAsDOT(OS, GraphEdgeLabel, GraphEdgeColorType, GraphVertexLabel,536 GraphVertexColorType);537 return Error::success();538});539