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