a few minutes delay to complete the pwru multi kprobe attachment

[vincentmli]

Hi,

I installed Ubuntu 20.04 and installed the Ubuntu PPA mainline kernel https://kernel.ubuntu.com/~kernel-ppa/mainline/v6.1.10/, when start pwru v0.0.8, it seems took a few minutes to complete the attachment

./pwru --filter-src-ip 10.169.72.114 --output-tuple --backend kprobe-multi

nothing output, wait for a few minutes, then finally got output like below

2023/02/09 04:15:42 Per cpu buffer size: 4096 bytes
2023/02/09 04:15:42 Attaching kprobes (via kprobe-multi)...
1517 / 1517 [-----------------------------------------------------------------------------------------------------------------------------] 100.00% ? p/s
2023/02/09 04:15:42 Attached (ignored 0)
2023/02/09 04:15:42 Listening for events..
               SKB    CPU          PROCESS                     FUNC

I run custom built 6.2 kernel on Centos 8 and same pwru, no such long delay attachment, looked the kernel config between Ubuntu PPA mainline 6.1.10 and Centos 8 custom 6.2 kernel, no difference in regard to FPROBE, KPROBE, FTRACE config. maybe Ubuntu PPA mainline 6.1.10 got more functions to attach?

[brb]

Hi, thanks for the issue. 8min is way too much for the kprobe-multi. On my laptop (the ArchLinux 6.1 kernel) it takes ~1 sec to attach to 1.4k functions.

Could you run pwru with strace -T -ttt -y -f -e bpf?

[vincentmli]

sure will do

[vincentmli]

this is the bpf syscall output, let me know if you need the full strace output

