BPF tracing with SPDK

•

Recently, in the v21.07 release, SPDK got support for BPF tracing. It consists of a set of scripts and static probes defined within the SPDK libraries giving the user yet another way to inspect SPDK-based applications. SPDK already had a tracing library, called libtrace, for a long time. BPF tracing isn’t supposed to replace it, but rather complement it. Both have slightly different capabilities - libtrace has significantly lower overhead, but is less flexible. BPF traces, on the other hand, are more costly (they require a kernel trap), but are more robust and can even be attached dynamically, without having to define the probes in code.

User-level tracing

Firstly, let’s discuss what BPF tracing is and how SPDK is utilizing it. BPF, Berkeley Packet Filter, is a technology that was originally developed to analyze and filter network traffic. It allows the user to run user-supplied programs inside the operating system kernel in a special BPF virtual machine. Later on, in Linux, it was extended (hence eBPF - extended BPF) to support more use-cases, among-others, tracing. It lets users to leverage Linux tracing subsystem to attach probes at certain places in the program and, once hit, run an eBPF program tied to that probe [1]. In user-space applications, it works by placing an instruction (int3 on x86) generating SIGTRAP, which is then caught by the kernel triggering the execution of the eBPF program. SPDK uses bpftrace to define and attach probes. This tool uses a high-level scripting language (described by its authors as a mix of awk and C) to describe the actions to be taken when a given probe is triggered.

The probes can be divided into two categories: statically and dynamically defined. Static probes, called USDT (User Statically-Defined Tracing), are placed by the programmer in various critical locations in code (using one of the SPDK_DTRACE_PROBE* macros). Dynamic probes, on the other hand, can be enabled at the start of any function without having to change the code or recompile the application. There’s one caveat though: some of the static function calls might get inlined by the compiler, in which case the probe won’t get executed when expected.

Tools and examples

In order for USDT probes to be compiled-in, SPDK must be configured with --with-usdt. It’s also recommended to build a recent version of bpftrace from source, as we’ve encountered a number of issues with packaged versions on both Ubuntu 20.04 and Fedora 33. scripts/bpftrace.sh can be used to attach and display the traces. It expects two parameters - PID of the process to trace and the bpftrace script to attach. These scripts are capable of gathering and displaying a variety of different information and statistics. For instance, it’s possible to print parameters of a function each time it’s called, count how many times a given code path is executed, or even create and display a histogram from a set of values. SPDK already provides several useful scripts, located in the scripts/bpf directory.

Let’s take a look at one of them, scripts/bpf/send_msg.bt, see how it works and how it can be used to inspect an SPDK application. The goal of this script is to count the number of times a function is executed through spdk_thread_send_msg() and spdk_for_each_channel(). The contents of the script are pretty straight-forward:

uprobe:__EXE__:spdk_thread_send_msg {
	@send_msg[usym(arg1)] = count();
}

uprobe:__EXE__:spdk_for_each_channel {
	@for_each_channel[usym(arg1)] = count();
}

It defines two dynamic probes (via the uprobe keyword) that saves the number of calls to each function in a map (called send_msg and for_each_channel respectively). The first argument, arg1, is used as a key in the map and, in both cases, refers to the pointer to the function to be executed. The script uses two helper functions: usym() returning the name of a symbol at given address, and count(), which counts the number of times a function has been called. For more information on the available functions and the general syntax of the scripts, consult the bpftrace manual.

There’s one extra special variable called __EXE__. This one is SPDK-specific and is replaced by scripts/bpftrace.sh with the name of the executable (which is expected by bpftrace). There’s also __PID__, which is replaced by the PID of the traced process. Both of them offer a convenient way of using the same scripts with different applications. More details can be found in SPDK documentation.

Once the script is attached, it’ll run until the application exits (or the script is stopped). When that happens, it’ll print out the name of each function along with the number of times it was called. The sample output below was gathered by attaching to an NVMe/TCP target:

