1=================== 2Debugging with XRay 3=================== 4 5This document shows an example of how you would go about analyzing applications 6built with XRay instrumentation. Here we will attempt to debug ``llc`` 7compiling some sample LLVM IR generated by Clang. 8 9.. contents:: 10 :local: 11 12Building with XRay 13------------------ 14 15To debug an application with XRay instrumentation, we need to build it with a 16Clang that supports the ``-fxray-instrument`` option. See `XRay <XRay.html>`_ 17for more technical details of how XRay works for background information. 18 19In our example, we need to add ``-fxray-instrument`` to the list of flags 20passed to Clang when building a binary. Note that we need to link with Clang as 21well to get the XRay runtime linked in appropriately. For building ``llc`` with 22XRay, we do something similar below for our LLVM build: 23 24:: 25 26 $ mkdir -p llvm-build && cd llvm-build 27 # Assume that the LLVM sources are at ../llvm 28 $ cmake -GNinja ../llvm -DCMAKE_BUILD_TYPE=Release \ 29 -DCMAKE_C_FLAGS_RELEASE="-fxray-instrument" -DCMAKE_CXX_FLAGS="-fxray-instrument" \ 30 # Once this finishes, we should build llc 31 $ ninja llc 32 33 34To verify that we have an XRay instrumented binary, we can use ``objdump`` to 35look for the ``xray_instr_map`` section. 36 37:: 38 39 $ objdump -h -j xray_instr_map ./bin/llc 40 ./bin/llc: file format elf64-x86-64 41 42 Sections: 43 Idx Name Size VMA LMA File off Algn 44 14 xray_instr_map 00002fc0 00000000041516c6 00000000041516c6 03d516c6 2**0 45 CONTENTS, ALLOC, LOAD, READONLY, DATA 46 47Getting Traces 48-------------- 49 50By default, XRay does not write out the trace files or patch the application 51before main starts. If we run ``llc`` it should work like a normally built 52binary. If we want to get a full trace of the application's operations (of the 53functions we do end up instrumenting with XRay) then we need to enable XRay 54at application start. To do this, XRay checks the ``XRAY_OPTIONS`` environment 55variable. 56 57:: 58 59 # The following doesn't create an XRay trace by default. 60 $ ./bin/llc input.ll 61 62 # We need to set the XRAY_OPTIONS to enable some features. 63 $ XRAY_OPTIONS="patch_premain=true xray_mode=xray-basic verbosity=1" ./bin/llc input.ll 64 ==69819==XRay: Log file in 'xray-log.llc.m35qPB' 65 66At this point we now have an XRay trace we can start analysing. 67 68The ``llvm-xray`` Tool 69---------------------- 70 71Having a trace then allows us to do basic accounting of the functions that were 72instrumented, and how much time we're spending in parts of the code. To make 73sense of this data, we use the ``llvm-xray`` tool which has a few subcommands 74to help us understand our trace. 75 76One of the things we can do is to get an accounting of the functions that have 77been instrumented. We can see an example accounting with ``llvm-xray account``: 78 79:: 80 81 $ llvm-xray account xray-log.llc.m35qPB --top=10 --sort=sum --sortorder=dsc --instr_map=./bin/llc 82 Functions with latencies: 29 83 funcid count [ min, med, 90p, 99p, max] sum function 84 187 360 [ 0.000000, 0.000001, 0.000014, 0.000032, 0.000075] 0.001596 LLLexer.cpp:446:0: llvm::LLLexer::LexIdentifier() 85 85 130 [ 0.000000, 0.000000, 0.000018, 0.000023, 0.000156] 0.000799 X86ISelDAGToDAG.cpp:1984:0: (anonymous namespace)::X86DAGToDAGISel::Select(llvm::SDNode*) 86 138 130 [ 0.000000, 0.000000, 0.000017, 0.000155, 0.000155] 0.000774 SelectionDAGISel.cpp:2963:0: llvm::SelectionDAGISel::SelectCodeCommon(llvm::SDNode*, unsigned char const*, unsigned int) 87 188 103 [ 0.000000, 0.000000, 0.000003, 0.000123, 0.000214] 0.000737 LLParser.cpp:2692:0: llvm::LLParser::ParseValID(llvm::ValID&, llvm::LLParser::PerFunctionState*) 88 88 1 [ 0.000562, 0.000562, 0.000562, 0.000562, 0.000562] 0.000562 X86ISelLowering.cpp:83:0: llvm::X86TargetLowering::X86TargetLowering(llvm::X86TargetMachine const&, llvm::X86Subtarget const&) 89 125 102 [ 0.000001, 0.000003, 0.000010, 0.000017, 0.000049] 0.000471 Verifier.cpp:3714:0: (anonymous namespace)::Verifier::visitInstruction(llvm::Instruction&) 90 90 8 [ 0.000023, 0.000035, 0.000106, 0.000106, 0.000106] 0.000342 X86ISelLowering.cpp:3363:0: llvm::X86TargetLowering::LowerCall(llvm::TargetLowering::CallLoweringInfo&, llvm::SmallVectorImpl<llvm::SDValue>&) const 91 124 32 [ 0.000003, 0.000007, 0.000016, 0.000041, 0.000041] 0.000310 Verifier.cpp:1967:0: (anonymous namespace)::Verifier::visitFunction(llvm::Function const&) 92 123 1 [ 0.000302, 0.000302, 0.000302, 0.000302, 0.000302] 0.000302 LLVMContextImpl.cpp:54:0: llvm::LLVMContextImpl::~LLVMContextImpl() 93 139 46 [ 0.000000, 0.000002, 0.000006, 0.000008, 0.000019] 0.000138 TargetLowering.cpp:506:0: llvm::TargetLowering::SimplifyDemandedBits(llvm::SDValue, llvm::APInt const&, llvm::APInt&, llvm::APInt&, llvm::TargetLowering::TargetLoweringOpt&, unsigned int, bool) const 94 95This shows us that for our input file, ``llc`` spent the most cumulative time 96in the lexer (a total of 1 millisecond). If we wanted for example to work with 97this data in a spreadsheet, we can output the results as CSV using the 98``-format=csv`` option to the command for further analysis. 99 100If we want to get a textual representation of the raw trace we can use the 101``llvm-xray convert`` tool to get YAML output. The first few lines of that 102output for an example trace would look like the following: 103 104:: 105 106 $ llvm-xray convert -f yaml --symbolize --instr_map=./bin/llc xray-log.llc.m35qPB 107 --- 108 header: 109 version: 1 110 type: 0 111 constant-tsc: true 112 nonstop-tsc: true 113 cycle-frequency: 2601000000 114 records: 115 - { type: 0, func-id: 110, function: __cxx_global_var_init.8, cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426023268520 } 116 - { type: 0, func-id: 110, function: __cxx_global_var_init.8, cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426023523052 } 117 - { type: 0, func-id: 164, function: __cxx_global_var_init, cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426029925386 } 118 - { type: 0, func-id: 164, function: __cxx_global_var_init, cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426030031128 } 119 - { type: 0, func-id: 142, function: '(anonymous namespace)::CommandLineParser::ParseCommandLineOptions(int, char const* const*, llvm::StringRef, llvm::raw_ostream*)', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426046951388 } 120 - { type: 0, func-id: 142, function: '(anonymous namespace)::CommandLineParser::ParseCommandLineOptions(int, char const* const*, llvm::StringRef, llvm::raw_ostream*)', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426047282020 } 121 - { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426047857332 } 122 - { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426047984152 } 123 - { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426048036584 } 124 - { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426048042292 } 125 - { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426048055056 } 126 - { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426048067316 } 127 128Controlling Fidelity 129-------------------- 130 131So far in our examples, we haven't been getting full coverage of the functions 132we have in the binary. To get that, we need to modify the compiler flags so 133that we can instrument more (if not all) the functions we have in the binary. 134We have two options for doing that, and we explore both of these below. 135 136Instruction Threshold 137````````````````````` 138 139The first "blunt" way of doing this is by setting the minimum threshold for 140function bodies to 1. We can do that with the 141``-fxray-instruction-threshold=N`` flag when building our binary. We rebuild 142``llc`` with this option and observe the results: 143 144:: 145 146 $ rm CMakeCache.txt 147 $ cmake -GNinja ../llvm -DCMAKE_BUILD_TYPE=Release \ 148 -DCMAKE_C_FLAGS_RELEASE="-fxray-instrument -fxray-instruction-threshold=1" \ 149 -DCMAKE_CXX_FLAGS="-fxray-instrument -fxray-instruction-threshold=1" 150 $ ninja llc 151 $ XRAY_OPTIONS="patch_premain=true" ./bin/llc input.ll 152 ==69819==XRay: Log file in 'xray-log.llc.5rqxkU' 153 154 $ llvm-xray account xray-log.llc.5rqxkU --top=10 --sort=sum --sortorder=dsc --instr_map=./bin/llc 155 Functions with latencies: 36652 156 funcid count [ min, med, 90p, 99p, max] sum function 157 75 1 [ 0.672368, 0.672368, 0.672368, 0.672368, 0.672368] 0.672368 llc.cpp:271:0: main 158 78 1 [ 0.626455, 0.626455, 0.626455, 0.626455, 0.626455] 0.626455 llc.cpp:381:0: compileModule(char**, llvm::LLVMContext&) 159 139617 1 [ 0.472618, 0.472618, 0.472618, 0.472618, 0.472618] 0.472618 LegacyPassManager.cpp:1723:0: llvm::legacy::PassManager::run(llvm::Module&) 160 139610 1 [ 0.472618, 0.472618, 0.472618, 0.472618, 0.472618] 0.472618 LegacyPassManager.cpp:1681:0: llvm::legacy::PassManagerImpl::run(llvm::Module&) 161 139612 1 [ 0.470948, 0.470948, 0.470948, 0.470948, 0.470948] 0.470948 LegacyPassManager.cpp:1564:0: (anonymous namespace)::MPPassManager::runOnModule(llvm::Module&) 162 139607 2 [ 0.147345, 0.315994, 0.315994, 0.315994, 0.315994] 0.463340 LegacyPassManager.cpp:1530:0: llvm::FPPassManager::runOnModule(llvm::Module&) 163 139605 21 [ 0.000002, 0.000002, 0.102593, 0.213336, 0.213336] 0.463331 LegacyPassManager.cpp:1491:0: llvm::FPPassManager::runOnFunction(llvm::Function&) 164 139563 26096 [ 0.000002, 0.000002, 0.000037, 0.000063, 0.000215] 0.225708 LegacyPassManager.cpp:1083:0: llvm::PMDataManager::findAnalysisPass(void const*, bool) 165 108055 188 [ 0.000002, 0.000120, 0.001375, 0.004523, 0.062624] 0.159279 MachineFunctionPass.cpp:38:0: llvm::MachineFunctionPass::runOnFunction(llvm::Function&) 166 62635 22 [ 0.000041, 0.000046, 0.000050, 0.126744, 0.126744] 0.127715 X86TargetMachine.cpp:242:0: llvm::X86TargetMachine::getSubtargetImpl(llvm::Function const&) const 167 168 169Instrumentation Attributes 170`````````````````````````` 171 172The other way is to use configuration files for selecting which functions 173should always be instrumented by the compiler. This gives us a way of ensuring 174that certain functions are either always or never instrumented by not having to 175add the attribute to the source. 176 177To use this feature, you can define one file for the functions to always 178instrument, and another for functions to never instrument. The format of these 179files are exactly the same as the SanitizerLists files that control similar 180things for the sanitizer implementations. For example: 181 182:: 183 184 # xray-attr-list.txt 185 # always instrument functions that match the following filters: 186 [always] 187 fun:main 188 189 # never instrument functions that match the following filters: 190 [never] 191 fun:__cxx_* 192 193Given the file above we can re-build by providing it to the 194``-fxray-attr-list=`` flag to clang. You can have multiple files, each defining 195different sets of attribute sets, to be combined into a single list by clang. 196 197The XRay stack tool 198------------------- 199 200Given a trace, and optionally an instrumentation map, the ``llvm-xray stack`` 201command can be used to analyze a call stack graph constructed from the function 202call timeline. 203 204The way to use the command is to output the top stacks by call count and time spent. 205 206:: 207 208 $ llvm-xray stack xray-log.llc.5rqxkU --instr_map=./bin/llc 209 210 Unique Stacks: 3069 211 Top 10 Stacks by leaf sum: 212 213 Sum: 9633790 214 lvl function count sum 215 #0 main 1 58421550 216 #1 compileModule(char**, llvm::LLVMContext&) 1 51440360 217 #2 llvm::legacy::PassManagerImpl::run(llvm::Module&) 1 40535375 218 #3 llvm::FPPassManager::runOnModule(llvm::Module&) 2 39337525 219 #4 llvm::FPPassManager::runOnFunction(llvm::Function&) 6 39331465 220 #5 llvm::PMDataManager::verifyPreservedAnalysis(llvm::Pass*) 399 16628590 221 #6 llvm::PMTopLevelManager::findAnalysisPass(void const*) 4584 15155600 222 #7 llvm::PMDataManager::findAnalysisPass(void const*, bool) 32088 9633790 223 224 ..etc.. 225 226In the default mode, identical stacks on different threads are independently 227aggregated. In a multithreaded program, you may end up having identical call 228stacks fill your list of top calls. 229 230To address this, you may specify the ``--aggregate-threads`` or 231``--per-thread-stacks`` flags. ``--per-thread-stacks`` treats the thread id as an 232implicit root in each call stack tree, while ``--aggregate-threads`` combines 233identical stacks from all threads. 234 235Flame Graph Generation 236---------------------- 237 238The ``llvm-xray stack`` tool may also be used to generate flamegraphs for 239visualizing your instrumented invocations. The tool does not generate the graphs 240themselves, but instead generates a format that can be used with Brendan Gregg's 241FlameGraph tool, currently available on `github 242<https://github.com/brendangregg/FlameGraph>`_. 243 244To generate output for a flamegraph, a few more options are necessary. 245 246- ``--all-stacks`` - Emits all of the stacks. 247- ``--stack-format`` - Choose the flamegraph output format 'flame'. 248- ``--aggregation-type`` - Choose the metric to graph. 249 250You may pipe the command output directly to the flamegraph tool to obtain an 251svg file. 252 253:: 254 255 $ llvm-xray stack xray-log.llc.5rqxkU --instr_map=./bin/llc --stack-format=flame --aggregation-type=time --all-stacks | \ 256 /path/to/FlameGraph/flamegraph.pl > flamegraph.svg 257 258If you open the svg in a browser, mouse events allow exploring the call stacks. 259 260Chrome Trace Viewer Visualization 261--------------------------------- 262 263We can also generate a trace which can be loaded by the Chrome Trace Viewer 264from the same generated trace: 265 266:: 267 268 $ llvm-xray convert --symbolize --instr_map=./bin/llc \ 269 --output-format=trace_event xray-log.llc.5rqxkU \ 270 | gzip > llc-trace.txt.gz 271 272From a Chrome browser, navigating to ``chrome:///tracing`` allows us to load 273the ``sample-trace.txt.gz`` file to visualize the execution trace. 274 275Further Exploration 276------------------- 277 278The ``llvm-xray`` tool has a few other subcommands that are in various stages 279of being developed. One interesting subcommand that can highlight a few 280interesting things is the ``graph`` subcommand. Given for example the following 281toy program that we build with XRay instrumentation, we can see how the 282generated graph may be a helpful indicator of where time is being spent for the 283application. 284 285.. code-block:: c++ 286 287 // sample.cc 288 #include <iostream> 289 #include <thread> 290 291 [[clang::xray_always_instrument]] void f() { 292 std::cerr << '.'; 293 } 294 295 [[clang::xray_always_instrument]] void g() { 296 for (int i = 0; i < 1 << 10; ++i) { 297 std::cerr << '-'; 298 } 299 } 300 301 int main(int argc, char* argv[]) { 302 std::thread t1([] { 303 for (int i = 0; i < 1 << 10; ++i) 304 f(); 305 }); 306 std::thread t2([] { 307 g(); 308 }); 309 t1.join(); 310 t2.join(); 311 std::cerr << '\n'; 312 } 313 314We then build the above with XRay instrumentation: 315 316:: 317 318 $ clang++ -o sample -O3 sample.cc -std=c++11 -fxray-instrument -fxray-instruction-threshold=1 319 $ XRAY_OPTIONS="patch_premain=true xray_mode=xray-basic" ./sample 320 321We can then explore the graph rendering of the trace generated by this sample 322application. We assume you have the graphviz tools available in your system, 323including both ``unflatten`` and ``dot``. If you prefer rendering or exploring 324the graph using another tool, then that should be feasible as well. ``llvm-xray 325graph`` will create DOT format graphs which should be usable in most graph 326rendering applications. One example invocation of the ``llvm-xray graph`` 327command should yield some interesting insights to the workings of C++ 328applications: 329 330:: 331 332 $ llvm-xray graph xray-log.sample.* -m sample --color-edges=sum --edge-label=sum \ 333 | unflatten -f -l10 | dot -Tsvg -o sample.svg 334 335 336Next Steps 337---------- 338 339If you have some interesting analyses you'd like to implement as part of the 340llvm-xray tool, please feel free to propose them on the llvm-dev@ mailing list. 341The following are some ideas to inspire you in getting involved and potentially 342making things better. 343 344 - Implement a query/filtering library that allows for finding patterns in the 345 XRay traces. 346 - Collecting function call stacks and how often they're encountered in the 347 XRay trace. 348
