Instrumenting with XRay

XRay is a tool, originally developed at Google and now integrated in LLVM, that instruments the program such that when it runs it produces a trace of executed functions and their timestamps. This article explains how to instrument WiredTiger, collect the XRay traces, and analyze them. As an example, we will show how to trace wtperf.

Step 1: Configure and compile WiredTiger with XRay instrumentation

$ mkdir build
$ cd build
$ cmake -DCMAKE_C_FLAGS=-fxray-instrument -DCMAKE_TOOLCHAIN_FILE=../cmake/toolchains/clang.cmake -DCLANG_C_VERSION="8" -DCLANG_CXX_VERSION="8"  ../.
$ make

Step 2: Run wtperf

Use the script wtperf_xray.sh to launch wtperf from the directory containing the wtperf binary. The first argument to the script must be the benchmark configuration file. For example:

$ cd bench/wtperf

$ ../../../bench/wtperf/runners/wtperf_xray.sh ../../../bench/wtperf/runners/small-btree.wtperf

In general the usage is:

wtperf_xray.sh <wtperf-config-file> [-h output-directory] [wtperf other arguments]

The wtperf_xray.sh produces a few outputs to help analyze performance:

wtperf_account.txt: The top 10 functions where the workload is spending the most time with a count, min, max and some percentiles for each one.
wtperf_stacks.txt: The top 10 stack traces where the workload is spending the most time. This calculation is done separately per thread.
wtperf_graph.svg: A function call graph showing what functions call each other. The edges are labeled and colored proportionally to represent the ratio of time spent in each function call.
wtperf_flame.svg: A graph visualizing stack traces and the time spent within each stack frame. If FLAME_GRAPH_PATH is not specified, this graph won't be generated.

The wtperf_xray.sh script uses a few optional environment variables to modify its behavior:

XRAY_BINARY: The binary to use to inspect the XRay log. The script defaults to using llvm-xray however, if you compiled with a particular clang version, you should use the corresponding llvm-xray version. For example, if you selected clang-8 like the configuration above, you should set XRAY_BINARY to llvm-xray-8.
FLAME_GRAPH_PATH: As part of the script's analysis phase, it can optionally produce a FlameGraph. The FLAME_GRAPH_PATH variable must be set to your copy of Brendan Gregg's FlameGraph script (flamegraph.pl).

Convert XRay logs to the Operation Tracking format (optional)

After running a program instrumented with XRay, a log file will be produced containing performance information. There is a tool called xray_to_optrack which is designed to convert this log to the Operation Tracking format.

Step 1: Take a copy of the wtperf binary and the XRay log

To build the xray_to_optrack utility, we'll need to reconfigure and build with a new set of flags. Before doing that, we'll need to keep a copy of the XRay log and the wtperf binary that we used to generate it.

$ cp <wtperf> <xray_log> .

Step 2: Install LLVM

The xray_to_optrack utility requires LLVM in order to parse the XRay log file. So we'll need to install LLVM via our package manager.

$ sudo apt install llvm

LLVM needs to be version 8 or higher. Check the version like this:

$ llvm-config -version

If your distribution's default llvm-config isn't from the 8 series, you'll need to move one with a major version of 8 into the $PATH such that it gets invoked instead.

The llvm-config command line tool is used to supply the required compiler and linker flags to build programs such like xray_to_optrack on top of LLVM.

Step 3: Configure and build WiredTiger with LLVM flags

Supply the -DENABLE_LLVM flag to your configuration to build anything with a dependency to LLVM.

$ cd build
$ cmake -DENABLE_LLVM=1 -DCMAKE_TOOLCHAIN_FILE=../cmake/toolchains/clang.cmake -DCLANG_C_VERSION="8" -DCLANG_CXX_VERSION="8" ../.
$ make

Take care NOT to customize CC or CXX. Customizing either of these variables will cause C++ programs such as workgen or xray_to_optrack to be skipped since we can't reliably link object files emitted by C and C++ compilers unless they are the system's default cc and c++.

Step 4: Process the traces

To process the traces, use the xray_to_optrack tool in the tools/xray_to_optrack directory.

Then, run the tool like this:

$ xray_to_optrack <xray_instrumented_binary> <xray_log>

xray_instrumented_binary is the binary that produced the log, wtperf in our case, and xray_log is the log file.

The script will produce one or more files with a prefix optrack. You can view these files with optrack tools, described in the optrack documentation.