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
diff(T L,T R)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
updateStat(GraphRenderer::TimeStat & S,int64_t L)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 // Labels in a DOT graph must be legal XML strings so it's necessary to escape
167 // certain characters.
escapeString(StringRef Label)168 static 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("&");
175 break;
176 case '<':
177 Str.append("<");
178 break;
179 case '>':
180 Str.append(">");
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.
accountRecord(const XRayRecord & Record)208 Error 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
274 template <typename U>
getStats(U begin,U end,GraphRenderer::TimeStat & S)275 void 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
updateMaxStats(const GraphRenderer::TimeStat & S,GraphRenderer::TimeStat & M)288 void 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
calculateEdgeStatistics()299 void 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
calculateVertexStatistics()309 void 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 llvm::append_range(TempTimings, A.Timings);
316 }
317 getStats(TempTimings.begin(), TempTimings.end(), G[V.first].S);
318 updateMaxStats(G[V.first].S, G.GraphVertexMax);
319 TempTimings.clear();
320 }
321 }
322 }
323
324 // A Helper function for normalizeStatistics which normalises a single
325 // TimeStat element.
normalizeTimeStat(GraphRenderer::TimeStat & S,double CycleFrequency)326 static void normalizeTimeStat(GraphRenderer::TimeStat &S,
327 double CycleFrequency) {
328 int64_t OldCount = S.Count;
329 S = S / CycleFrequency;
330 S.Count = OldCount;
331 }
332
333 // Normalises the statistics in the graph for a given TSC frequency.
normalizeStatistics(double CycleFrequency)334 void GraphRenderer::normalizeStatistics(double CycleFrequency) {
335 for (auto &E : G.edges()) {
336 auto &S = E.second.S;
337 normalizeTimeStat(S, CycleFrequency);
338 }
339 for (auto &V : G.vertices()) {
340 auto &S = V.second.S;
341 normalizeTimeStat(S, CycleFrequency);
342 }
343
344 normalizeTimeStat(G.GraphEdgeMax, CycleFrequency);
345 normalizeTimeStat(G.GraphVertexMax, CycleFrequency);
346 }
347
348 // Returns a string containing the value of statistic field T
349 std::string
getString(GraphRenderer::StatType T) const350 GraphRenderer::TimeStat::getString(GraphRenderer::StatType T) const {
351 std::string St;
352 raw_string_ostream S{St};
353 double TimeStat::*DoubleStatPtrs[] = {&TimeStat::Min, &TimeStat::Median,
354 &TimeStat::Pct90, &TimeStat::Pct99,
355 &TimeStat::Max, &TimeStat::Sum};
356 switch (T) {
357 case GraphRenderer::StatType::NONE:
358 break;
359 case GraphRenderer::StatType::COUNT:
360 S << Count;
361 break;
362 default:
363 S << (*this).*
364 DoubleStatPtrs[static_cast<int>(T) -
365 static_cast<int>(GraphRenderer::StatType::MIN)];
366 break;
367 }
368 return S.str();
369 }
370
371 // Returns the quotient between the property T of this and another TimeStat as
372 // a double
getDouble(StatType T) const373 double GraphRenderer::TimeStat::getDouble(StatType T) const {
374 double retval = 0;
375 double TimeStat::*DoubleStatPtrs[] = {&TimeStat::Min, &TimeStat::Median,
376 &TimeStat::Pct90, &TimeStat::Pct99,
377 &TimeStat::Max, &TimeStat::Sum};
378 switch (T) {
379 case GraphRenderer::StatType::NONE:
380 retval = 0.0;
381 break;
382 case GraphRenderer::StatType::COUNT:
383 retval = static_cast<double>(Count);
384 break;
385 default:
386 retval =
387 (*this).*DoubleStatPtrs[static_cast<int>(T) -
388 static_cast<int>(GraphRenderer::StatType::MIN)];
389 break;
390 }
391 return retval;
392 }
393
394 // Outputs a DOT format version of the Graph embedded in the GraphRenderer
395 // object on OS. It does this in the expected way by itterating
396 // through all edges then vertices and then outputting them and their
397 // annotations.
398 //
399 // FIXME: output more information, better presented.
exportGraphAsDOT(raw_ostream & OS,StatType ET,StatType EC,StatType VT,StatType VC)400 void GraphRenderer::exportGraphAsDOT(raw_ostream &OS, StatType ET, StatType EC,
401 StatType VT, StatType VC) {
402 OS << "digraph xray {\n";
403
404 if (VT != StatType::NONE)
405 OS << "node [shape=record];\n";
406
407 for (const auto &E : G.edges()) {
408 const auto &S = E.second.S;
409 OS << "F" << E.first.first << " -> "
410 << "F" << E.first.second << " [label=\"" << S.getString(ET) << "\"";
411 if (EC != StatType::NONE)
412 OS << " color=\""
413 << CHelper.getColorString(
414 std::sqrt(S.getDouble(EC) / G.GraphEdgeMax.getDouble(EC)))
415 << "\"";
416 OS << "];\n";
417 }
418
419 for (const auto &V : G.vertices()) {
420 const auto &VA = V.second;
421 if (V.first == 0)
422 continue;
423 OS << "F" << V.first << " [label=\"" << (VT != StatType::NONE ? "{" : "")
424 << escapeString(VA.SymbolName.size() > 40
425 ? VA.SymbolName.substr(0, 40) + "..."
426 : VA.SymbolName);
427 if (VT != StatType::NONE)
428 OS << "|" << VA.S.getString(VT) << "}\"";
429 else
430 OS << "\"";
431 if (VC != StatType::NONE)
432 OS << " color=\""
433 << CHelper.getColorString(
434 std::sqrt(VA.S.getDouble(VC) / G.GraphVertexMax.getDouble(VC)))
435 << "\"";
436 OS << "];\n";
437 }
438 OS << "}\n";
439 }
440
getGraphRenderer()441 Expected<GraphRenderer> GraphRenderer::Factory::getGraphRenderer() {
442 InstrumentationMap Map;
443 if (!GraphInstrMap.empty()) {
444 auto InstrumentationMapOrError = loadInstrumentationMap(GraphInstrMap);
445 if (!InstrumentationMapOrError)
446 return joinErrors(
447 make_error<StringError>(
448 Twine("Cannot open instrumentation map '") + GraphInstrMap + "'",
449 std::make_error_code(std::errc::invalid_argument)),
450 InstrumentationMapOrError.takeError());
451 Map = std::move(*InstrumentationMapOrError);
452 }
453
454 const auto &FunctionAddresses = Map.getFunctionAddresses();
455
456 symbolize::LLVMSymbolizer Symbolizer;
457 const auto &Header = Trace.getFileHeader();
458
459 llvm::xray::FuncIdConversionHelper FuncIdHelper(InstrMap, Symbolizer,
460 FunctionAddresses);
461
462 xray::GraphRenderer GR(FuncIdHelper, DeduceSiblingCalls);
463 for (const auto &Record : Trace) {
464 auto E = GR.accountRecord(Record);
465 if (!E)
466 continue;
467
468 for (const auto &ThreadStack : GR.getPerThreadFunctionStack()) {
469 errs() << "Thread ID: " << ThreadStack.first << "\n";
470 auto Level = ThreadStack.second.size();
471 for (const auto &Entry : llvm::reverse(ThreadStack.second))
472 errs() << "#" << Level-- << "\t"
473 << FuncIdHelper.SymbolOrNumber(Entry.FuncId) << '\n';
474 }
475
476 if (!GraphKeepGoing)
477 return joinErrors(make_error<StringError>(
478 "Error encountered generating the call graph.",
479 std::make_error_code(std::errc::invalid_argument)),
480 std::move(E));
481
482 handleAllErrors(std::move(E),
483 [&](const ErrorInfoBase &E) { E.log(errs()); });
484 }
485
486 GR.G.GraphEdgeMax = {};
487 GR.G.GraphVertexMax = {};
488 GR.calculateEdgeStatistics();
489 GR.calculateVertexStatistics();
490
491 if (Header.CycleFrequency)
492 GR.normalizeStatistics(Header.CycleFrequency);
493
494 return GR;
495 }
496
497 // Here we register and implement the llvm-xray graph subcommand.
498 // The bulk of this code reads in the options, opens the required files, uses
499 // those files to create a context for analysing the xray trace, then there is a
500 // short loop which actually analyses the trace, generates the graph and then
501 // outputs it as a DOT.
502 //
503 // FIXME: include additional filtering and annalysis passes to provide more
504 // specific useful information.
__anon92a68a0e0302() 505 static CommandRegistration Unused(&GraphC, []() -> Error {
506 GraphRenderer::Factory F;
507
508 F.KeepGoing = GraphKeepGoing;
509 F.DeduceSiblingCalls = GraphDeduceSiblingCalls;
510 F.InstrMap = GraphInstrMap;
511
512 auto TraceOrErr = loadTraceFile(GraphInput, true);
513
514 if (!TraceOrErr)
515 return make_error<StringError>(
516 Twine("Failed loading input file '") + GraphInput + "'",
517 make_error_code(llvm::errc::invalid_argument));
518
519 F.Trace = std::move(*TraceOrErr);
520 auto GROrError = F.getGraphRenderer();
521 if (!GROrError)
522 return GROrError.takeError();
523 auto &GR = *GROrError;
524
525 std::error_code EC;
526 raw_fd_ostream OS(GraphOutput, EC, sys::fs::OpenFlags::OF_TextWithCRLF);
527 if (EC)
528 return make_error<StringError>(
529 Twine("Cannot open file '") + GraphOutput + "' for writing.", EC);
530
531 GR.exportGraphAsDOT(OS, GraphEdgeLabel, GraphEdgeColorType, GraphVertexLabel,
532 GraphVertexColorType);
533 return Error::success();
534 });
535