libbpf-tools: some bio tools fails to run on kernel v6.1

[michael-chuh]

I'm testing bio tools on riscv cpu with kenel 6.1, and get failures

~ # uname -a
Linux formosa 6.1.31+ #8 SMP Thu Jun 15 09:10:38 CST 2023 riscv64 GNU/Linux
~ # biosnoop
libbpf: prog 'blk_account_io_start': failed to attach: ERROR: strerror_r(-524)=22
failed to attach blk_account_io_start: Unknown error 524
~ # biostacks
libbpf: prog 'blk_account_io_done': failed to find kernel BTF type ID of 'blk_account_io_done': -3
libbpf: prog 'blk_account_io_done': failed to prepare load attributes: -3
libbpf: prog 'blk_account_io_done': failed to load: -3
libbpf: failed to load object 'biostacks_bpf'
libbpf: failed to load BPF skeleton 'biostacks_bpf': -3
failed to load BPF object: -3
~ # biotop
trace_kprobe: Could not probe notrace function blk_account_io_start
libbpf: prog 'blk_account_io_start': failed to create kprobe 'blk_account_io_start+0x0' perf event: Invalid argument
failed to load attach blk_account_io_start

only blk_account_io_start can be found in /proc/kallsyms, and they are both not existed in tracing/available_filter_functions

~ # cat /proc/kallsyms | grep blk_account_io
ffffffff801eed42 t blk_account_io_merge_bio
ffffffff801f2a9e t blk_account_io_completion
ffffffff801f2c74 t blk_account_io_start
~ # cat /sys/kernel/tracing/available_filter_functions | grep blk_account_io
blk_account_io_merge_bio
blk_account_io_completion

These 2 funstions are all inline functions, see
https://elixir.bootlin.com/linux/v6.1.31/source/block/blk-mq.c#L1001
https://elixir.bootlin.com/linux/v6.1.31/source/block/blk-mq.c#L971
inline is defined in include/linux/compiler_types.h

/*
 * Prefer gnu_inline, so that extern inline functions do not emit an
 * externally visible function. This makes extern inline behave as per gnu89
 * semantics rather than c99. This prevents multiple symbol definition errors
 * of extern inline functions at link time.
 * A lot of inline functions can cause havoc with function tracing.
 */
#define inline inline __gnu_inline __inline_maybe_unused notrace

they also become notrace functions, is there any way to fix it?

[yonghong-song]

