docs/XRayExample.rst

   1 ===================
   2 Debugging with XRay
   3 ===================
   4
   5 This document shows an example of how you would go about analyzing applications
   6 built with XRay instrumentation. Here we will attempt to debug ``llc``
   7 compiling some sample LLVM IR generated by Clang.
   8
   9 .. contents::
  10   :local:
  11
  12 Building with XRay
  13 ------------------
  14
  15 To debug an application with XRay instrumentation, we need to build it with a
  16 Clang that supports the ``-fxray-instrument`` option. See `XRay <XRay.html>`_
  17 for more technical details of how XRay works for background information.
  18
  19 In our example, we need to add ``-fxray-instrument`` to the list of flags
  20 passed to Clang when building a binary. Note that we need to link with Clang as
  21 well to get the XRay runtime linked in appropriately. For building ``llc`` with
  22 XRay, 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
  34 To verify that we have an XRay instrumented binary, we can use ``objdump`` to
  35 look 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
  47 Getting Traces
  48 --------------
  49
  50 By default, XRay does not write out the trace files or patch the application
  51 before main starts. If we just run ``llc`` it should just work like a normally
  52 built binary. However, if we want to get a full trace of the application's
  53 operations (of the functions we do end up instrumenting with XRay) then we need
  54 to enable XRay at application start. To do this, XRay checks the
  55 ``XRAY_OPTIONS`` environment variable.
  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" ./bin/llc input.ll
  64   ==69819==XRay: Log file in 'xray-log.llc.m35qPB'
  65
  66 At this point we now have an XRay trace we can start analysing.
  67
  68 The ``llvm-xray`` Tool
  69 ----------------------
  70
  71 Having a trace then allows us to do basic accounting of the functions that were
  72 instrumented, and how much time we're spending in parts of the code. To make
  73 sense of this data, we use the ``llvm-xray`` tool which has a few subcommands
  74 to help us understand our trace.
  75
  76 One of the simplest things we can do is to get an accounting of the functions
  77 that have been instrumented. We can see an example accounting with ``llvm-xray
  78 account``:
  79
  80 ::
  81
  82   $ llvm-xray account xray-log.llc.m35qPB -top=10 -sort=sum -sortorder=dsc -instr_map ./bin/llc
  83   Functions with latencies: 29
  84      funcid      count [      min,       med,       90p,       99p,       max]       sum  function
  85         187        360 [ 0.000000,  0.000001,  0.000014,  0.000032,  0.000075]  0.001596  LLLexer.cpp:446:0: llvm::LLLexer::LexIdentifier()
  86          85        130 [ 0.000000,  0.000000,  0.000018,  0.000023,  0.000156]  0.000799  X86ISelDAGToDAG.cpp:1984:0: (anonymous namespace)::X86DAGToDAGISel::Select(llvm::SDNode*)
  87         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)
  88         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*)
  89          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&)
  90         125        102 [ 0.000001,  0.000003,  0.000010,  0.000017,  0.000049]  0.000471  Verifier.cpp:3714:0: (anonymous namespace)::Verifier::visitInstruction(llvm::Instruction&)
  91          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
  92         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&)
  93         123          1 [ 0.000302,  0.000302,  0.000302,  0.000302,  0.000302]  0.000302  LLVMContextImpl.cpp:54:0: llvm::LLVMContextImpl::~LLVMContextImpl()
  94         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
  95
  96 This shows us that for our input file, ``llc`` spent the most cumulative time
  97 in the lexer (a total of 1 millisecond). If we wanted for example to work with
  98 this data in a spreadsheet, we can output the results as CSV using the
  99 ``-format=csv`` option to the command for further analysis.
 100
 101 If we want to get a textual representation of the raw trace we can use the
 102 ``llvm-xray convert`` tool to get YAML output. The first few lines of that
 103 output for an example trace would look like the following:
 104
 105 ::
 106
 107   $ llvm-xray convert -f yaml -symbolize -instr_map=./bin/llc xray-log.llc.m35qPB
 108   ---
 109   header:
 110     version:         1
 111     type:            0
 112     constant-tsc:    true
 113     nonstop-tsc:     true
 114     cycle-frequency: 2601000000
 115   records:
 116     - { type: 0, func-id: 110, function: __cxx_global_var_init.8, cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426023268520 }
 117     - { type: 0, func-id: 110, function: __cxx_global_var_init.8, cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426023523052 }
 118     - { type: 0, func-id: 164, function: __cxx_global_var_init, cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426029925386 }
 119     - { type: 0, func-id: 164, function: __cxx_global_var_init, cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426030031128 }
 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-enter, tsc: 5434426046951388 }
 121     - { 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 }
 122     - { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426047857332 }
 123     - { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426047984152 }
 124     - { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426048036584 }
 125     - { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426048042292 }
 126     - { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426048055056 }
 127     - { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426048067316 }
 128
 129 Controlling Fidelity
 130 --------------------
 131
 132 So far in our examples, we haven't been getting full coverage of the functions
 133 we have in the binary. To get that, we need to modify the compiler flags so
 134 that we can instrument more (if not all) the functions we have in the binary.
 135 We have two options for doing that, and we explore both of these below.
 136
 137 Instruction Threshold
 138 `````````````````````
 139
 140 The first "blunt" way of doing this is by setting the minimum threshold for
 141 function bodies to 1. We can do that with the
 142 ``-fxray-instruction-threshold=N`` flag when building our binary. We rebuild
 143 ``llc`` with this option and observe the results:
 144
 145 ::
 146
 147   $ rm CMakeCache.txt
 148   $ cmake -GNinja ../llvm -DCMAKE_BUILD_TYPE=Release \
 149       -DCMAKE_C_FLAGS_RELEASE="-fxray-instrument -fxray-instruction-threshold=1" \
 150       -DCMAKE_CXX_FLAGS="-fxray-instrument -fxray-instruction-threshold=1"
 151   $ ninja llc
 152   $ XRAY_OPTIONS="patch_premain=true" ./bin/llc input.ll
 153   ==69819==XRay: Log file in 'xray-log.llc.5rqxkU'
 154
 155   $ llvm-xray account xray-log.llc.5rqxkU -top=10 -sort=sum -sortorder=dsc -instr_map ./bin/llc
 156   Functions with latencies: 36652
 157    funcid      count [      min,       med,       90p,       99p,       max]       sum  function
 158        75          1 [ 0.672368,  0.672368,  0.672368,  0.672368,  0.672368]  0.672368  llc.cpp:271:0: main
 159        78          1 [ 0.626455,  0.626455,  0.626455,  0.626455,  0.626455]  0.626455  llc.cpp:381:0: compileModule(char**, llvm::LLVMContext&)
 160    139617          1 [ 0.472618,  0.472618,  0.472618,  0.472618,  0.472618]  0.472618  LegacyPassManager.cpp:1723:0: llvm::legacy::PassManager::run(llvm::Module&)
 161    139610          1 [ 0.472618,  0.472618,  0.472618,  0.472618,  0.472618]  0.472618  LegacyPassManager.cpp:1681:0: llvm::legacy::PassManagerImpl::run(llvm::Module&)
 162    139612          1 [ 0.470948,  0.470948,  0.470948,  0.470948,  0.470948]  0.470948  LegacyPassManager.cpp:1564:0: (anonymous namespace)::MPPassManager::runOnModule(llvm::Module&)
 163    139607          2 [ 0.147345,  0.315994,  0.315994,  0.315994,  0.315994]  0.463340  LegacyPassManager.cpp:1530:0: llvm::FPPassManager::runOnModule(llvm::Module&)
 164    139605         21 [ 0.000002,  0.000002,  0.102593,  0.213336,  0.213336]  0.463331  LegacyPassManager.cpp:1491:0: llvm::FPPassManager::runOnFunction(llvm::Function&)
 165    139563      26096 [ 0.000002,  0.000002,  0.000037,  0.000063,  0.000215]  0.225708  LegacyPassManager.cpp:1083:0: llvm::PMDataManager::findAnalysisPass(void const*, bool)
 166    108055        188 [ 0.000002,  0.000120,  0.001375,  0.004523,  0.062624]  0.159279  MachineFunctionPass.cpp:38:0: llvm::MachineFunctionPass::runOnFunction(llvm::Function&)
 167     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
 168
 169
 170 Instrumentation Attributes
 171 ``````````````````````````
 172
 173 The other way is to use configuration files for selecting which functions
 174 should always be instrumented by the compiler. This gives us a way of ensuring
 175 that certain functions are either always or never instrumented by not having to
 176 add the attribute to the source.
 177
 178 To use this feature, you can define one file for the functions to always
 179 instrument, and another for functions to never instrument. The format of these
 180 files are exactly the same as the SanitizerLists files that control similar
 181 things for the sanitizer implementations. For example, we can have two
 182 different files like below:
 183
 184 ::
 185
 186   # always-instrument.txt
 187   # always instrument functions that match the following filters:
 188   fun:main
 189
 190   # never-instrument.txt
 191   # never instrument functions that match the following filters:
 192   fun:__cxx_*
 193
 194 Given the above two files we can re-build by providing those two files as
 195 arguments to clang as ``-fxray-always-instrument=always-instrument.txt`` or
 196 ``-fxray-never-instrument=never-instrument.txt``.
 197
 198 Further Exploration
 199 -------------------
 200
 201 The ``llvm-xray`` tool has a few other subcommands that are in various stages
 202 of being developed. One interesting subcommand that can highlight a few
 203 interesting things is the ``graph`` subcommand. Given for example the following
 204 toy program that we build with XRay instrumentation, we can see how the
 205 generated graph may be a helpful indicator of where time is being spent for the
 206 application.
 207
 208 .. code-block:: c++
 209
 210   // sample.cc
 211   #include <iostream>
 212   #include <thread>
 213
 214   [[clang::xray_always_intrument]] void f() {
 215     std::cerr << '.';
 216   }
 217
 218   [[clang::xray_always_intrument]] void g() {
 219     for (int i = 0; i < 1 << 10; ++i) {
 220       std::cerr << '-';
 221     }
 222   }
 223
 224   int main(int argc, char* argv[]) {
 225     std::thread t1([] {
 226       for (int i = 0; i < 1 << 10; ++i)
 227         f();
 228     });
 229     std::thread t2([] {
 230       g();
 231     });
 232     t1.join();
 233     t2.join();
 234     std::cerr << '\n';
 235   }
 236
 237 We then build the above with XRay instrumentation:
 238
 239 ::
 240
 241   $ clang++ -o sample -O3 sample.cc -std=c++11 -fxray-instrument -fxray-instruction-threshold=1
 242   $ XRAY_OPTIONS="patch_premain=true" ./sample
 243
 244 We can then explore the graph rendering of the trace generated by this sample
 245 application. We assume you have the graphviz toosl available in your system,
 246 including both ``unflatten`` and ``dot``. If you prefer rendering or exploring
 247 the graph using another tool, then that should be feasible as well. ``llvm-xray
 248 graph`` will create DOT format graphs which should be usable in most graph
 249 rendering applications. One example invocation of the ``llvm-xray graph``
 250 command should yield some interesting insights to the workings of C++
 251 applications:
 252
 253 ::
 254
 255   $ llvm-xray graph xray-log.sample.* -m sample -color-edges=sum -edge-label=sum \
 256       | unflatten -f -l10 | dot -Tsvg -o sample.svg
 257
 258 Next Steps
 259 ----------
 260
 261 If you have some interesting analyses you'd like to implement as part of the
 262 llvm-xray tool, please feel free to propose them on the llvm-dev@ mailing list.
 263 The following are some ideas to inspire you in getting involved and potentially
 264 making things better.
 265
 266   - Implement a query/filtering library that allows for finding patterns in the
 267     XRay traces.
 268   - A conversion from the XRay trace onto something that can be visualised
 269     better by other tools (like the Chrome trace viewer for example).
 270   - Collecting function call stacks and how often they're encountered in the
 271     XRay trace.
 272
 273