Debugging with XRay

This document shows an example of how you would go about analyzing applicationsbuilt with XRay instrumentation. Here we will attempt to debug llccompiling some sample LLVM IR generated by Clang.

Building with XRay

To debug an application with XRay instrumentation, we need to build it with aClang that supports the -fxray-instrument option. See XRayfor more technical details of how XRay works for background information.

In our example, we need to add -fxray-instrument to the list of flagspassed to Clang when building a binary. Note that we need to link with Clang aswell to get the XRay runtime linked in appropriately. For building llc withXRay, we do something similar below for our LLVM build:

  1. $ mkdir -p llvm-build && cd llvm-build
  2. # Assume that the LLVM sources are at ../llvm
  3. $ cmake -GNinja ../llvm -DCMAKE_BUILD_TYPE=Release \
  4.     -DCMAKE_C_FLAGS_RELEASE="-fxray-instrument" -DCMAKE_CXX_FLAGS="-fxray-instrument" \
  5. # Once this finishes, we should build llc
  6. $ ninja llc

To verify that we have an XRay instrumented binary, we can use objdump tolook for the xray_instr_map section.

  1. $ objdump -h -j xray_instr_map ./bin/llc
  2. ./bin/llc:     file format elf64-x86-64
  3.  
  4. Sections:
  5. Idx Name          Size      VMA               LMA               File off  Algn
  6.  14 xray_instr_map 00002fc0  00000000041516c6  00000000041516c6  03d516c6  2**0
  7.                   CONTENTS, ALLOC, LOAD, READONLY, DATA

Getting Traces

By default, XRay does not write out the trace files or patch the applicationbefore main starts. If we run llc it should work like a normally builtbinary. If we want to get a full trace of the application’s operations (of thefunctions we do end up instrumenting with XRay) then we need to enable XRayat application start. To do this, XRay checks the XRAY_OPTIONS environmentvariable.

  1. # The following doesn't create an XRay trace by default.
  2. $ ./bin/llc input.ll
  3.  
  4. # We need to set the XRAY_OPTIONS to enable some features.
  5. $ XRAY_OPTIONS="patch_premain=true xray_mode=xray-basic verbosity=1" ./bin/llc input.ll
  6. ==69819==XRay: Log file in 'xray-log.llc.m35qPB'

At this point we now have an XRay trace we can start analysing.

The llvm-xray Tool

Having a trace then allows us to do basic accounting of the functions that wereinstrumented, and how much time we’re spending in parts of the code. To makesense of this data, we use the llvm-xray tool which has a few subcommandsto help us understand our trace.

One of the things we can do is to get an accounting of the functions that havebeen instrumented. We can see an example accounting with llvm-xray account:

  1. $ llvm-xray account xray-log.llc.m35qPB -top=10 -sort=sum -sortorder=dsc -instr_map ./bin/llc
  2. Functions with latencies: 29
  3.    funcid      count [      min,       med,       90p,       99p,       max]       sum  function
  4.       187        360 [ 0.000000,  0.000001,  0.000014,  0.000032,  0.000075]  0.001596  LLLexer.cpp:446:0: llvm::LLLexer::LexIdentifier()
  5.        85        130 [ 0.000000,  0.000000,  0.000018,  0.000023,  0.000156]  0.000799  X86ISelDAGToDAG.cpp:1984:0: (anonymous namespace)::X86DAGToDAGISel::Select(llvm::SDNode*)
  6.       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)
  7.       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*)
  8.        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&)
  9.       125        102 [ 0.000001,  0.000003,  0.000010,  0.000017,  0.000049]  0.000471  Verifier.cpp:3714:0: (anonymous namespace)::Verifier::visitInstruction(llvm::Instruction&)
  10.        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
  11.       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&)
  12.       123          1 [ 0.000302,  0.000302,  0.000302,  0.000302,  0.000302]  0.000302  LLVMContextImpl.cpp:54:0: llvm::LLVMContextImpl::~LLVMContextImpl()
  13.       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

This shows us that for our input file, llc spent the most cumulative timein the lexer (a total of 1 millisecond). If we wanted for example to work withthis data in a spreadsheet, we can output the results as CSV using the-format=csv option to the command for further analysis.

If we want to get a textual representation of the raw trace we can use thellvm-xray convert tool to get YAML output. The first few lines of thatoutput for an example trace would look like the following:

  1. $ llvm-xray convert -f yaml -symbolize -instr_map=./bin/llc xray-log.llc.m35qPB

header: version: 1 type: 0 constant-tsc: true nonstop-tsc: true cycle-frequency: 2601000000records:

  • { type: 0, func-id: 110, function: __cxx_global_var_init.8, cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426023268520 }
  • { type: 0, func-id: 110, function: __cxx_global_var_init.8, cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426023523052 }
  • { type: 0, func-id: 164, function: __cxx_global_var_init, cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426029925386 }
  • { type: 0, func-id: 164, function: __cxx_global_var_init, cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426030031128 }
  • { 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 }
  • { 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 }
  • { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426047857332 }
  • { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426047984152 }
  • { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426048036584 }
  • { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426048042292 }
  • { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-enter, tsc: 5434426048055056 }
  • { type: 0, func-id: 187, function: 'llvm::LLLexer::LexIdentifier()', cpu: 37, thread: 69819, kind: function-exit, tsc: 5434426048067316 }

