llvm/tools/llvm-xray/xray-graph.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-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       bool FoundParent =
 236           llvm::any_of(llvm::reverse(ThreadStack), [&](const FunctionAttr &A) {
 237             return A.FuncId == Record.FuncId;
 238           });
 239       if (!FoundParent)
 240         return make_error<StringError>(
 241             "No matching Entry record in stack",
 242             make_error_code(errc::invalid_argument)); // There is no matching
 243                                                       // Function for this exit.
 244       while (ThreadStack.back().FuncId != Record.FuncId) {
 245         TimestampT D = diff(ThreadStack.back().TSC, Record.TSC);
 246         VertexIdentifier TopFuncId = ThreadStack.back().FuncId;
 247         ThreadStack.pop_back();
 248         assert(ThreadStack.size() != 0);
 249         EdgeIdentifier EI(ThreadStack.back().FuncId, TopFuncId);
 250         auto &EA = G[EI];
 251         EA.Timings.push_back(D);
 252         updateStat(EA.S, D);
 253         updateStat(G[TopFuncId].S, D);
 254       }
 255     }
 256     uint64_t D = diff(ThreadStack.back().TSC, Record.TSC);
 257     ThreadStack.pop_back();
 258     VertexIdentifier VI = ThreadStack.empty() ? 0 : ThreadStack.back().FuncId;
 259     EdgeIdentifier EI(VI, Record.FuncId);
 260     auto &EA = G[EI];
 261     EA.Timings.push_back(D);
 262     updateStat(EA.S, D);
 263     updateStat(G[Record.FuncId].S, D);
 264     break;
 265   }
 266   case RecordTypes::CUSTOM_EVENT:
 267   case RecordTypes::TYPED_EVENT:
 268     // TODO: Support custom and typed events in the graph processing?
 269     break;
 270   }
 271
 272   return Error::success();
 273 }
 274
 275 template <typename U>
 276 void GraphRenderer::getStats(U begin, U end, GraphRenderer::TimeStat &S) {
 277   if (begin == end) return;
 278   std::ptrdiff_t MedianOff = S.Count / 2;
 279   std::nth_element(begin, begin + MedianOff, end);
 280   S.Median = *(begin + MedianOff);
 281   std::ptrdiff_t Pct90Off = (S.Count * 9) / 10;
 282   std::nth_element(begin, begin + Pct90Off, end);
 283   S.Pct90 = *(begin + Pct90Off);
 284   std::ptrdiff_t Pct99Off = (S.Count * 99) / 100;
 285   std::nth_element(begin, begin + Pct99Off, end);
 286   S.Pct99 = *(begin + Pct99Off);
 287 }
 288
 289 void GraphRenderer::updateMaxStats(const GraphRenderer::TimeStat &S,
 290                                    GraphRenderer::TimeStat &M) {
 291   M.Count = std::max(M.Count, S.Count);
 292   M.Min = std::max(M.Min, S.Min);
 293   M.Median = std::max(M.Median, S.Median);
 294   M.Pct90 = std::max(M.Pct90, S.Pct90);
 295   M.Pct99 = std::max(M.Pct99, S.Pct99);
 296   M.Max = std::max(M.Max, S.Max);
 297   M.Sum = std::max(M.Sum, S.Sum);
 298 }
 299
 300 void GraphRenderer::calculateEdgeStatistics() {
 301   assert(!G.edges().empty());
 302   for (auto &E : G.edges()) {
 303     auto &A = E.second;
 304     assert(!A.Timings.empty());
 305     getStats(A.Timings.begin(), A.Timings.end(), A.S);
 306     updateMaxStats(A.S, G.GraphEdgeMax);
 307   }
 308 }
 309
 310 void GraphRenderer::calculateVertexStatistics() {
 311   std::vector<uint64_t> TempTimings;
 312   for (auto &V : G.vertices()) {
 313     if (V.first != 0) {
 314       for (auto &E : G.inEdges(V.first)) {
 315         auto &A = E.second;
 316         llvm::append_range(TempTimings, A.Timings);
 317       }
 318       getStats(TempTimings.begin(), TempTimings.end(), G[V.first].S);
 319       updateMaxStats(G[V.first].S, G.GraphVertexMax);
 320       TempTimings.clear();
 321     }
 322   }
 323 }
 324
 325 // A Helper function for normalizeStatistics which normalises a single
 326 // TimeStat element.
 327 static void normalizeTimeStat(GraphRenderer::TimeStat &S,
 328                               double CycleFrequency) {
 329   int64_t OldCount = S.Count;
 330   S = S / CycleFrequency;
 331   S.Count = OldCount;
 332 }
 333
 334 // Normalises the statistics in the graph for a given TSC frequency.
 335 void GraphRenderer::normalizeStatistics(double CycleFrequency) {
 336   for (auto &E : G.edges()) {
 337     auto &S = E.second.S;
 338     normalizeTimeStat(S, CycleFrequency);
 339   }
 340   for (auto &V : G.vertices()) {
 341     auto &S = V.second.S;
 342     normalizeTimeStat(S, CycleFrequency);
 343   }
 344
 345   normalizeTimeStat(G.GraphEdgeMax, CycleFrequency);
 346   normalizeTimeStat(G.GraphVertexMax, CycleFrequency);
 347 }
 348
 349 // Returns a string containing the value of statistic field T
 350 std::string
 351 GraphRenderer::TimeStat::getString(GraphRenderer::StatType T) const {
 352   std::string St;
 353   raw_string_ostream S{St};
 354   double TimeStat::*DoubleStatPtrs[] = {&TimeStat::Min,   &TimeStat::Median,
 355                                         &TimeStat::Pct90, &TimeStat::Pct99,
 356                                         &TimeStat::Max,   &TimeStat::Sum};
 357   switch (T) {
 358   case GraphRenderer::StatType::NONE:
 359     break;
 360   case GraphRenderer::StatType::COUNT:
 361     S << Count;
 362     break;
 363   default:
 364     S << (*this).*
 365              DoubleStatPtrs[static_cast<int>(T) -
 366                             static_cast<int>(GraphRenderer::StatType::MIN)];
 367     break;
 368   }
 369   return S.str();
 370 }
 371
 372 // Returns the quotient between the property T of this and another TimeStat as
 373 // a double
 374 double GraphRenderer::TimeStat::getDouble(StatType T) const {
 375   double retval = 0;
 376   double TimeStat::*DoubleStatPtrs[] = {&TimeStat::Min,   &TimeStat::Median,
 377                                         &TimeStat::Pct90, &TimeStat::Pct99,
 378                                         &TimeStat::Max,   &TimeStat::Sum};
 379   switch (T) {
 380   case GraphRenderer::StatType::NONE:
 381     retval = 0.0;
 382     break;
 383   case GraphRenderer::StatType::COUNT:
 384     retval = static_cast<double>(Count);
 385     break;
 386   default:
 387     retval =
 388         (*this).*DoubleStatPtrs[static_cast<int>(T) -
 389                                 static_cast<int>(GraphRenderer::StatType::MIN)];
 390     break;
 391   }
 392   return retval;
 393 }
 394
 395 // Outputs a DOT format version of the Graph embedded in the GraphRenderer
 396 // object on OS. It does this in the expected way by itterating
 397 // through all edges then vertices and then outputting them and their
 398 // annotations.
 399 //
 400 // FIXME: output more information, better presented.
 401 void GraphRenderer::exportGraphAsDOT(raw_ostream &OS, StatType ET, StatType EC,
 402                                      StatType VT, StatType VC) {
 403   OS << "digraph xray {\n";
 404
 405   if (VT != StatType::NONE)
 406     OS << "node [shape=record];\n";
 407
 408   for (const auto &E : G.edges()) {
 409     const auto &S = E.second.S;
 410     OS << "F" << E.first.first << " -> "
 411        << "F" << E.first.second << " [label=\"" << S.getString(ET) << "\"";
 412     if (EC != StatType::NONE)
 413       OS << " color=\""
 414          << CHelper.getColorString(
 415                 std::sqrt(S.getDouble(EC) / G.GraphEdgeMax.getDouble(EC)))
 416          << "\"";
 417     OS << "];\n";
 418   }
 419
 420   for (const auto &V : G.vertices()) {
 421     const auto &VA = V.second;
 422     if (V.first == 0)
 423       continue;
 424     OS << "F" << V.first << " [label=\"" << (VT != StatType::NONE ? "{" : "")
 425        << escapeString(VA.SymbolName.size() > 40
 426                            ? VA.SymbolName.substr(0, 40) + "..."
 427                            : VA.SymbolName);
 428     if (VT != StatType::NONE)
 429       OS << "|" << VA.S.getString(VT) << "}\"";
 430     else
 431       OS << "\"";
 432     if (VC != StatType::NONE)
 433       OS << " color=\""
 434          << CHelper.getColorString(
 435                 std::sqrt(VA.S.getDouble(VC) / G.GraphVertexMax.getDouble(VC)))
 436          << "\"";
 437     OS << "];\n";
 438   }
 439   OS << "}\n";
 440 }
 441
 442 Expected<GraphRenderer> GraphRenderer::Factory::getGraphRenderer() {
 443   InstrumentationMap Map;
 444   if (!GraphInstrMap.empty()) {
 445     auto InstrumentationMapOrError = loadInstrumentationMap(GraphInstrMap);
 446     if (!InstrumentationMapOrError)
 447       return joinErrors(
 448           make_error<StringError>(
 449               Twine("Cannot open instrumentation map '") + GraphInstrMap + "'",
 450               std::make_error_code(std::errc::invalid_argument)),
 451           InstrumentationMapOrError.takeError());
 452     Map = std::move(*InstrumentationMapOrError);
 453   }
 454
 455   const auto &FunctionAddresses = Map.getFunctionAddresses();
 456
 457   symbolize::LLVMSymbolizer Symbolizer;
 458   const auto &Header = Trace.getFileHeader();
 459
 460   llvm::xray::FuncIdConversionHelper FuncIdHelper(InstrMap, Symbolizer,
 461                                                   FunctionAddresses);
 462
 463   xray::GraphRenderer GR(FuncIdHelper, DeduceSiblingCalls);
 464   for (const auto &Record : Trace) {
 465     auto E = GR.accountRecord(Record);
 466     if (!E)
 467       continue;
 468
 469     for (const auto &ThreadStack : GR.getPerThreadFunctionStack()) {
 470       errs() << "Thread ID: " << ThreadStack.first << "\n";
 471       auto Level = ThreadStack.second.size();
 472       for (const auto &Entry : llvm::reverse(ThreadStack.second))
 473         errs() << "#" << Level-- << "\t"
 474                << FuncIdHelper.SymbolOrNumber(Entry.FuncId) << '\n';
 475     }
 476
 477     if (!GraphKeepGoing)
 478       return joinErrors(make_error<StringError>(
 479                             "Error encountered generating the call graph.",
 480                             std::make_error_code(std::errc::invalid_argument)),
 481                         std::move(E));
 482
 483     handleAllErrors(std::move(E),
 484                     [&](const ErrorInfoBase &E) { E.log(errs()); });
 485   }
 486
 487   GR.G.GraphEdgeMax = {};
 488   GR.G.GraphVertexMax = {};
 489   GR.calculateEdgeStatistics();
 490   GR.calculateVertexStatistics();
 491
 492   if (Header.CycleFrequency)
 493     GR.normalizeStatistics(Header.CycleFrequency);
 494
 495   return GR;
 496 }
 497
 498 // Here we register and implement the llvm-xray graph subcommand.
 499 // The bulk of this code reads in the options, opens the required files, uses
 500 // those files to create a context for analysing the xray trace, then there is a
 501 // short loop which actually analyses the trace, generates the graph and then
 502 // outputs it as a DOT.
 503 //
 504 // FIXME: include additional filtering and annalysis passes to provide more
 505 // specific useful information.
 506 static CommandRegistration Unused(&GraphC, []() -> Error {
 507   GraphRenderer::Factory F;
 508
 509   F.KeepGoing = GraphKeepGoing;
 510   F.DeduceSiblingCalls = GraphDeduceSiblingCalls;
 511   F.InstrMap = GraphInstrMap;
 512
 513   auto TraceOrErr = loadTraceFile(GraphInput, true);
 514
 515   if (!TraceOrErr)
 516     return make_error<StringError>(
 517         Twine("Failed loading input file '") + GraphInput + "'",
 518         make_error_code(llvm::errc::invalid_argument));
 519
 520   F.Trace = std::move(*TraceOrErr);
 521   auto GROrError = F.getGraphRenderer();
 522   if (!GROrError)
 523     return GROrError.takeError();
 524   auto &GR = *GROrError;
 525
 526   std::error_code EC;
 527   raw_fd_ostream OS(GraphOutput, EC, sys::fs::OpenFlags::OF_TextWithCRLF);
 528   if (EC)
 529     return make_error<StringError>(
 530         Twine("Cannot open file '") + GraphOutput + "' for writing.", EC);
 531
 532   GR.exportGraphAsDOT(OS, GraphEdgeLabel, GraphEdgeColorType, GraphVertexLabel,
 533                       GraphVertexColorType);
 534   return Error::success();
 535 });