• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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 
diff(T L,T R)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
updateStat(GraphRenderer::TimeStat & S,int64_t L)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.
accountRecord(const XRayRecord & Record)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   }
250 
251   return Error::success();
252 }
253 
254 template <typename U>
getStats(U begin,U end,GraphRenderer::TimeStat & S)255 void GraphRenderer::getStats(U begin, U end, GraphRenderer::TimeStat &S) {
256   if (begin == end) return;
257   std::ptrdiff_t MedianOff = S.Count / 2;
258   std::nth_element(begin, begin + MedianOff, end);
259   S.Median = *(begin + MedianOff);
260   std::ptrdiff_t Pct90Off = (S.Count * 9) / 10;
261   std::nth_element(begin, begin + Pct90Off, end);
262   S.Pct90 = *(begin + Pct90Off);
263   std::ptrdiff_t Pct99Off = (S.Count * 99) / 100;
264   std::nth_element(begin, begin + Pct99Off, end);
265   S.Pct99 = *(begin + Pct99Off);
266 }
267 
updateMaxStats(const GraphRenderer::TimeStat & S,GraphRenderer::TimeStat & M)268 void GraphRenderer::updateMaxStats(const GraphRenderer::TimeStat &S,
269                                    GraphRenderer::TimeStat &M) {
270   M.Count = std::max(M.Count, S.Count);
271   M.Min = std::max(M.Min, S.Min);
272   M.Median = std::max(M.Median, S.Median);
273   M.Pct90 = std::max(M.Pct90, S.Pct90);
274   M.Pct99 = std::max(M.Pct99, S.Pct99);
275   M.Max = std::max(M.Max, S.Max);
276   M.Sum = std::max(M.Sum, S.Sum);
277 }
278 
calculateEdgeStatistics()279 void GraphRenderer::calculateEdgeStatistics() {
280   assert(!G.edges().empty());
281   for (auto &E : G.edges()) {
282     auto &A = E.second;
283     assert(!A.Timings.empty());
284     getStats(A.Timings.begin(), A.Timings.end(), A.S);
285     updateMaxStats(A.S, G.GraphEdgeMax);
286   }
287 }
288 
calculateVertexStatistics()289 void GraphRenderer::calculateVertexStatistics() {
290   std::vector<uint64_t> TempTimings;
291   for (auto &V : G.vertices()) {
292     if (V.first != 0) {
293       for (auto &E : G.inEdges(V.first)) {
294         auto &A = E.second;
295         TempTimings.insert(TempTimings.end(), A.Timings.begin(),
296                            A.Timings.end());
297       }
298       getStats(TempTimings.begin(), TempTimings.end(), G[V.first].S);
299       updateMaxStats(G[V.first].S, G.GraphVertexMax);
300       TempTimings.clear();
301     }
302   }
303 }
304 
305 // A Helper function for normalizeStatistics which normalises a single
306 // TimeStat element.
normalizeTimeStat(GraphRenderer::TimeStat & S,double CycleFrequency)307 static void normalizeTimeStat(GraphRenderer::TimeStat &S,
308                               double CycleFrequency) {
309   int64_t OldCount = S.Count;
310   S = S / CycleFrequency;
311   S.Count = OldCount;
312 }
313 
314 // Normalises the statistics in the graph for a given TSC frequency.
normalizeStatistics(double CycleFrequency)315 void GraphRenderer::normalizeStatistics(double CycleFrequency) {
316   for (auto &E : G.edges()) {
317     auto &S = E.second.S;
318     normalizeTimeStat(S, CycleFrequency);
319   }
320   for (auto &V : G.vertices()) {
321     auto &S = V.second.S;
322     normalizeTimeStat(S, CycleFrequency);
323   }
324 
325   normalizeTimeStat(G.GraphEdgeMax, CycleFrequency);
326   normalizeTimeStat(G.GraphVertexMax, CycleFrequency);
327 }
328 
329 // Returns a string containing the value of statistic field T
330 std::string
getString(GraphRenderer::StatType T) const331 GraphRenderer::TimeStat::getString(GraphRenderer::StatType T) const {
332   std::string St;
333   raw_string_ostream S{St};
334   double TimeStat::*DoubleStatPtrs[] = {&TimeStat::Min,   &TimeStat::Median,
335                                         &TimeStat::Pct90, &TimeStat::Pct99,
336                                         &TimeStat::Max,   &TimeStat::Sum};
337   switch (T) {
338   case GraphRenderer::StatType::NONE:
339     break;
340   case GraphRenderer::StatType::COUNT:
341     S << Count;
342     break;
343   default:
344     S << (*this).*
345              DoubleStatPtrs[static_cast<int>(T) -
346                             static_cast<int>(GraphRenderer::StatType::MIN)];
347     break;
348   }
349   return S.str();
350 }
351 
352 // Returns the quotient between the property T of this and another TimeStat as
353 // a double
getDouble(StatType T) const354 double GraphRenderer::TimeStat::getDouble(StatType T) const {
355   double retval = 0;
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     retval = 0.0;
362     break;
363   case GraphRenderer::StatType::COUNT:
364     retval = static_cast<double>(Count);
365     break;
366   default:
367     retval =
368         (*this).*DoubleStatPtrs[static_cast<int>(T) -
369                                 static_cast<int>(GraphRenderer::StatType::MIN)];
370     break;
371   }
372   return retval;
373 }
374 
375 // Outputs a DOT format version of the Graph embedded in the GraphRenderer
376 // object on OS. It does this in the expected way by itterating
377 // through all edges then vertices and then outputting them and their
378 // annotations.
379 //
380 // FIXME: output more information, better presented.
exportGraphAsDOT(raw_ostream & OS,StatType ET,StatType EC,StatType VT,StatType VC)381 void GraphRenderer::exportGraphAsDOT(raw_ostream &OS, StatType ET, StatType EC,
382                                      StatType VT, StatType VC) {
383   OS << "digraph xray {\n";
384 
385   if (VT != StatType::NONE)
386     OS << "node [shape=record];\n";
387 
388   for (const auto &E : G.edges()) {
389     const auto &S = E.second.S;
390     OS << "F" << E.first.first << " -> "
391        << "F" << E.first.second << " [label=\"" << S.getString(ET) << "\"";
392     if (EC != StatType::NONE)
393       OS << " color=\""
394          << CHelper.getColorString(
395                 std::sqrt(S.getDouble(EC) / G.GraphEdgeMax.getDouble(EC)))
396          << "\"";
397     OS << "];\n";
398   }
399 
400   for (const auto &V : G.vertices()) {
401     const auto &VA = V.second;
402     if (V.first == 0)
403       continue;
404     OS << "F" << V.first << " [label=\"" << (VT != StatType::NONE ? "{" : "")
405        << (VA.SymbolName.size() > 40 ? VA.SymbolName.substr(0, 40) + "..."
406                                      : VA.SymbolName);
407     if (VT != StatType::NONE)
408       OS << "|" << VA.S.getString(VT) << "}\"";
409     else
410       OS << "\"";
411     if (VC != StatType::NONE)
412       OS << " color=\""
413          << CHelper.getColorString(
414                 std::sqrt(VA.S.getDouble(VC) / G.GraphVertexMax.getDouble(VC)))
415          << "\"";
416     OS << "];\n";
417   }
418   OS << "}\n";
419 }
420 
getGraphRenderer()421 Expected<GraphRenderer> GraphRenderer::Factory::getGraphRenderer() {
422   InstrumentationMap Map;
423   if (!GraphInstrMap.empty()) {
424     auto InstrumentationMapOrError = loadInstrumentationMap(GraphInstrMap);
425     if (!InstrumentationMapOrError)
426       return joinErrors(
427           make_error<StringError>(
428               Twine("Cannot open instrumentation map '") + GraphInstrMap + "'",
429               std::make_error_code(std::errc::invalid_argument)),
430           InstrumentationMapOrError.takeError());
431     Map = std::move(*InstrumentationMapOrError);
432   }
433 
434   const auto &FunctionAddresses = Map.getFunctionAddresses();
435 
436   symbolize::LLVMSymbolizer::Options Opts(
437       symbolize::FunctionNameKind::LinkageName, true, true, false, "");
438   symbolize::LLVMSymbolizer Symbolizer(Opts);
439   const auto &Header = Trace.getFileHeader();
440 
441   llvm::xray::FuncIdConversionHelper FuncIdHelper(InstrMap, Symbolizer,
442                                                   FunctionAddresses);
443 
444   xray::GraphRenderer GR(FuncIdHelper, DeduceSiblingCalls);
445   for (const auto &Record : Trace) {
446     auto E = GR.accountRecord(Record);
447     if (!E)
448       continue;
449 
450     for (const auto &ThreadStack : GR.getPerThreadFunctionStack()) {
451       errs() << "Thread ID: " << ThreadStack.first << "\n";
452       auto Level = ThreadStack.second.size();
453       for (const auto &Entry : llvm::reverse(ThreadStack.second))
454         errs() << "#" << Level-- << "\t"
455                << FuncIdHelper.SymbolOrNumber(Entry.FuncId) << '\n';
456     }
457 
458     if (!GraphKeepGoing)
459       return joinErrors(make_error<StringError>(
460                             "Error encountered generating the call graph.",
461                             std::make_error_code(std::errc::invalid_argument)),
462                         std::move(E));
463 
464     handleAllErrors(std::move(E),
465                     [&](const ErrorInfoBase &E) { E.log(errs()); });
466   }
467 
468   GR.G.GraphEdgeMax = {};
469   GR.G.GraphVertexMax = {};
470   GR.calculateEdgeStatistics();
471   GR.calculateVertexStatistics();
472 
473   if (Header.CycleFrequency)
474     GR.normalizeStatistics(Header.CycleFrequency);
475 
476   return GR;
477 }
478 
479 // Here we register and implement the llvm-xray graph subcommand.
480 // The bulk of this code reads in the options, opens the required files, uses
481 // those files to create a context for analysing the xray trace, then there is a
482 // short loop which actually analyses the trace, generates the graph and then
483 // outputs it as a DOT.
484 //
485 // FIXME: include additional filtering and annalysis passes to provide more
486 // specific useful information.
__anonf9893fcb0302() 487 static CommandRegistration Unused(&GraphC, []() -> Error {
488   GraphRenderer::Factory F;
489 
490   F.KeepGoing = GraphKeepGoing;
491   F.DeduceSiblingCalls = GraphDeduceSiblingCalls;
492   F.InstrMap = GraphInstrMap;
493 
494   auto TraceOrErr = loadTraceFile(GraphInput, true);
495 
496   if (!TraceOrErr)
497     return make_error<StringError>(
498         Twine("Failed loading input file '") + GraphInput + "'",
499         make_error_code(llvm::errc::invalid_argument));
500 
501   F.Trace = std::move(*TraceOrErr);
502   auto GROrError = F.getGraphRenderer();
503   if (!GROrError)
504     return GROrError.takeError();
505   auto &GR = *GROrError;
506 
507   std::error_code EC;
508   raw_fd_ostream OS(GraphOutput, EC, sys::fs::OpenFlags::F_Text);
509   if (EC)
510     return make_error<StringError>(
511         Twine("Cannot open file '") + GraphOutput + "' for writing.", EC);
512 
513   GR.exportGraphAsDOT(OS, GraphEdgeLabel, GraphEdgeColorType, GraphVertexLabel,
514                       GraphVertexColorType);
515   return Error::success();
516 });
517