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 cl::sub(GraphC)); 35 36 static cl::opt<std::string> 37 GraphOutput("output", cl::value_desc("Output file"), cl::init("-"), 38 cl::desc("output file; use '-' for stdout"), cl::sub(GraphC)); 39 static cl::alias GraphOutput2("o", cl::aliasopt(GraphOutput), 40 cl::desc("Alias for -output"), cl::sub(GraphC)); 41 42 static cl::opt<std::string> 43 GraphInstrMap("instr_map", 44 cl::desc("binary with the instrumrntation map, or " 45 "a separate instrumentation map"), 46 cl::value_desc("binary with xray_instr_map"), cl::sub(GraphC), 47 cl::init("")); 48 static cl::alias GraphInstrMap2("m", cl::aliasopt(GraphInstrMap), 49 cl::desc("alias for -instr_map"), 50 cl::sub(GraphC)); 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 cl::sub(GraphC)); 60 61 static cl::opt<GraphRenderer::StatType> 62 GraphEdgeLabel("edge-label", 63 cl::desc("Output graphs with edges labeled with this field"), 64 cl::value_desc("field"), cl::sub(GraphC), 65 cl::init(GraphRenderer::StatType::NONE), 66 cl::values(clEnumValN(GraphRenderer::StatType::NONE, "none", 67 "Do not label Edges"), 68 clEnumValN(GraphRenderer::StatType::COUNT, 69 "count", "function call counts"), 70 clEnumValN(GraphRenderer::StatType::MIN, "min", 71 "minimum function durations"), 72 clEnumValN(GraphRenderer::StatType::MED, "med", 73 "median function durations"), 74 clEnumValN(GraphRenderer::StatType::PCT90, "90p", 75 "90th percentile durations"), 76 clEnumValN(GraphRenderer::StatType::PCT99, "99p", 77 "99th percentile durations"), 78 clEnumValN(GraphRenderer::StatType::MAX, "max", 79 "maximum function durations"), 80 clEnumValN(GraphRenderer::StatType::SUM, "sum", 81 "sum of call durations"))); 82 static cl::alias GraphEdgeLabel2("e", cl::aliasopt(GraphEdgeLabel), 83 cl::desc("Alias for -edge-label"), 84 cl::sub(GraphC)); 85 86 static cl::opt<GraphRenderer::StatType> GraphVertexLabel( 87 "vertex-label", 88 cl::desc("Output graphs with vertices labeled with this field"), 89 cl::value_desc("field"), cl::sub(GraphC), 90 cl::init(GraphRenderer::StatType::NONE), 91 cl::values(clEnumValN(GraphRenderer::StatType::NONE, "none", 92 "Do not label Vertices"), 93 clEnumValN(GraphRenderer::StatType::COUNT, "count", 94 "function call counts"), 95 clEnumValN(GraphRenderer::StatType::MIN, "min", 96 "minimum function durations"), 97 clEnumValN(GraphRenderer::StatType::MED, "med", 98 "median function durations"), 99 clEnumValN(GraphRenderer::StatType::PCT90, "90p", 100 "90th percentile durations"), 101 clEnumValN(GraphRenderer::StatType::PCT99, "99p", 102 "99th percentile durations"), 103 clEnumValN(GraphRenderer::StatType::MAX, "max", 104 "maximum function durations"), 105 clEnumValN(GraphRenderer::StatType::SUM, "sum", 106 "sum of call durations"))); 107 static cl::alias GraphVertexLabel2("v", cl::aliasopt(GraphVertexLabel), 108 cl::desc("Alias for -edge-label"), 109 cl::sub(GraphC)); 110 111 static cl::opt<GraphRenderer::StatType> GraphEdgeColorType( 112 "color-edges", 113 cl::desc("Output graphs with edge colors determined by this field"), 114 cl::value_desc("field"), cl::sub(GraphC), 115 cl::init(GraphRenderer::StatType::NONE), 116 cl::values(clEnumValN(GraphRenderer::StatType::NONE, "none", 117 "Do not color Edges"), 118 clEnumValN(GraphRenderer::StatType::COUNT, "count", 119 "function call counts"), 120 clEnumValN(GraphRenderer::StatType::MIN, "min", 121 "minimum function durations"), 122 clEnumValN(GraphRenderer::StatType::MED, "med", 123 "median function durations"), 124 clEnumValN(GraphRenderer::StatType::PCT90, "90p", 125 "90th percentile durations"), 126 clEnumValN(GraphRenderer::StatType::PCT99, "99p", 127 "99th percentile durations"), 128 clEnumValN(GraphRenderer::StatType::MAX, "max", 129 "maximum function durations"), 130 clEnumValN(GraphRenderer::StatType::SUM, "sum", 131 "sum of call durations"))); 132 static cl::alias GraphEdgeColorType2("c", cl::aliasopt(GraphEdgeColorType), 133 cl::desc("Alias for -color-edges"), 134 cl::sub(GraphC)); 135 136 static cl::opt<GraphRenderer::StatType> GraphVertexColorType( 137 "color-vertices", 138 cl::desc("Output graphs with vertex colors determined by this field"), 139 cl::value_desc("field"), cl::sub(GraphC), 140 cl::init(GraphRenderer::StatType::NONE), 141 cl::values(clEnumValN(GraphRenderer::StatType::NONE, "none", 142 "Do not color vertices"), 143 clEnumValN(GraphRenderer::StatType::COUNT, "count", 144 "function call counts"), 145 clEnumValN(GraphRenderer::StatType::MIN, "min", 146 "minimum function durations"), 147 clEnumValN(GraphRenderer::StatType::MED, "med", 148 "median function durations"), 149 clEnumValN(GraphRenderer::StatType::PCT90, "90p", 150 "90th percentile durations"), 151 clEnumValN(GraphRenderer::StatType::PCT99, "99p", 152 "99th percentile durations"), 153 clEnumValN(GraphRenderer::StatType::MAX, "max", 154 "maximum function durations"), 155 clEnumValN(GraphRenderer::StatType::SUM, "sum", 156 "sum of call durations"))); 157 static cl::alias GraphVertexColorType2("b", cl::aliasopt(GraphVertexColorType), 158 cl::desc("Alias for -edge-label"), 159 cl::sub(GraphC)); 160 161 template <class T> T diff(T L, T R) { return std::max(L, R) - std::min(L, R); } 162 163 // Updates the statistics for a GraphRenderer::TimeStat 164 static void updateStat(GraphRenderer::TimeStat &S, int64_t L) { 165 S.Count++; 166 if (S.Min > L || S.Min == 0) 167 S.Min = L; 168 if (S.Max < L) 169 S.Max = L; 170 S.Sum += L; 171 } 172 173 // Evaluates an XRay record and performs accounting on it. 174 // 175 // If the record is an ENTER record it pushes the FuncID and TSC onto a 176 // structure representing the call stack for that function. 177 // If the record is an EXIT record it checks computes computes the ammount of 178 // time the function took to complete and then stores that information in an 179 // edge of the graph. If there is no matching ENTER record the function tries 180 // to recover by assuming that there were EXIT records which were missed, for 181 // example caused by tail call elimination and if the option is enabled then 182 // then tries to recover from this. 183 // 184 // This funciton will also error if the records are out of order, as the trace 185 // is expected to be sorted. 186 // 187 // The graph generated has an immaginary root for functions called by no-one at 188 // FuncId 0. 189 // 190 // FIXME: Refactor this and account subcommand to reduce code duplication. 191 Error GraphRenderer::accountRecord(const XRayRecord &Record) { 192 using std::make_error_code; 193 using std::errc; 194 if (CurrentMaxTSC == 0) 195 CurrentMaxTSC = Record.TSC; 196 197 if (Record.TSC < CurrentMaxTSC) 198 return make_error<StringError>("Records not in order", 199 make_error_code(errc::invalid_argument)); 200 201 auto &ThreadStack = PerThreadFunctionStack[Record.TId]; 202 switch (Record.Type) { 203 case RecordTypes::ENTER: 204 case RecordTypes::ENTER_ARG: { 205 if (Record.FuncId != 0 && G.count(Record.FuncId) == 0) 206 G[Record.FuncId].SymbolName = FuncIdHelper.SymbolOrNumber(Record.FuncId); 207 ThreadStack.push_back({Record.FuncId, Record.TSC}); 208 break; 209 } 210 case RecordTypes::EXIT: 211 case RecordTypes::TAIL_EXIT: { 212 // FIXME: Refactor this and the account subcommand to reduce code 213 // duplication 214 if (ThreadStack.size() == 0 || ThreadStack.back().FuncId != Record.FuncId) { 215 if (!DeduceSiblingCalls) 216 return make_error<StringError>("No matching ENTRY record", 217 make_error_code(errc::invalid_argument)); 218 auto Parent = std::find_if( 219 ThreadStack.rbegin(), ThreadStack.rend(), 220 [&](const FunctionAttr &A) { return A.FuncId == Record.FuncId; }); 221 if (Parent == ThreadStack.rend()) 222 return make_error<StringError>( 223 "No matching Entry record in stack", 224 make_error_code(errc::invalid_argument)); // There is no matching 225 // Function for this exit. 226 while (ThreadStack.back().FuncId != Record.FuncId) { 227 TimestampT D = diff(ThreadStack.back().TSC, Record.TSC); 228 VertexIdentifier TopFuncId = ThreadStack.back().FuncId; 229 ThreadStack.pop_back(); 230 assert(ThreadStack.size() != 0); 231 EdgeIdentifier EI(ThreadStack.back().FuncId, TopFuncId); 232 auto &EA = G[EI]; 233 EA.Timings.push_back(D); 234 updateStat(EA.S, D); 235 updateStat(G[TopFuncId].S, D); 236 } 237 } 238 uint64_t D = diff(ThreadStack.back().TSC, Record.TSC); 239 ThreadStack.pop_back(); 240 VertexIdentifier VI = ThreadStack.empty() ? 0 : ThreadStack.back().FuncId; 241 EdgeIdentifier EI(VI, Record.FuncId); 242 auto &EA = G[EI]; 243 EA.Timings.push_back(D); 244 updateStat(EA.S, D); 245 updateStat(G[Record.FuncId].S, D); 246 break; 247 } 248 case RecordTypes::CUSTOM_EVENT: 249 case RecordTypes::TYPED_EVENT: 250 // TODO: Support custom and typed events in the graph processing? 251 break; 252 } 253 254 return Error::success(); 255 } 256 257 template <typename U> 258 void GraphRenderer::getStats(U begin, U end, GraphRenderer::TimeStat &S) { 259 if (begin == end) return; 260 std::ptrdiff_t MedianOff = S.Count / 2; 261 std::nth_element(begin, begin + MedianOff, end); 262 S.Median = *(begin + MedianOff); 263 std::ptrdiff_t Pct90Off = (S.Count * 9) / 10; 264 std::nth_element(begin, begin + Pct90Off, end); 265 S.Pct90 = *(begin + Pct90Off); 266 std::ptrdiff_t Pct99Off = (S.Count * 99) / 100; 267 std::nth_element(begin, begin + Pct99Off, end); 268 S.Pct99 = *(begin + Pct99Off); 269 } 270 271 void GraphRenderer::updateMaxStats(const GraphRenderer::TimeStat &S, 272 GraphRenderer::TimeStat &M) { 273 M.Count = std::max(M.Count, S.Count); 274 M.Min = std::max(M.Min, S.Min); 275 M.Median = std::max(M.Median, S.Median); 276 M.Pct90 = std::max(M.Pct90, S.Pct90); 277 M.Pct99 = std::max(M.Pct99, S.Pct99); 278 M.Max = std::max(M.Max, S.Max); 279 M.Sum = std::max(M.Sum, S.Sum); 280 } 281 282 void GraphRenderer::calculateEdgeStatistics() { 283 assert(!G.edges().empty()); 284 for (auto &E : G.edges()) { 285 auto &A = E.second; 286 assert(!A.Timings.empty()); 287 getStats(A.Timings.begin(), A.Timings.end(), A.S); 288 updateMaxStats(A.S, G.GraphEdgeMax); 289 } 290 } 291 292 void GraphRenderer::calculateVertexStatistics() { 293 std::vector<uint64_t> TempTimings; 294 for (auto &V : G.vertices()) { 295 if (V.first != 0) { 296 for (auto &E : G.inEdges(V.first)) { 297 auto &A = E.second; 298 TempTimings.insert(TempTimings.end(), A.Timings.begin(), 299 A.Timings.end()); 300 } 301 getStats(TempTimings.begin(), TempTimings.end(), G[V.first].S); 302 updateMaxStats(G[V.first].S, G.GraphVertexMax); 303 TempTimings.clear(); 304 } 305 } 306 } 307 308 // A Helper function for normalizeStatistics which normalises a single 309 // TimeStat element. 310 static void normalizeTimeStat(GraphRenderer::TimeStat &S, 311 double CycleFrequency) { 312 int64_t OldCount = S.Count; 313 S = S / CycleFrequency; 314 S.Count = OldCount; 315 } 316 317 // Normalises the statistics in the graph for a given TSC frequency. 318 void GraphRenderer::normalizeStatistics(double CycleFrequency) { 319 for (auto &E : G.edges()) { 320 auto &S = E.second.S; 321 normalizeTimeStat(S, CycleFrequency); 322 } 323 for (auto &V : G.vertices()) { 324 auto &S = V.second.S; 325 normalizeTimeStat(S, CycleFrequency); 326 } 327 328 normalizeTimeStat(G.GraphEdgeMax, CycleFrequency); 329 normalizeTimeStat(G.GraphVertexMax, CycleFrequency); 330 } 331 332 // Returns a string containing the value of statistic field T 333 std::string 334 GraphRenderer::TimeStat::getString(GraphRenderer::StatType T) const { 335 std::string St; 336 raw_string_ostream S{St}; 337 double TimeStat::*DoubleStatPtrs[] = {&TimeStat::Min, &TimeStat::Median, 338 &TimeStat::Pct90, &TimeStat::Pct99, 339 &TimeStat::Max, &TimeStat::Sum}; 340 switch (T) { 341 case GraphRenderer::StatType::NONE: 342 break; 343 case GraphRenderer::StatType::COUNT: 344 S << Count; 345 break; 346 default: 347 S << (*this).* 348 DoubleStatPtrs[static_cast<int>(T) - 349 static_cast<int>(GraphRenderer::StatType::MIN)]; 350 break; 351 } 352 return S.str(); 353 } 354 355 // Returns the quotient between the property T of this and another TimeStat as 356 // a double 357 double GraphRenderer::TimeStat::getDouble(StatType T) const { 358 double retval = 0; 359 double TimeStat::*DoubleStatPtrs[] = {&TimeStat::Min, &TimeStat::Median, 360 &TimeStat::Pct90, &TimeStat::Pct99, 361 &TimeStat::Max, &TimeStat::Sum}; 362 switch (T) { 363 case GraphRenderer::StatType::NONE: 364 retval = 0.0; 365 break; 366 case GraphRenderer::StatType::COUNT: 367 retval = static_cast<double>(Count); 368 break; 369 default: 370 retval = 371 (*this).*DoubleStatPtrs[static_cast<int>(T) - 372 static_cast<int>(GraphRenderer::StatType::MIN)]; 373 break; 374 } 375 return retval; 376 } 377 378 // Outputs a DOT format version of the Graph embedded in the GraphRenderer 379 // object on OS. It does this in the expected way by itterating 380 // through all edges then vertices and then outputting them and their 381 // annotations. 382 // 383 // FIXME: output more information, better presented. 384 void GraphRenderer::exportGraphAsDOT(raw_ostream &OS, StatType ET, StatType EC, 385 StatType VT, StatType VC) { 386 OS << "digraph xray {\n"; 387 388 if (VT != StatType::NONE) 389 OS << "node [shape=record];\n"; 390 391 for (const auto &E : G.edges()) { 392 const auto &S = E.second.S; 393 OS << "F" << E.first.first << " -> " 394 << "F" << E.first.second << " [label=\"" << S.getString(ET) << "\""; 395 if (EC != StatType::NONE) 396 OS << " color=\"" 397 << CHelper.getColorString( 398 std::sqrt(S.getDouble(EC) / G.GraphEdgeMax.getDouble(EC))) 399 << "\""; 400 OS << "];\n"; 401 } 402 403 for (const auto &V : G.vertices()) { 404 const auto &VA = V.second; 405 if (V.first == 0) 406 continue; 407 OS << "F" << V.first << " [label=\"" << (VT != StatType::NONE ? "{" : "") 408 << (VA.SymbolName.size() > 40 ? VA.SymbolName.substr(0, 40) + "..." 409 : VA.SymbolName); 410 if (VT != StatType::NONE) 411 OS << "|" << VA.S.getString(VT) << "}\""; 412 else 413 OS << "\""; 414 if (VC != StatType::NONE) 415 OS << " color=\"" 416 << CHelper.getColorString( 417 std::sqrt(VA.S.getDouble(VC) / G.GraphVertexMax.getDouble(VC))) 418 << "\""; 419 OS << "];\n"; 420 } 421 OS << "}\n"; 422 } 423 424 Expected<GraphRenderer> GraphRenderer::Factory::getGraphRenderer() { 425 InstrumentationMap Map; 426 if (!GraphInstrMap.empty()) { 427 auto InstrumentationMapOrError = loadInstrumentationMap(GraphInstrMap); 428 if (!InstrumentationMapOrError) 429 return joinErrors( 430 make_error<StringError>( 431 Twine("Cannot open instrumentation map '") + GraphInstrMap + "'", 432 std::make_error_code(std::errc::invalid_argument)), 433 InstrumentationMapOrError.takeError()); 434 Map = std::move(*InstrumentationMapOrError); 435 } 436 437 const auto &FunctionAddresses = Map.getFunctionAddresses(); 438 439 symbolize::LLVMSymbolizer Symbolizer; 440 const auto &Header = Trace.getFileHeader(); 441 442 llvm::xray::FuncIdConversionHelper FuncIdHelper(InstrMap, Symbolizer, 443 FunctionAddresses); 444 445 xray::GraphRenderer GR(FuncIdHelper, DeduceSiblingCalls); 446 for (const auto &Record : Trace) { 447 auto E = GR.accountRecord(Record); 448 if (!E) 449 continue; 450 451 for (const auto &ThreadStack : GR.getPerThreadFunctionStack()) { 452 errs() << "Thread ID: " << ThreadStack.first << "\n"; 453 auto Level = ThreadStack.second.size(); 454 for (const auto &Entry : llvm::reverse(ThreadStack.second)) 455 errs() << "#" << Level-- << "\t" 456 << FuncIdHelper.SymbolOrNumber(Entry.FuncId) << '\n'; 457 } 458 459 if (!GraphKeepGoing) 460 return joinErrors(make_error<StringError>( 461 "Error encountered generating the call graph.", 462 std::make_error_code(std::errc::invalid_argument)), 463 std::move(E)); 464 465 handleAllErrors(std::move(E), 466 [&](const ErrorInfoBase &E) { E.log(errs()); }); 467 } 468 469 GR.G.GraphEdgeMax = {}; 470 GR.G.GraphVertexMax = {}; 471 GR.calculateEdgeStatistics(); 472 GR.calculateVertexStatistics(); 473 474 if (Header.CycleFrequency) 475 GR.normalizeStatistics(Header.CycleFrequency); 476 477 return GR; 478 } 479 480 // Here we register and implement the llvm-xray graph subcommand. 481 // The bulk of this code reads in the options, opens the required files, uses 482 // those files to create a context for analysing the xray trace, then there is a 483 // short loop which actually analyses the trace, generates the graph and then 484 // outputs it as a DOT. 485 // 486 // FIXME: include additional filtering and annalysis passes to provide more 487 // specific useful information. 488 static CommandRegistration Unused(&GraphC, []() -> Error { 489 GraphRenderer::Factory F; 490 491 F.KeepGoing = GraphKeepGoing; 492 F.DeduceSiblingCalls = GraphDeduceSiblingCalls; 493 F.InstrMap = GraphInstrMap; 494 495 auto TraceOrErr = loadTraceFile(GraphInput, true); 496 497 if (!TraceOrErr) 498 return make_error<StringError>( 499 Twine("Failed loading input file '") + GraphInput + "'", 500 make_error_code(llvm::errc::invalid_argument)); 501 502 F.Trace = std::move(*TraceOrErr); 503 auto GROrError = F.getGraphRenderer(); 504 if (!GROrError) 505 return GROrError.takeError(); 506 auto &GR = *GROrError; 507 508 std::error_code EC; 509 raw_fd_ostream OS(GraphOutput, EC, sys::fs::OpenFlags::F_Text); 510 if (EC) 511 return make_error<StringError>( 512 Twine("Cannot open file '") + GraphOutput + "' for writing.", EC); 513 514 GR.exportGraphAsDOT(OS, GraphEdgeLabel, GraphEdgeColorType, GraphVertexLabel, 515 GraphVertexColorType); 516 return Error::success(); 517 }); 518