llvm.org GIT mirror llvm / 21463ca
[XRay][docs] Examples for how to use XRay Summary: This document is an attempt at showing how XRay could be used to debug latency issues with LLVM tools, and how to use the llvm-xray tool to analyse XRay traces. Reviewers: echristo, mehdi_amini, davide Subscribers: llvm-commits Differential Revision: https://reviews.llvm.org/D31493 git-svn-id: https://llvm.org/svn/llvm-project/llvm/trunk@299133 91177308-0d34-0410-b5e6-96231b3b80d8 Dean Michael Berris 2 years ago
2 changed file(s) with 277 addition(s) and 0 deletion(s). Raw diff Collapse all Expand all
0 ===================
1 Debugging with XRay
2 ===================
3
4 This document shows an example of how you would go about analyzing applications
5 built with XRay instrumentation. Here we will attempt to debug ``llc``
6 compiling some sample LLVM IR generated by Clang.
7
8 .. contents::
9 :local:
10
11 Building with XRay
12 ------------------
13
14 To debug an application with XRay instrumentation, we need to build it with a
15 Clang that supports the ``-fxray-instrument`` option. See `XRay
16
17 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&) 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 ouput 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
212 #include
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
398398 :doc:`XRay`
399399 High-level documentation of how to use XRay in LLVM.
400400
401 :doc:`XRayExample`
402 An example of how to debug an application with XRay.
403
401404 :doc:`The Microsoft PDB File Format `
402405 A detailed description of the Microsoft PDB (Program Database) file format.
403406