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 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 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. 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. 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> 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 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 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 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. 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. 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 353 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 376 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. 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 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. 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