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