@for_each_channel[nvmf_ctrlr_disconnect_io_qpairs_on_pg]: 1
@for_each_channel[_nvmf_tgt_add_transport]: 1
@for_each_channel[subsystem_state_change_on_pg]: 5

@send_msg[_nvmf_ctrlr_add_admin_qpair]: 1
@send_msg[_nvmf_subsystem_add_ctrlr]: 1
@send_msg[_nvmf_ctrlr_destruct]: 1
@send_msg[_finish_unregister]: 1
@send_msg[_nvmf_ctrlr_destruct]: 1
@send_msg[put_io_channel]: 4
@send_msg[_call_completion]: 7
@send_msg[_call_channel]: 7
@send_msg[nvmf_ctrlr_add_io_qpair]: 24
@send_msg[_nvmf_ctrlr_add_io_qpair]: 24
@send_msg[_nvmf_ctrlr_free_from_qpair]: 25
@send_msg[_nvmf_poll_group_add]: 25
@send_msg[_nvmf_transport_qpair_fini]: 25

The other available scripts can be used to track system calls (syscalls.bt), NVMeoF subsystem state transitions (nvmf.bt), and readv calls with the number of bytes read (readv.bt). These, on their own, provide a lot of information, but they can also be used as a guideline for writing scripts aimed to track different properties of an application.

SPDK and BPF traces together

As stated before, one of the main goals of the SPDK trace library was to have minimal overhead. This means that each tracepoint is allowed to record only the most critical data. It makes it possible to place tracepoints in I/O path without major effect on performance. But now, with BPF traces, we can put bpftrace probes in places where objects are created, gather all kinds of their properties, and then use that data to annotate SPDK traces.

For instance, in NVMe/RDMA I/O path we record the pointer to a qpair on which a request is executed. We can use bpftrace to record information about a qpair such as its queue ID, thread ID, subsystem NQN, and host NQN and display it along with the pointer when showing SPDK traces. This is what the scripts/bpf/trace.py script is responsible for.

Let’s see how it works in practice. Firstly, bpftraces have to be recorded (assuming we’re tracing spdk_tgt app exposing an NVMe/RDMA target):

$ scripts/bpf/trace.py --record `pidof spdk_tgt` > bpftraces

Then, we can use it to annotate the traces:

$ build/bin/spdk_trace -f /dev/shm/spdk_tgt_trace.pid`pidof spdk_tgt` -j | scripts/bpf/trace.py --bpftrace bpftraces

This will transform the output from:

 0  39100254.090     RDMA_REQ_COMPLETING     id: r10  time: 49.692   qpair: 0x1178af0
 0  39100320.354     RDMA_REQ_COMPLETED      id: r10  time: 115.956  qpair: 0x1178af0
 0  39100494.100     RDMA_REQ_NEW            id: r11  qpair: 0x11790a0
 0  39100494.454     RDMA_REQ_NEED_BUFFER    id: r11  time: 0.354    qpair: 0x11790a0
 0  39100494.684     RDMA_REQ_RDY_TO_EXECUTE id: r11  time: 0.584    qpair: 0x11790a0
 0  39100500.546     RDMA_REQ_EXECUTING      id: r11  time: 6.446    qpair: 0x11790a0
 0  39100516.727     RDMA_REQ_EXECUTED       id: r11  time: 22.627   qpair: 0x11790a0
 0  39100516.903     RDMA_REQ_RDY_TO_COMPL   id: r11  time: 22.803   qpair: 0x11790a0
 0  39100517.333     RDMA_REQ_COMPLETING     id: r11  time: 23.233   qpair: 0x11790a0
 0  39100550.895     RDMA_REQ_COMPLETED      id: r11  time: 56.795   qpair: 0x11790a0

