kallsyms: add update trigger on bpf_ksym_add

[florianl]

Notify Symbolizer for kallsyms about changes to eBPF programs.

Fixes #938

[fabled]

Thanks this seems leanest implementation to me.

I think the reload triggering needs more work.

I'd also avoid the kernel version check (and related changes to package moving). Mostly because redhat (and some others) maintain their own stuff and pure version check can result in wrong behavior.

[christos68k]

We should cleanup/disable the perfEvents here (as nobody is calling Tracer.Close if AttachTracer fails).

[florianl]

Tracer.Close() is called via ctlr.Shutdown().
So, if AttachTracer() fails then ctlr.Start() fails and it will trigger the cleanup.

[christos68k]

AFAICT from reading this code, this is not executed when the profiler is running as a receiver inside OTel collector.

It's also better to deal with the in-between private state inside the method -as it's the method that created it-, rather than propagate this private state outside and depend on an external caller of a different method (as we're then introducing a time-window where there's invalid private state that depends on further action for cleanup).

[florianl]

This code path is executed by the OTel collector, as BuildProfilesReceiver() (and xreceiver.Profiles) satisfies the component.Factory interface with its Shutdown(context.Context) error function. Here we implement it.

[christos68k]

When reading the interface docstring, I don't see anything that mentions Shutdown being called when Start fails.

Regardless of that, it's not right to delay cleanup in this case and introduce implicit dependencies on external components: it violates encapsulation and the principle of single responsibility, thus making the code harder to reason about.

It's this method that introduces this in-between state and it should be this method that cleans it up when it fails (this is similar to RAII).

[florianl]

Addded terminatePerfEvents() as cleanup routine for failures with d391075

[bobrik]

Doing full kallsyms re-parsing might be a bit too heavy handed here:

ivan@748m17:~$ time cat /proc/kallsyms > /dev/null

real    0m0.878s
user    0m0.004s
sys     0m0.872s

Just running bpftool prog loads a bunch of programs:

ivan@748m17:~$ sudo strace -f -e bpf bpftool prog 2>&1 | grep BPF_PROG_LOAD
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_SOCKET_FILTER, insn_cnt=2, insns=0x7ffc88c97fc0, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=0, func_info_rec_size=0, func_info=NULL, func_info_cnt=0, line_info_rec_size=0, line_info=NULL, line_info_cnt=0, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 152) = 3
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_SOCKET_FILTER, insn_cnt=2, insns=0x7ffc88c97be0, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=0, func_info_rec_size=0, func_info=NULL, func_info_cnt=0, line_info_rec_size=0, line_info=NULL, line_info_cnt=0, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 148) = 4
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_SOCKET_FILTER, insn_cnt=2, insns=0x7ffc88c97df0, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=0, func_info_rec_size=0, func_info=NULL, func_info_cnt=0, line_info_rec_size=0, line_info=NULL, line_info_cnt=0, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 148) = 4
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_SOCKET_FILTER, insn_cnt=2, insns=0x7ffc88c97a70, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="libbpf_nametest", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=0, func_info_rec_size=0, func_info=NULL, func_info_cnt=0, line_info_rec_size=0, line_info=NULL, line_info_cnt=0, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 148) = 4
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=4, insns=0x7ffc88c97b70, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="det_arg_ctx", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=4, func_info_rec_size=8, func_info=0x7ffc88c97b60, func_info_cnt=2, line_info_rec_size=0, line_info=NULL, line_info_cnt=0, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 148) = 5
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_SOCKET_FILTER, insn_cnt=5, insns=0x7ffc88c97ba0, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=0, func_info_rec_size=0, func_info=NULL, func_info_cnt=0, line_info_rec_size=0, line_info=NULL, line_info_cnt=0, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 148) = 6
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_TRACEPOINT, insn_cnt=6, insns=0x7ffc88c97c70, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=0, func_info_rec_size=0, func_info=NULL, func_info_cnt=0, line_info_rec_size=0, line_info=NULL, line_info_cnt=0, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 148) = 5
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_TRACING, insn_cnt=137, insns=0x56257fd162e0, license="Dual BSD/GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(6, 12, 66), prog_flags=0, prog_name="iter", prog_ifindex=0, expected_attach_type=BPF_TRACE_ITER, prog_btf_fd=4, func_info_rec_size=8, func_info=0x56257fd15840, func_info_cnt=1, line_info_rec_size=16, line_info=0x56257fd22f40, line_info_cnt=44, attach_btf_id=30369, attach_prog_fd=0, fd_array=NULL}, 148) = 5
bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_SOCKET_FILTER, insn_cnt=2, insns=0x7ffc88c97a70, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(0, 0, 0), prog_flags=0, prog_name="", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=0, func_info_rec_size=0, func_info=NULL, func_info_cnt=0, line_info_rec_size=0, line_info=NULL, line_info_cnt=0, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 148) = 7

