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 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> 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 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 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 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. 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. 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 350 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 373 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. 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 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. 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