Controlling Fidelity

So far in our examples, we haven’t been getting full coverage of the functionswe have in the binary. To get that, we need to modify the compiler flags sothat we can instrument more (if not all) the functions we have in the binary.We have two options for doing that, and we explore both of these below.

Instruction Threshold

The first “blunt” way of doing this is by setting the minimum threshold forfunction bodies to 1. We can do that with the-fxray-instruction-threshold=N flag when building our binary. We rebuildllc with this option and observe the results:

  1. $ rm CMakeCache.txt
  2. $ cmake -GNinja ../llvm -DCMAKE_BUILD_TYPE=Release \
  3.     -DCMAKE_C_FLAGS_RELEASE="-fxray-instrument -fxray-instruction-threshold=1" \
  4.     -DCMAKE_CXX_FLAGS="-fxray-instrument -fxray-instruction-threshold=1"
  5. $ ninja llc
  6. $ XRAY_OPTIONS="patch_premain=true" ./bin/llc input.ll
  7. ==69819==XRay: Log file in 'xray-log.llc.5rqxkU'
  8.  
  9. $ llvm-xray account xray-log.llc.5rqxkU -top=10 -sort=sum -sortorder=dsc -instr_map ./bin/llc
  10. Functions with latencies: 36652
  11.  funcid      count [      min,       med,       90p,       99p,       max]       sum  function
  12.      75          1 [ 0.672368,  0.672368,  0.672368,  0.672368,  0.672368]  0.672368  llc.cpp:271:0: main
  13.      78          1 [ 0.626455,  0.626455,  0.626455,  0.626455,  0.626455]  0.626455  llc.cpp:381:0: compileModule(char**, llvm::LLVMContext&)
  14.  139617          1 [ 0.472618,  0.472618,  0.472618,  0.472618,  0.472618]  0.472618  LegacyPassManager.cpp:1723:0: llvm::legacy::PassManager::run(llvm::Module&)
  15.  139610          1 [ 0.472618,  0.472618,  0.472618,  0.472618,  0.472618]  0.472618  LegacyPassManager.cpp:1681:0: llvm::legacy::PassManagerImpl::run(llvm::Module&)
  16.  139612          1 [ 0.470948,  0.470948,  0.470948,  0.470948,  0.470948]  0.470948  LegacyPassManager.cpp:1564:0: (anonymous namespace)::MPPassManager::runOnModule(llvm::Module&)
  17.  139607          2 [ 0.147345,  0.315994,  0.315994,  0.315994,  0.315994]  0.463340  LegacyPassManager.cpp:1530:0: llvm::FPPassManager::runOnModule(llvm::Module&)
  18.  139605         21 [ 0.000002,  0.000002,  0.102593,  0.213336,  0.213336]  0.463331  LegacyPassManager.cpp:1491:0: llvm::FPPassManager::runOnFunction(llvm::Function&)
  19.  139563      26096 [ 0.000002,  0.000002,  0.000037,  0.000063,  0.000215]  0.225708  LegacyPassManager.cpp:1083:0: llvm::PMDataManager::findAnalysisPass(void const*, bool)
  20.  108055        188 [ 0.000002,  0.000120,  0.001375,  0.004523,  0.062624]  0.159279  MachineFunctionPass.cpp:38:0: llvm::MachineFunctionPass::runOnFunction(llvm::Function&)
  21.   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

Instrumentation Attributes

The other way is to use configuration files for selecting which functionsshould always be instrumented by the compiler. This gives us a way of ensuringthat certain functions are either always or never instrumented by not having toadd the attribute to the source.

To use this feature, you can define one file for the functions to alwaysinstrument, and another for functions to never instrument. The format of thesefiles are exactly the same as the SanitizerLists files that control similarthings for the sanitizer implementations. For example:

  1. # xray-attr-list.txt
  2. # always instrument functions that match the following filters:
  3. [always]
  4. fun:main
  5.  
  6. # never instrument functions that match the following filters:
  7. [never]
  8. fun:__cxx_*

Given the file above we can re-build by providing it to the-fxray-attr-list= flag to clang. You can have multiple files, each definingdifferent sets of attribute sets, to be combined into a single list by clang.

The XRay stack tool

Given a trace, and optionally an instrumentation map, the llvm-xray stackcommand can be used to analyze a call stack graph constructed from the functioncall timeline.

