llvm/tools/llvm-xray/xray-graph.cpp

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