tools/llvm-xray/xray-graph.cpp

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