The way to use the command is to output the top stacks by call count and time spent.

  1. $ llvm-xray stack xray-log.llc.5rqxkU -instr_map ./bin/llc
  2.  
  3. Unique Stacks: 3069
  4. Top 10 Stacks by leaf sum:
  5.  
  6. Sum: 9633790
  7. lvl   function                                                            count              sum
  8. #0    main                                                                    1         58421550
  9. #1    compileModule(char**, llvm::LLVMContext&)                               1         51440360
  10. #2    llvm::legacy::PassManagerImpl::run(llvm::Module&)                       1         40535375
  11. #3    llvm::FPPassManager::runOnModule(llvm::Module&)                         2         39337525
  12. #4    llvm::FPPassManager::runOnFunction(llvm::Function&)                     6         39331465
  13. #5    llvm::PMDataManager::verifyPreservedAnalysis(llvm::Pass*)             399         16628590
  14. #6    llvm::PMTopLevelManager::findAnalysisPass(void const*)               4584         15155600
  15. #7    llvm::PMDataManager::findAnalysisPass(void const*, bool)            32088          9633790
  16.  
  17. ..etc..

In the default mode, identical stacks on different threads are independentlyaggregated. In a multithreaded program, you may end up having identical callstacks fill your list of top calls.

To address this, you may specify the -aggregate-threads or-per-thread-stacks flags. -per-thread-stacks treats the thread id as animplicit root in each call stack tree, while -aggregate-threads combinesidentical stacks from all threads.

Flame Graph Generation

The llvm-xray stack tool may also be used to generate flamegraphs forvisualizing your instrumented invocations. The tool does not generate the graphsthemselves, but instead generates a format that can be used with Brendan Gregg’sFlameGraph tool, currently available on github.

To generate output for a flamegraph, a few more options are necessary.

  • -all-stacks - Emits all of the stacks.
  • -stack-format - Choose the flamegraph output format ‘flame’.
  • -aggregation-type - Choose the metric to graph.

You may pipe the command output directly to the flamegraph tool to obtain ansvg file.

  1. $llvm-xray stack xray-log.llc.5rqxkU -instr_map ./bin/llc -stack-format=flame -aggregation-type=time -all-stacks | \
  2. /path/to/FlameGraph/flamegraph.pl > flamegraph.svg

If you open the svg in a browser, mouse events allow exploring the call stacks.

Chrome Trace Viewer Visualization

We can also generate a trace which can be loaded by the Chrome Trace Viewerfrom the same generated trace:

  1. $ llvm-xray convert -symbolize -instr_map=./bin/llc \
  2.   -output-format=trace_event xray-log.llc.5rqxkU \
  3.     | gzip > llc-trace.txt.gz

From a Chrome browser, navigating to chrome:///tracing allows us to loadthe sample-trace.txt.gz file to visualize the execution trace.

Further Exploration

The llvm-xray tool has a few other subcommands that are in various stagesof being developed. One interesting subcommand that can highlight a fewinteresting things is the graph subcommand. Given for example the followingtoy program that we build with XRay instrumentation, we can see how thegenerated graph may be a helpful indicator of where time is being spent for theapplication.

  1. // sample.cc
  2. #include <iostream>
  3. #include <thread>
  4.  
  5. [[clang::xray_always_instrument]] void f() {
  6.   std::cerr << '.';
  7. }
  8.  
  9. [[clang::xray_always_instrument]] void g() {
  10.   for (int i = 0; i < 1 << 10; ++i) {
  11.     std::cerr << '-';
  12.   }
  13. }
  14.  
  15. int main(int argc, char* argv[]) {
  16.   std::thread t1([] {
  17.     for (int i = 0; i < 1 << 10; ++i)
  18.       f();
  19.   });
  20.   std::thread t2([] {
  21.     g();
  22.   });
  23.   t1.join();
  24.   t2.join();
  25.   std::cerr << '\n';
  26. }

We then build the above with XRay instrumentation:

  1. $ clang++ -o sample -O3 sample.cc -std=c++11 -fxray-instrument -fxray-instruction-threshold=1
  2. $ XRAY_OPTIONS="patch_premain=true xray_mode=xray-basic" ./sample

We can then explore the graph rendering of the trace generated by this sampleapplication. We assume you have the graphviz toosl available in your system,including both unflatten and dot. If you prefer rendering or exploringthe graph using another tool, then that should be feasible as well. llvm-xraygraph will create DOT format graphs which should be usable in most graphrendering applications. One example invocation of the llvm-xray graphcommand should yield some interesting insights to the workings of C++applications:

  1. $ llvm-xray graph xray-log.sample.* -m sample -color-edges=sum -edge-label=sum \
  2.     | unflatten -f -l10 | dot -Tsvg -o sample.svg

Next Steps

If you have some interesting analyses you’d like to implement as part of thellvm-xray tool, please feel free to propose them on the llvm-dev@ mailing list.The following are some ideas to inspire you in getting involved and potentiallymaking things better.

  • Implement a query/filtering library that allows for finding patterns in theXRay traces.
  • Collecting function call stacks and how often they’re encountered in theXRay trace.