[Proposal] Tracing inline functions

[ShawnZhong]

Kernel function inlining has caused a lot of trouble for tracing in the past (e.g., #703, #1667, #2252, #2373, #3913, #4638, just to name a few)

I posted a proof of concept at #4638 (comment) to attach kprobes to inlined functions with the help of the debug info.

In short, we can

1. Download the debug info of the kernel image.
2. Look for the address of the inlined function (inside the caller function) and the location of the parameter (since the inlined function does not follow the calling convention).
3. Attach to the inlined function, and manually read the parameter from the register or stack.

The purpose of this post is to discuss whether this approach is feasible and if it can be implemented in a more general way.

Some of the challenges I can think of are:

• BTF does not record the address of inlined functions, so we have to rely on the debug info, which adds another dependency. Adding this information to BTF might be possible if people find it useful (and it does not increase the size too much).
• Usually, the location of the parameter can be found in some register. However, in the general case, it might require resolving DWARF expressions (see Chapter 2.5 at https://dwarfstd.org/doc/DWARF5.pdf). To automate this process, we might need to implement a DWARF expressions evaluator in BPF.
• Whether or not this approach is feasible depends on the quality of the debug info. I have seen cases where the compiler does not generate debug info for functions marked as __always_inline.

Here are the original proof of concept posted at #4638 (comment):

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
   

[yonghong-song]

cc @eddyz87 who had done something similar here by using dwarf info to identify func offset to be traced with kprobe.

[eddyz87]

I agree that this should be doable.
@ShawnZhong , do you have some code for this?
If not, I can work on this.