Does uprobe add a significant overhead for tracing?

Question

I just started learning eBPF to trace function calls using libbpf project with uprobe. I started with the example uprobe.c and add high resolution clock to measure overheads added to the function call before and after uprobe is attached.

Here are useful sections of the code. All pieces are compiled with "-O2"

uprobe_target.cpp

int __attribute__ ((noinline)) uprobed_add(int a, int b) {
    return a + b;
}

int main(int argc, char **argv) {
    using namespace std::chrono;
    high_resolution_clock::time_point t1, t2;
    printf("uprobed_add = %lu
", &uprobed_add);
    for (int i = 0; ; i++) {
        t1 = high_resolution_clock::now();
        auto s = uprobed_add(i, i + 1);
        t2 = high_resolution_clock::now();
        printf("%ld,	#%d
", duration_cast(t2 - t1), s);
        std::this_thread::sleep_for(std::chrono::seconds(3));
    }
}

uprobe.bpf.c

SEC("uprobe")
int BPF_KPROBE(uprobe_add, int a, int b)
{
    bpf_printk("uprobed_add ENTRY: a = %d, b = %d", a, b);
    return 0;
}

SEC("uretprobe")
int BPF_KRETPROBE(uretprobe_add, int ret)
{
    bpf_printk("uprobed_add EXIT: return = %d", ret);
    return 0;
}

uprobe.c

uprobe_offset = get_uprobe_offset(&uprobed_add_addr);
/* Attach tracepoint handler */
skel->links.uprobe_add = bpf_program__attach_uprobe(skel->progs.uprobe_add,
                        false /* not uretprobe */,
                        -1 /* self pid */,
                        "compiled_uprobe_target",
                        uprobe_offset);
skel->links.uretprobe_add = bpf_program__attach_uprobe(skel->progs.uretprobe_add,
                       true /* uretprobe */,
                       -1 /* any pid */,
                       "compiled_uprobe_target",
                       uprobe_offset);
    printf("Successfully started! Please run `sudo cat /sys/kernel/debug/tracing/trace_pipe` "
           "to see output of the BPF programs.
");

The BPF hooks can be properly attached. We can find proper output from trace_pipe as bpf_trace_printk: uprobed_add ENTRY: a = 184, b = 185. However, before and after attaching the hook, the uprobed_add becomes 50x slower. E.g., Before

48,     #467
35,     #469
56,     #471
64,     #473
53,     #475
40,     #477

After

11573,  #19237
12242,  #19239
10274,  #19241
12566,  #19243
12360,  #19245
11727,  #19247

I initially consider it might be caused by printk function inside the hooks. However, commenting printing lines out doesn't change numbers overall. I also made another experiment using uprobe from /sys/kernel/debug/tracing, which showed similar numbers before and after uprobe hook is attached.

echo 'p:enter_add /fsx/src/libbpf-bootstrap/examples/c/c.out:' >> /sys/kernel/debug/tracing/uprobe_events
echo 1 > /sys/kernel/debug/tracing/events/uprobes/enter_add/enable

As long as I enable the tracing point, total time for each call immediately jump to 10000ns+.

Is it a true overhead for a call tracing using uprobe?

Does uprobe add a significant overhead for tracing?

0 Answers