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