348 lines · plain
1===================2Debugging with XRay3===================4 5This document shows an example of how you would go about analyzing applications6built 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 XRay13------------------14 15To debug an application with XRay instrumentation, we need to build it with a16Clang 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 flags20passed to Clang when building a binary. Note that we need to link with Clang as21well to get the XRay runtime linked in appropriately. For building ``llc`` with22XRay, we do something similar below for our LLVM build:23 24::25 26 $ mkdir -p llvm-build && cd llvm-build27 # Assume that the LLVM sources are at ../llvm28 $ 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 llc31 $ ninja llc32 33 34To verify that we have an XRay instrumented binary, we can use ``objdump`` to35look for the ``xray_instr_map`` section.36 37::38 39 $ objdump -h -j xray_instr_map ./bin/llc40 ./bin/llc: file format elf64-x86-6441 42 Sections:43 Idx Name Size VMA LMA File off Algn44 14 xray_instr_map 00002fc0 00000000041516c6 00000000041516c6 03d516c6 2**045 CONTENTS, ALLOC, LOAD, READONLY, DATA46 47Getting Traces48--------------49 50By default, XRay does not write out the trace files or patch the application51before main starts. If we run ``llc`` it should work like a normally built52binary. If we want to get a full trace of the application's operations (of the53functions we do end up instrumenting with XRay) then we need to enable XRay54at application start. To do this, XRay checks the ``XRAY_OPTIONS`` environment55variable.56 57::58 59 # The following doesn't create an XRay trace by default.60 $ ./bin/llc input.ll61 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.ll64 ==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`` Tool69----------------------70 71Having a trace then allows us to do basic accounting of the functions that were72instrumented, and how much time we're spending in parts of the code. To make73sense of this data, we use the ``llvm-xray`` tool which has a few subcommands74to help us understand our trace.75 76One of the things we can do is to get an accounting of the functions that have77been 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/llc82 Functions with latencies: 2983 funcid count [ min, med, 90p, 99p, max] sum function84 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>&) const91 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) const94 95This shows us that for our input file, ``llc`` spent the most cumulative time96in the lexer (a total of 1 millisecond). If we wanted for example to work with97this data in a spreadsheet, we can output the results as CSV using the98``-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 the101``llvm-xray convert`` tool to get YAML output. The first few lines of that102output 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.m35qPB107 ---108 header:109 version: 1110 type: 0111 constant-tsc: true112 nonstop-tsc: true113 cycle-frequency: 2601000000114 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 Fidelity129--------------------130 131So far in our examples, we haven't been getting full coverage of the functions132we have in the binary. To get that, we need to modify the compiler flags so133that 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 Threshold137`````````````````````138 139The first "blunt" way of doing this is by setting the minimum threshold for140function bodies to 1. We can do that with the141``-fxray-instruction-threshold=N`` flag when building our binary. We rebuild142``llc`` with this option and observe the results:143 144::145 146 $ rm CMakeCache.txt147 $ 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 llc151 $ XRAY_OPTIONS="patch_premain=true" ./bin/llc input.ll152 ==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/llc155 Functions with latencies: 36652156 funcid count [ min, med, 90p, 99p, max] sum function157 75 1 [ 0.672368, 0.672368, 0.672368, 0.672368, 0.672368] 0.672368 llc.cpp:271:0: main158 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&) const167 168 169Instrumentation Attributes170``````````````````````````171 172The other way is to use configuration files for selecting which functions173should always be instrumented by the compiler. This gives us a way of ensuring174that certain functions are either always or never instrumented by not having to175add the attribute to the source.176 177To use this feature, you can define one file for the functions to always178instrument, and another for functions to never instrument. The format of these179files are exactly the same as the SanitizerLists files that control similar180things for the sanitizer implementations. For example:181 182::183 184 # xray-attr-list.txt185 # always instrument functions that match the following filters:186 [always]187 fun:main188 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 the194``-fxray-attr-list=`` flag to clang. You can have multiple files, each defining195different sets of attribute sets, to be combined into a single list by clang.196 197The XRay stack tool198-------------------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 function202call 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/llc209 210 Unique Stacks: 3069211 Top 10 Stacks by leaf sum:212 213 Sum: 9633790214 lvl function count sum215 #0 main 1 58421550216 #1 compileModule(char**, llvm::LLVMContext&) 1 51440360217 #2 llvm::legacy::PassManagerImpl::run(llvm::Module&) 1 40535375218 #3 llvm::FPPassManager::runOnModule(llvm::Module&) 2 39337525219 #4 llvm::FPPassManager::runOnFunction(llvm::Function&) 6 39331465220 #5 llvm::PMDataManager::verifyPreservedAnalysis(llvm::Pass*) 399 16628590221 #6 llvm::PMTopLevelManager::findAnalysisPass(void const*) 4584 15155600222 #7 llvm::PMDataManager::findAnalysisPass(void const*, bool) 32088 9633790223 224 ..etc..225 226In the default mode, identical stacks on different threads are independently227aggregated. In a multithreaded program, you may end up having identical call228stacks fill your list of top calls.229 230To address this, you may specify the ``--aggregate-threads`` or231``--per-thread-stacks`` flags. ``--per-thread-stacks`` treats the thread id as an232implicit root in each call stack tree, while ``--aggregate-threads`` combines233identical stacks from all threads.234 235Flame Graph Generation236----------------------237 238The ``llvm-xray stack`` tool may also be used to generate flamegraphs for239visualizing your instrumented invocations. The tool does not generate the graphs240themselves, but instead generates a format that can be used with Brendan Gregg's241FlameGraph tool, currently available on `github242<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 an251svg 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.svg257 258If you open the svg in a browser, mouse events allow exploring the call stacks.259 260Chrome Trace Viewer Visualization261---------------------------------262 263We can also generate a trace which can be loaded by the Chrome Trace Viewer264from 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.gz271 272From a Chrome browser, navigating to ``chrome:///tracing`` allows us to load273the ``sample-trace.txt.gz`` file to visualize the execution trace.274 275Further Exploration276-------------------277 278The ``llvm-xray`` tool has a few other subcommands that are in various stages279of being developed. One interesting subcommand that can highlight a few280interesting things is the ``graph`` subcommand. Given for example the following281toy program that we build with XRay instrumentation, we can see how the282generated graph may be a helpful indicator of where time is being spent for the283application.284 285.. code-block:: c++286 287 // sample.cc288 #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=1319 $ XRAY_OPTIONS="patch_premain=true xray_mode=xray-basic" ./sample320 321We can then explore the graph rendering of the trace generated by this sample322application. We assume you have the graphviz tools available in your system,323including both ``unflatten`` and ``dot``. If you prefer rendering or exploring324the graph using another tool, then that should be feasible as well. ``llvm-xray325graph`` will create DOT format graphs which should be usable in most graph326rendering 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.svg334 335 336Next Steps337----------338 339If you have some interesting analyses you'd like to implement as part of the340llvm-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 potentially342making things better.343 344 - Implement a query/filtering library that allows for finding patterns in the345 XRay traces.346 - Collecting function call stacks and how often they're encountered in the347 XRay trace.348