contrib/llvm/tools/llvm-xray/xray-graph.cc

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