Yes, blk_account_io_start/done() are inline functions in the kernel. @chenhengqi has submitted and got accepted with a tracepoint approach (https://lore.kernel.org/bpf/20230520084057.1467003-1-hengqi.chen@gmail.com/) they should be available in 6.5 kernel and corresponding bio tools using blk_account_io_start/done() will use tracepoint.

[yonghong-song]

I don't have a good solution with 6.1 kernel for these bio tools. If somebody has time, maybe poke into the kernel codes to see what could be done...

[michael-chuh]

I backport this patch to my local linux-6.1, and add tracepoint to bio tools for future use
#4659

[ShawnZhong]

Here is a proof of concept to attach kprobes to inline functions and read the arguments given the debug info.

1. Download the debug info of the kernel image (e.g., sudo apt install linux-image-$(uname -r)-dbgsym for Ubuntu. Need to add the package list first following this link)

2. Dump the address of inlined function:

   llvm-dwarfdump /usr/lib/debug/boot/vmlinux-$(uname -r) --name=blk_account_io_start -c -p
   

   For example, one of the inlined sites is shown as follows:

   0x05bb39d6:     DW_TAG_inlined_subroutine
                     DW_AT_abstract_origin	(0x05bb6776 "blk_account_io_start")
                     DW_AT_entry_pc	(0xffffffff8174428e)
                     DW_AT_GNU_entry_view	(0x0007)
                     DW_AT_low_pc	(0xffffffff8174428e)
                     DW_AT_high_pc	(0xffffffff817442a0)
                     DW_AT_call_file	("/build/linux-hwe-6.2-fr4wiC/linux-hwe-6.2-6.2.0/block/blk-mq.c")
                     DW_AT_call_line	(1341)
                     DW_AT_call_column	(0x02)
                     DW_AT_sibling	(0x05bb3a54)
   
   0x05bb39fd:       DW_TAG_formal_parameter
                       DW_AT_abstract_origin	(0x05bb6784 "req")
                       DW_AT_location	(0x00e7f3c3: 
                          [0xffffffff8174428e, 0xffffffff817442a0): DW_OP_reg12 R12)
                       DW_AT_GNU_locviews	(0x00e7f3c1)

   From the output above, we know that this inlined call site for blk_account_io_start is at 0xffffffff8174428e (or blk_execute_rq_nowait+0x8e with symbol table info) and the first parameter req is at r12. Similar information can be found for other inlined call sites.

3. Given that, we can write an eBPF program to attach to inlined functions. The full code is shown below:

   int print_req(unsigned long reg) {
     struct request *req = (struct request *)reg;
     bpf_printk("req->cmd_flags: %x", BPF_CORE_READ(req, cmd_flags));
     return 0;
   }
   
   SEC("kprobe/blk_insert_cloned_request+0x94")
   int BPF_KPROBE(blk_insert_cloned_request_0x94) { return print_req(ctx->r12); }
   
   SEC("kprobe/blk_mq_submit_bio+0x245")
   int BPF_KPROBE(blk_mq_submit_bio_0x245) { return print_req(ctx->r13); }
   
   SEC("kprobe/blk_execute_rq+0x9d")
   int BPF_KPROBE(blk_execute_rq_0x9d) { return print_req(ctx->bx); }
   
   SEC("kprobe/blk_execute_rq_nowait+0x8e")
   int BPF_KPROBE(blk_execute_rq_nowait_0x8e) { return print_req(ctx->r12); }

   with output:

    kworker/u81:3-8065    [021] d.Z21  7952.811875: bpf_trace_printk: req->cmd_flags: 103001
    kworker/u81:3-8065    [021] d.Z21  7952.811896: bpf_trace_printk: req->cmd_flags: 103001
    kworker/u81:3-8065    [021] d.Z21  7952.811916: bpf_trace_printk: req->cmd_flags: 103001
    kworker/u81:3-8065    [021] d.Z21  7952.811932: bpf_trace_printk: req->cmd_flags: 103001
    kworker/u81:3-8065    [021] d.Z21  7952.811948: bpf_trace_printk: req->cmd_flags: 103001
    kworker/u81:3-8065    [021] d.Z21  7952.811965: bpf_trace_printk: req->cmd_flags: 103001
    kworker/u81:3-8065    [021] d.Z21  7952.811978: bpf_trace_printk: req->cmd_flags: 103001
    kworker/u81:3-8065    [021] d.Z21  7952.811990: bpf_trace_printk: req->cmd_flags: 103001
    kworker/u81:3-8065    [021] d.Z21  7952.812804: bpf_trace_printk: req->cmd_flags: 1
    kworker/u81:3-8065    [021] d.Z21  7952.812848: bpf_trace_printk: req->cmd_flags: 1
    kworker/u81:3-8065    [021] d.Z21  7952.812919: bpf_trace_printk: req->cmd_flags: 1
    kworker/u81:3-8065    [021] d.Z21  7952.815200: bpf_trace_printk: req->cmd_flags: 1
    kworker/u81:3-8065    [021] d.Z21  7952.815336: bpf_trace_printk: req->cmd_flags: 1
      jbd2/sda3-8-573     [009] d.Z21  7953.945114: bpf_trace_printk: req->cmd_flags: 801
      jbd2/sda3-8-573     [009] d.Z21  7953.945629: bpf_trace_printk: req->cmd_flags: 60801
    kworker/u81:3-8065    [024] d.Z21  7958.699324: bpf_trace_printk: req->cmd_flags: 1
    kworker/u81:3-8065    [024] d.Z21  7958.699384: bpf_trace_printk: req->cmd_flags: 103001
    kworker/u81:3-8065    [024] d.Z21  7958.699406: bpf_trace_printk: req->cmd_flags: 103001