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
22 using namespace llvm;
23 using namespace llvm::xray;
24
25 // Setup llvm-xray graph subcommand and its options.
26 static cl::SubCommand GraphC("graph", "Generate function-call graph");
27 static cl::opt<std::string> GraphInput(cl::Positional,
28 cl::desc("<xray log file>"),
29 cl::Required, cl::sub(GraphC));
30
31 static cl::opt<bool>
32 GraphKeepGoing("keep-going", cl::desc("Keep going on errors encountered"),
33 cl::sub(GraphC), cl::init(false));
34 static cl::alias GraphKeepGoing2("k", cl::aliasopt(GraphKeepGoing),
35 cl::desc("Alias for -keep-going"));
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"));
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
52 static 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));
56 static cl::alias
57 GraphDeduceSiblingCalls2("d", cl::aliasopt(GraphDeduceSiblingCalls),
58 cl::desc("Alias for -deduce-sibling-calls"));
59
60 static 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")));
81 static cl::alias GraphEdgeLabel2("e", cl::aliasopt(GraphEdgeLabel),
82 cl::desc("Alias for -edge-label"));
83
84 static 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")));
105 static cl::alias GraphVertexLabel2("v", cl::aliasopt(GraphVertexLabel),
106 cl::desc("Alias for -edge-label"));
107
108 static 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")));
129 static cl::alias GraphEdgeColorType2("c", cl::aliasopt(GraphEdgeColorType),
130 cl::desc("Alias for -color-edges"));
131
132 static 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")));
153 static cl::alias GraphVertexColorType2("b", cl::aliasopt(GraphVertexColorType),
154 cl::desc("Alias for -edge-label"));
155
diff(T L,T R)156 template <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
updateStat(GraphRenderer::TimeStat & S,int64_t L)159 static 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.
escapeString(StringRef Label)170 static 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("&");
177 break;
178 case '<':
179 Str.append("<");
180 break;
181 case '>':
182 Str.append(">");
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.
accountRecord(const XRayRecord & Record)210 Error 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
277 template <typename U>
getStats(U begin,U end,GraphRenderer::TimeStat & S)278 void 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
updateMaxStats(const GraphRenderer::TimeStat & S,GraphRenderer::TimeStat & M)291 void 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
calculateEdgeStatistics()302 void 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
calculateVertexStatistics()312 void 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.
normalizeTimeStat(GraphRenderer::TimeStat & S,double CycleFrequency)329 static 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.
normalizeStatistics(double CycleFrequency)337 void 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
352 std::string
getString(GraphRenderer::StatType T) const353 GraphRenderer::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
getDouble(StatType T) const376 double 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.
exportGraphAsDOT(raw_ostream & OS,StatType ET,StatType EC,StatType VT,StatType VC)403 void 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
getGraphRenderer()444 Expected<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.
__anon4662d1480302() 508 static 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