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