to:

 0  39100254.090     RDMA_REQ_COMPLETING     id: r10  time: 49.692   qpair(ptr=0x1178af0, thread=2, qid=1, subnqn=nqn.2016-06.io.spdk:cnode0, hostnqn=nqn.2014-08.org.nvmexpress:uuid:8da29bed555a45e8b9bc378e115f4c2)
 0  39100320.354     RDMA_REQ_COMPLETED      id: r10  time: 115.956  qpair(ptr=0x1178af0, thread=2, qid=1, subnqn=nqn.2016-06.io.spdk:cnode0, hostnqn=nqn.2014-08.org.nvmexpress:uuid:8da29bed555a45e8b9bc378e115f4c2)
 0  39100494.100     RDMA_REQ_NEW            id: r11  qpair(ptr=0x11790a0, thread=2, qid=2, subnqn=nqn.2016-06.io.spdk:cnode0, hostnqn=nqn.2014-08.org.nvmexpress:uuid:8da29bed555a45e8b9bc378e115f4c2)
 0  39100494.454     RDMA_REQ_NEED_BUFFER    id: r11  time: 0.354    qpair(ptr=0x11790a0, thread=2, qid=2, subnqn=nqn.2016-06.io.spdk:cnode0, hostnqn=nqn.2014-08.org.nvmexpress:uuid:8da29bed555a45e8b9bc378e115f4c2)
 0  39100494.684     RDMA_REQ_RDY_TO_EXECUTE id: r11  time: 0.584    qpair(ptr=0x11790a0, thread=2, qid=2, subnqn=nqn.2016-06.io.spdk:cnode0, hostnqn=nqn.2014-08.org.nvmexpress:uuid:8da29bed555a45e8b9bc378e115f4c2)
 0  39100500.546     RDMA_REQ_EXECUTING      id: r11  time: 6.446    qpair(ptr=0x11790a0, thread=2, qid=2, subnqn=nqn.2016-06.io.spdk:cnode0, hostnqn=nqn.2014-08.org.nvmexpress:uuid:8da29bed555a45e8b9bc378e115f4c2)
 0  39100516.727     RDMA_REQ_EXECUTED       id: r11  time: 22.627   qpair(ptr=0x11790a0, thread=2, qid=2, subnqn=nqn.2016-06.io.spdk:cnode0, hostnqn=nqn.2014-08.org.nvmexpress:uuid:8da29bed555a45e8b9bc378e115f4c2)
 0  39100516.903     RDMA_REQ_RDY_TO_COMPL   id: r11  time: 22.803   qpair(ptr=0x11790a0, thread=2, qid=2, subnqn=nqn.2016-06.io.spdk:cnode0, hostnqn=nqn.2014-08.org.nvmexpress:uuid:8da29bed555a45e8b9bc378e115f4c2)
 0  39100517.333     RDMA_REQ_COMPLETING     id: r11  time: 23.233   qpair(ptr=0x11790a0, thread=2, qid=2, subnqn=nqn.2016-06.io.spdk:cnode0, hostnqn=nqn.2014-08.org.nvmexpress:uuid:8da29bed555a45e8b9bc378e115f4c2)
 0  39100550.895     RDMA_REQ_COMPLETED      id: r11  time: 56.795   qpair(ptr=0x11790a0, thread=2, qid=2, subnqn=nqn.2016-06.io.spdk:cnode0, hostnqn=nqn.2014-08.org.nvmexpress:uuid:8da29bed555a45e8b9bc378e115f4c2)

For now, only RDMA qpairs can be annotated, however, expect more to come in the future.

Conclusion

Summing up, SPDK now has another robust way of inspecting its applications via BPF tracing. It consists of a set of bpftrace programs, USDT probes defined in SPDK libraries, and several scripts that simplify BPF tracing and make it possible to combine it with regular SPDK traces.

Stay tuned for more blog posts on this topic. Happy tracing!

Copyright © SPDK a Series of LF Projects, LLC. For web site terms of use, trademark policy, and other project policies please see https://lfprojects.org.