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