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