We rely on this for bpf runtime time accounting pretty heavily.

We apparently also have a steady stream of bpf programs loaded in production.

Given that we have all the info in the kprobe arguments (start, end, name), should we maybe use that directly?

struct bpf_ksym {
	unsigned long		 start;
	unsigned long		 end;
	char			 name[KSYM_NAME_LEN];
	struct list_head	 lnode;
	struct latch_tree_node	 tnode;
	bool			 prog;
	u32			 fp_start;
	u32			 fp_end;
};

[fabled]

Yes, reading full kallsyms is very cpu heavy. Tracking and queueing the probes can be problematic too.

I wonder if kallsyms can be seeked, and we could just read the non-module portion of it from the end directly.

[bobrik]

It's interesting that bpf_get_kallsym is the most expensive bit of it too.

I cross-checked it with just perf:

ivan@748m17:~$ sudo perf record -g -- cat /proc/kallsyms > /dev/null

ivan@748m17:~$ sudo perf script | grep 'cat 3828805' | wc -l
3644
ivan@748m17:~$ sudo perf script | grep 'bpf_get_kallsym' | wc -l
3285

I wonder if there's something quadratic going on there and we just need to fix the kernel itself as the first step.

[bobrik]

Oh yeah, this is quadratic alright:

https://github.com/torvalds/linux/blob/7d0a66e4bb9081d75c82ec4957c50034cb0ea449/kernel/bpf/core.c#L781-L807

We do have a lot of symbols too:

ivan@748m17:~$ cat /proc/kallsyms | grep -F '[bpf]' | wc -l
10507

[bobrik]

I took a stab at fixing it upstream:

• https://lore.kernel.org/bpf/20260129-ivan-bpf-ksym-cache-v1-1-ca503070dcc0@cloudflare.com/T/#u

Testing in production on v6.12 series (with ~10000 bpf ksyms as well):

• On AMD EPYC 9684X (Zen4): ~870ms -> ~100ms
• On Ampere Altra Max M128-30: ~4650ms -> ~70ms

[bobrik]

Even with the patch applied, it's still a considerable amount of work to read and parse /proc/kallsyms:

For me about 72% of symbols are static. You can seek over them but that would not prevent any of the hot printf code from executing, so the utility of doing that is kind of limited (you only save a small portion of userspace work).

Having a separate /proc/kallsyms-dynamic is one way to reduce work, but that's not going to get into older kernels and it would still be a lot of work for a small change when a symbol is added.

Ultimately, I think having a ringbuf (or a map) for updates from a kprobe on bpf_ksym_add is probably the best way to reduce work here. We can detect dropped updates and fall back to full parsing if it comes to that.

[fabled]

Ultimately, I think having a ringbuf (or a map) for updates from a kprobe on bpf_ksym_add is probably the best way to reduce work here. We can detect dropped updates and fall back to full parsing if it comes to that.

Could you open an issue to track this instead of this merged PR. I suspect your use case is quite special from most other use cases so its not immediate issue. But the solution would require quite a bit of work to make it robust and work without too much overhead. I think the design and further points should be discussed in a new issue. Thanks.

[bobrik]

I made #1151 for this.