root@vli-2004:~# grep 'bpf' /tmp/pwru.txt 
30105 14:52:21.804762 bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0\34\0\0\0\34\0\0\0\3\0\0\0\0\0\0\0\0\0\0\2"..., btf_log_buf=NULL, btf_size=55, btf_log_size=0, btf_log_level=0}, 32) = 3<anon_inode:btf> <0.000034>
30105 14:52:21.805009 bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0\30\0\0\0\30\0\0\0\3\0\0\0\0\0\0\0\0\0\0\r"..., btf_log_buf=NULL, btf_size=51, btf_log_size=0, btf_log_level=0}, 32) = 3<anon_inode:btf> <0.000025>
30118 14:52:23.157715 bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_ARRAY, key_size=4, value_size=4, max_entries=1, map_flags=0, inner_map_fd=0</dev/pts/0>, map_name="feature_test", map_ifindex=0, btf_fd=0</dev/pts/0>, btf_key_type_id=0, btf_value_type_id=0}, 72) = 7<anon_inode:bpf-map> <0.000032>
30118 14:52:23.157927 bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_ARRAY, key_size=4, value_size=4, max_entries=1, map_flags=0, inner_map_fd=0</dev/pts/0>, map_name=".test", map_ifindex=0, btf_fd=0</dev/pts/0>, btf_key_type_id=0, btf_value_type_id=0}, 72) = 7<anon_inode:bpf-map> <0.000015>
30118 14:52:23.159553 bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0\250\1\0\0\250\1\0\0\4\1\0\0\1\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=708, btf_log_size=0, btf_log_level=0}, 32) = 7<anon_inode:btf> <0.000032>
30118 14:52:23.159625 bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_ARRAY, key_size=4, value_size=54, max_entries=1, map_flags=0, inner_map_fd=0</dev/pts/0>, map_name="cfg_map", map_ifindex=0, btf_fd=7<anon_inode:btf>, btf_key_type_id=3, btf_value_type_id=15}, 72) = 8<anon_inode:bpf-map> <0.000017>
30118 14:52:23.159716 bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_STACK_TRACE, key_size=4, value_size=400, max_entries=256, map_flags=0, inner_map_fd=0</dev/pts/0>, map_name="print_stack_map", map_ifindex=0, btf_fd=0</dev/pts/0>, btf_key_type_id=0, btf_value_type_id=0}, 72) = 7<anon_inode:bpf-map> <0.000059>
30118 14:52:23.159821 bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=8, map_flags=0, inner_map_fd=0</dev/pts/0>, map_name="events", map_ifindex=0, btf_fd=0</dev/pts/0>, btf_key_type_id=0, btf_value_type_id=0}, 72) = 9<anon_inode:bpf-map> <0.000018>
30118 14:52:23.160845 bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0T\1\0\0T\1\0\0002\r\0\0\1\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=3742, btf_log_size=0, btf_log_level=0}, 32) = 10<anon_inode:btf> <0.000021>
30119 14:53:43.407658 bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=6, insns=0xc001df4000, 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</dev/pts/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</dev/pts/0>}, 144) = 11<anon_inode:bpf-prog> <0.000109>
30119 14:53:43.408082 bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=982, insns=0xc0032b8000, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(6, 1, 10), prog_flags=0, prog_name="kprobe_skb_1", prog_ifindex=0, expected_attach_type=0x2a /* BPF_??? */, prog_btf_fd=10<anon_inode:btf>, func_info_rec_size=8, func_info=0xc001ffe000, func_info_cnt=1, line_info_rec_size=16, line_info=0xc000137500, line_info_cnt=237, attach_btf_id=0, attach_prog_fd=0</dev/pts/0>}, 144) = 11<anon_inode:bpf-prog> <0.001539>
30119 14:53:43.409900 bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0T\1\0\0T\1\0\0002\r\0\0\1\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=3742, btf_log_size=0, btf_log_level=0}, 32) = 10<anon_inode:btf> <0.000027>
30108 14:54:58.689417 bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=982, insns=0xc0034ce000, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(6, 1, 10), prog_flags=0, prog_name="kprobe_skb_2", prog_ifindex=0, expected_attach_type=0x2a /* BPF_??? */, prog_btf_fd=10<anon_inode:btf>, func_info_rec_size=8, func_info=0xc001ffe140, func_info_cnt=1, line_info_rec_size=16, line_info=0xc000138a00, line_info_cnt=237, attach_btf_id=0, attach_prog_fd=0</dev/pts/0>}, 144) = 12<anon_inode:bpf-prog> <0.002278>
30108 14:54:58.692117 bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0T\1\0\0T\1\0\0002\r\0\0\1\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=3742, btf_log_size=0, btf_log_level=0}, 32) = 10<anon_inode:btf> <0.000034>
30119 14:56:05.844620 bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=982, insns=0xc00317a000, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(6, 1, 10), prog_flags=0, prog_name="kprobe_skb_3", prog_ifindex=0, expected_attach_type=0x2a /* BPF_??? */, prog_btf_fd=10<anon_inode:btf>, func_info_rec_size=8, func_info=0xc00001a0c0, func_info_cnt=1, line_info_rec_size=16, line_info=0xc000137500, line_info_cnt=237, attach_btf_id=0, attach_prog_fd=0</dev/pts/0>}, 144) = 13<anon_inode:bpf-prog> <0.001464>
30119 14:56:05.846425 bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0T\1\0\0T\1\0\0002\r\0\0\1\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=3742, btf_log_size=0, btf_log_level=0}, 32) = 10<anon_inode:btf> <0.000036>
30108 14:57:12.766168 bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=982, insns=0xc00d074000, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(6, 1, 10), prog_flags=0, prog_name="kprobe_skb_4", prog_ifindex=0, expected_attach_type=0x2a /* BPF_??? */, prog_btf_fd=10<anon_inode:btf>, func_info_rec_size=8, func_info=0xc00025d200, func_info_cnt=1, line_info_rec_size=16, line_info=0xc000138a00, line_info_cnt=237, attach_btf_id=0, attach_prog_fd=0</dev/pts/0>}, 144) = 14<anon_inode:bpf-prog> <0.001508>
30108 14:57:12.768141 bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0T\1\0\0T\1\0\0002\r\0\0\1\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=3742, btf_log_size=0, btf_log_level=0}, 32) = 10<anon_inode:btf> <0.000038>
30115 14:58:18.934537 bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=982, insns=0xc002c48000, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(6, 1, 10), prog_flags=0, prog_name="kprobe_skb_5", prog_ifindex=0, expected_attach_type=0x2a /* BPF_??? */, prog_btf_fd=10<anon_inode:btf>, func_info_rec_size=8, func_info=0xc00025d240, func_info_cnt=1, line_info_rec_size=16, line_info=0xc000137500, line_info_cnt=237, attach_btf_id=0, attach_prog_fd=0</dev/pts/0>}, 144) = 15<anon_inode:bpf-prog> <0.001446>
30115 14:58:18.936418 bpf(BPF_MAP_UPDATE_ELEM, {map_fd=8<anon_inode:bpf-map>, key=0xc00001a0c0, value=0xc00001a140, flags=BPF_ANY}, 32) = 0 <0.000017>
30115 14:58:18.936808 bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=2, insns=0xc001e504b0, license="MIT", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(6, 1, 10), prog_flags=0, prog_name="probe_kpm_link", prog_ifindex=0, expected_attach_type=0x2a /* BPF_??? */, prog_btf_fd=0</dev/pts/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</dev/pts/0>}, 144) = 10<anon_inode:bpf-prog> <0.000041>

