xray-graph.cpp revision 360784 
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// 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.
184Error 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
250template <typename U>
251void 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
264void 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
275void 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
285void 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.
303static 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.
311void 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
326std::string
327GraphRenderer::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
350double 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.
377void 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
417Expected<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.
481static 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});
511