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