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