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