[brb]

Thanks. Could you try again, but this time without -e bpf?

[vincentmli]

pwru-1.txt
pwru-2.txt
pwru-3.txt

[vincentmli]

strace too big, attached split files

[brb]

@vincentmli Could it be that the system is under heavy load?

[vincentmli]

@brb this is a lab unit with almost nothing going on, almost idle system

[brb]

Do you encounter the same issue when running with v0.0.7?

[vincentmli]

let me try v0.0.7

[vincentmli]

same delay with v0.0.7. I wonder what is so special with https://kernel.ubuntu.com/~kernel-ppa/mainline/v6.1.10/ mainline build on Ubuntu 20.04, I installed the Ubuntu PPA kernel because I want to test out XDP SYNPROXY acceleration that requires kernel version supporting that feature. these are the packages

Test amd64/build succeeded (rc=0, on=amd64, time=0:11:50, log=[amd64/log](https://kernel.ubuntu.com/~kernel-ppa/mainline/v6.1.10/amd64/log))
  [amd64/linux-headers-6.1.10-060110-generic_6.1.10-060110.202302060840_amd64.deb](https://kernel.ubuntu.com/~kernel-ppa/mainline/v6.1.10/amd64/linux-headers-6.1.10-060110-generic_6.1.10-060110.202302060840_amd64.deb)
  [amd64/linux-headers-6.1.10-060110_6.1.10-060110.202302060840_all.deb](https://kernel.ubuntu.com/~kernel-ppa/mainline/v6.1.10/amd64/linux-headers-6.1.10-060110_6.1.10-060110.202302060840_all.deb)
  [amd64/linux-image-unsigned-6.1.10-060110-generic_6.1.10-060110.202302060840_amd64.deb](https://kernel.ubuntu.com/~kernel-ppa/mainline/v6.1.10/amd64/linux-image-unsigned-6.1.10-060110-generic_6.1.10-060110.202302060840_amd64.deb)
  [amd64/linux-modules-6.1.10-060110-generic_6.1.10-060110.202302060840_amd64.deb](https://kernel.ubuntu.com/~kernel-ppa/mainline/v6.1.10/amd64/linux-modules-6.1.10-060110-generic_6.1.10-060110.202302060840_amd64.deb)

I only have failure install linux-headers-6.1.10-060110-generic_6.1.10-060110.202302060840_amd64.deb but that seems irrelevant to me

dpkg -i linux-headers-6.1.10-060110-generic_6.1.10-060110.202302060840_amd64.deb
Selecting previously unselected package linux-headers-6.1.10-060110-generic.
(Reading database ... 222107 files and directories currently installed.)
Preparing to unpack linux-headers-6.1.10-060110-generic_6.1.10-060110.202302060840_amd64.deb ...
Unpacking linux-headers-6.1.10-060110-generic (6.1.10-060110.202302060840) ...
dpkg: dependency problems prevent configuration of linux-headers-6.1.10-060110-generic:
 linux-headers-6.1.10-060110-generic depends on libc6 (>= 2.34); however:
  Version of libc6:amd64 on system is 2.31-0ubuntu9.9.
 linux-headers-6.1.10-060110-generic depends on libssl3 (>= 3.0.0); however:
  Package libssl3 is not installed.

dpkg: error processing package linux-headers-6.1.10-060110-generic (--install):
 dependency problems - leaving unconfigured
Errors were encountered while processing:
 linux-headers-6.1.10-060110-generic

[vincentmli]

@brb when you have time, you could easily reproduce this issue with fresh Ubuntu 20.04 install, and then install the Ubuntu PPA mainline kernel, I am just curious what is delaying pwru.

[brb]

@vincentmli Do you have a Vagrant vbox image I can run?

[vincentmli]

sorry I am not familiar with Vagrant, I use VM in ESXi/KVM environment, and my KVM server is down at the moment from a remote site :)

[brb]

@vincentmli Are you still experiencing the issue?

[brb]

Fixed by #220.