I want to count tcp rtt information through kprobe tcp_rcv_established and wrote the following ebpf program, but bpf_perf_event_output returns -22, I can't read any events from ebpf map. What causes bpf_perf_event_output to return -22?
#include "vmlinux.h"
#include "bpf_tracing.h"
#include "bpf_helpers.h"
char __license[] SEC("license") = "Dual MIT/GPL";
#define AF_INET 2
#define AF_INET6 10
struct rtt_info {
u16 sport;
u16 dport;
u32 saddr;
u32 daddr;
u8 saddr6[16];
u8 daddr6[16];
u16 family;
u32 latency;
};
struct {
__uint(type, BPF_MAP_TYPE_PERF_EVENT_ARRAY);
} tcp_rtt_events SEC(".maps");
const struct rtt_info *unused __attribute__((unused));
SEC("kprobe/tcp_rcv_established")
int kprobe__tcp_rcv_established(struct pt_regs *ctx)
{
bpf_trace_printk("tcp_rcv_established called\n", sizeof("tcp_rcv_established called\n"));
struct sock *sk = (struct sock *)PT_REGS_PARM1(ctx);
if (sk == NULL) {
return 0;
}
struct tcp_sock *ts = (struct tcp_sock *)sk;
u32 srtt;
bpf_probe_read_kernel(&srtt, sizeof(srtt), &ts->srtt_us);
bpf_trace_printk("srtt %d\n", sizeof("srtt %d\n"), srtt);
const struct inet_sock *inet = (struct inet_sock *)sk;
struct rtt_info event = {0};
event.latency = srtt >> 3;
bpf_trace_printk("latency %d\n", sizeof("latency %d\n"), event.latency);
bpf_probe_read_kernel(&event.sport, sizeof(event.sport), (void *)&inet->inet_sport);
bpf_probe_read_kernel(&event.dport, sizeof(event.dport), (void *)&inet->inet_dport);
bpf_probe_read_kernel(&event.family, sizeof(event.family), (void *)&sk->__sk_common.skc_family);
if (event.family == AF_INET6) {
bpf_probe_read_kernel(&event.saddr6, sizeof(event.saddr6),
(void *)&sk->__sk_common.skc_v6_rcv_saddr.in6_u.u6_addr8);
bpf_probe_read_kernel(&event.daddr6, sizeof(event.daddr6),
(void *)&sk->__sk_common.skc_v6_daddr.in6_u.u6_addr8);
} else {
bpf_probe_read_kernel(&event.saddr, sizeof(event.saddr), (void *)&inet->inet_saddr);
bpf_probe_read_kernel(&event.daddr, sizeof(event.daddr), (void *)&inet->inet_daddr);
}
long ret = bpf_perf_event_output(ctx, &tcp_rtt_events, BPF_F_CURRENT_CPU, &event, sizeof(event));
bpf_trace_printk("output event: ret %ld, latency %d\n", sizeof("output event: ret %ld, latency %d\n"), ret, event.latency);
return 0;
}
cat /sys/kernel/debug/tracing/trace_pipe
<idle>-0 [008] ..s. 4058805.485734: 0: tcp_rcv_established called
<idle>-0 [008] ..s. 4058805.485742: 0: srtt 14256
<idle>-0 [008] ..s. 4058805.485742: 0: latency 1782
<idle>-0 [008] ..s. 4058805.485743: 0: output event: ret -22, latency 1782
<idle>-0 [008] ..s. 4058805.494305: 0: tcp_rcv_established called
<idle>-0 [008] .Ns. 4058805.494310: 0: srtt 14256
<idle>-0 [008] .Ns. 4058805.494311: 0: latency 1782
<idle>-0 [008] .Ns. 4058805.494311: 0: output event: ret -22, latency 1782
<idle>-0 [008] ..s. 4058805.495349: 0: tcp_rcv_established called
<idle>-0 [008] .Ns. 4058805.495353: 0: srtt 14256
<idle>-0 [008] .Ns. 4058805.495353: 0: latency 1782
<idle>-0 [008] .Ns. 4058805.495354: 0: output event: ret -22, latency 1782
I tried to simplify the program, but bpf_perf_event_output still always returns -22 in the modified program.
#include "vmlinux.h"
#include "bpf_tracing.h"
#include "bpf_helpers.h"
char __license[] SEC("license") = "Dual MIT/GPL";
struct {
__uint(type, BPF_MAP_TYPE_PERF_EVENT_ARRAY);
} tcp_rtt_events SEC(".maps");
//const struct rtt_info *unused __attribute__((unused));
SEC("kprobe/tcp_rcv_established")
int kprobe__tcp_rcv_established(struct pt_regs *ctx)
{
bpf_trace_printk("tcp_rcv_established called\n", sizeof("tcp_rcv_established called\n"));
struct sock *sk = (struct sock *)PT_REGS_PARM1(ctx);
if (sk == NULL) {
return 0;
}
struct tcp_sock *ts = (struct tcp_sock *)sk;
u32 srtt;
bpf_probe_read_kernel(&srtt, sizeof(srtt), &ts->srtt_us);
bpf_trace_printk("srtt %d\n", sizeof("srtt %d\n"), srtt);
long ret = bpf_perf_event_output(ctx, &tcp_rtt_events, BPF_F_CURRENT_CPU, &srtt, sizeof(srtt));
bpf_trace_printk("output event: ret %ld, latency %d\n", sizeof("output event: ret %ld, latency %d\n"), ret, srtt);
return 0;
}
<idle>-0 [004] ..s. 4058699.193256: 0: tcp_rcv_established called
<idle>-0 [004] ..s. 4058699.193264: 0: srtt 14256
<idle>-0 [004] ..s. 4058699.193265: 0: output event: ret -22, latency 14256
<idle>-0 [004] ..s. 4058699.202467: 0: tcp_rcv_established called
<idle>-0 [004] ..s. 4058699.202475: 0: srtt 14256
<idle>-0 [004] ..s. 4058699.202475: 0: output event: ret -22, latency 14256
<idle>-0 [004] ..s. 4058699.208232: 0: tcp_rcv_established called
<idle>-0 [004] ..s. 4058699.208239: 0: srtt 14256
<idle>-0 [004] ..s. 4058699.208240: 0: output event: ret -22, latency 14256
I want to know what is wrong in this code...
strace -f -ebpf ./tcp_rtt
linux 5.4.203, cilium/ebpf 0.12.2 llvmorg-15.0.7
strace: Process 2790008 attached
strace: Process 2790009 attached
strace: Process 2790010 attached
strace: Process 2790011 attached
[pid 2790007] 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, map_name="", map_ifindex=0, btf_fd=0, btf_key_type_id=0, btf_value_type_id=0, btf_vmlinux_value_type_id=0, map_extra=0}, 72) = -1 EPERM (Operation not permitted)
strace: Process 2790012 attached
strace: Process 2790013 attached
[pid 2790010] 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, map_name="feature_test", map_ifindex=0, btf_fd=0, btf_key_type_id=0, btf_value_type_id=0, btf_vmlinux_value_type_id=0, map_extra=0}, 72) = 3
[pid 2790010] 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, map_name=".test", map_ifindex=0, btf_fd=0, btf_key_type_id=0, btf_value_type_id=0, btf_vmlinux_value_type_id=0, map_extra=0}, 72) = 3
[pid 2790010] bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_ARRAY, key_size=4, value_size=84, max_entries=1, map_flags=BPF_F_RDONLY_PROG, inner_map_fd=0, map_name=".rodata.str1.1", map_ifindex=0, btf_fd=0, btf_key_type_id=0, btf_value_type_id=0, btf_vmlinux_value_type_id=0, map_extra=0}, 72) = 3
[pid 2790010] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0xc00009af00, value=0xc00009e480, flags=BPF_ANY}, 32) = 0
[pid 2790010] bpf(BPF_MAP_FREEZE, {map_fd=3}, 4) = 0
[pid 2790010] bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=10, map_flags=0, inner_map_fd=0, map_name="tcp_rtt_events", map_ifindex=0, btf_fd=0, btf_key_type_id=0, btf_value_type_id=0, btf_vmlinux_value_type_id=0, map_extra=0}, 72) = 4
[pid 2790010] bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0\20\0\0\0\20\0\0\0\1\0\0\0\0\0\0\0\0\0\0\1"..., btf_log_buf=NULL, btf_size=41, btf_log_size=0, btf_log_level=0}, 32) = 8
[pid 2790010] 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\1\0\0\0\0\0\0\f"..., btf_log_buf=NULL, btf_size=51, btf_log_size=0, btf_log_level=0}, 32) = 8
[pid 2790010] 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\1\0\0\0\1\0\0\f"..., btf_log_buf=NULL, btf_size=51, btf_log_size=0, btf_log_level=0}, 32) = -1 EINVAL (Invalid argument)
[pid 2790010] 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\6\0\0\0\0\0\0\0\1\0\0\23"..., btf_log_buf=NULL, btf_size=54, btf_log_size=0, btf_log_level=0}, 32) = -1 EINVAL (Invalid argument)
[pid 2790010] bpf(BPF_BTF_LOAD, {btf="\237\353\1\0\30\0\0\0\0\0\0\0T\1\0\0T\1\0\0\222\6\0\0\v\6\0\0\0\0\0\f"..., btf_log_buf=NULL, btf_size=2046, btf_log_size=0, btf_log_level=0}, 32) = 8
[pid 2790010] bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=6, insns=0xc0000cc1e0, 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}, 144) = -1 EINVAL (Invalid argument)
[pid 2790010] bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=90, insns=0xc000198000, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(5, 4, 203), prog_flags=0, prog_name="kprobe__tcp_rcv", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, prog_btf_fd=8, func_info_rec_size=8, func_info=0xc0000acf40, func_info_cnt=1, line_info_rec_size=16, line_info=0xc0000ea400, line_info_cnt=39, attach_btf_id=0, attach_prog_fd=0, fd_array=NULL}, 144) = 9
[pid 2790010] bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=2, insns=0xc00009b7d0, license="MIT", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(5, 4, 203), prog_flags=0, prog_name="probe_bpf_perf_", 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}, 144) = -1 EAGAIN (Resource temporarily unavailable)
[pid 2790010] --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=2790007, si_uid=0} ---
[pid 2790010] bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=2, insns=0xc00009b7d0, license="MIT", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(5, 4, 203), prog_flags=0, prog_name="probe_bpf_perf_", 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}, 144) = 8
[pid 2790010] bpf(BPF_LINK_CREATE, {link_create={prog_fd=8, target_fd=0, attach_type=BPF_PERF_EVENT, flags=0, perf_event={bpf_cookie=0}}}, 48) = -1 EINVAL (Invalid argument)
[pid 2790010] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=21, key=0xc00009b80c, value=0xc00009b808, flags=BPF_ANY}, 32) = 0
[pid 2790010] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=21, key=0xc00009b814, value=0xc00009b810, flags=BPF_ANY}, 32) = 0
[pid 2790010] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=21, key=0xc00009b81c, value=0xc00009b818, flags=BPF_ANY}, 32) = 0
[pid 2790010] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=21, key=0xc00009b824, value=0xc00009b820, flags=BPF_ANY}, 32) = 0
[pid 2790010] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=21, key=0xc00009b82c, value=0xc00009b828, flags=BPF_ANY}, 32) = 0
[pid 2790010] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=21, key=0xc00009b834, value=0xc00009b830, flags=BPF_ANY}, 32) = 0
[pid 2790010] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=21, key=0xc00009b83c, value=0xc00009b838, flags=BPF_ANY}, 32) = 0
[pid 2790010] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=21, key=0xc00009b844, value=0xc00009b840, flags=BPF_ANY}, 32) = 0
[pid 2790010] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=21, key=0xc00009b84c, value=0xc00009b848, flags=BPF_ANY}, 32) = 0
[pid 2790010] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=21, key=0xc00009b854, value=0xc00009b850, flags=BPF_ANY}, 32) = 0
2023/10/23 19:35:01 Listening for events..
^Cstrace: Process 2790007 detached
strace: Process 2790008 detached
strace: Process 2790009 detached
strace: Process 2790010 detached
strace: Process 2790011 detached
strace: Process 2790012 detached
strace: Process 2790013 detached
linux 5.4.119, cilium/ebpf 0.12.2 llvmorg-15.0.7
strace: Process 24096 attached
strace: Process 24097 attached
strace: Process 24098 attached
strace: Process 24099 attached
strace: Process 24100 attached
[pid 24095] 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, map_name="", map_ifindex=0}, 72) = -1 EPERM (Operation not permitted)
[pid 24095] --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=24095, si_uid=0} ---
strace: Process 24101 attached
[pid 24099] 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, map_name="feature_test", map_ifindex=0}, 72) = 3
[pid 24099] 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, map_name=".test", map_ifindex=0}, 72) = 3
[pid 24099] bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_ARRAY, key_size=4, value_size=84, max_entries=1, map_flags=0x80 /* BPF_F_??? */, inner_map_fd=0, map_name=".rodata.str1.1", map_ifindex=0}, 72) = 3
[pid 24099] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=3, key=0xc0000a7018, value=0xc00008c4e0, flags=BPF_ANY}, 32) = 0
[pid 24099] bpf(0x16 /* BPF_??? */, 0xc0000d31dc, 4) = 0
[pid 24099] bpf(BPF_MAP_CREATE, {map_type=BPF_MAP_TYPE_PERF_EVENT_ARRAY, key_size=4, value_size=4, max_entries=4, map_flags=0, inner_map_fd=0, map_name="tcp_rtt_events", map_ifindex=0}, 72) = 4
[pid 24099] bpf(BPF_BTF_LOAD, 0xc0001a2b18, 32) = 8
[pid 24099] bpf(BPF_BTF_LOAD, 0xc0001a2c28, 32) = 8
[pid 24099] bpf(BPF_BTF_LOAD, 0xc0001a2b68, 32) = 8
[pid 24099] bpf(BPF_BTF_LOAD, 0xc0001a2b68, 32) = -1 EINVAL (Invalid argument)
[pid 24099] bpf(BPF_BTF_LOAD, 0xc0001a2cb0, 32) = 8
[pid 24099] bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=6, insns=0xc0000f0150, 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}, 144) = 9
[pid 24099] bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=90, insns=0xc0001ae000, license="GPL", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(5, 4, 119), prog_flags=0, prog_name="kprobe__tcp_rcv", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS, ...}, 144) = 9
[pid 24099] bpf(BPF_PROG_LOAD, {prog_type=BPF_PROG_TYPE_KPROBE, insn_cnt=2, insns=0xc0000a78f0, license="MIT", log_level=0, log_size=0, log_buf=NULL, kern_version=KERNEL_VERSION(5, 4, 119), prog_flags=0, prog_name="probe_bpf_perf_", prog_ifindex=0, expected_attach_type=BPF_CGROUP_INET_INGRESS}, 144) = 8
[pid 24099] bpf(0x1c /* BPF_??? */, 0xc0001a3a08, 48) = -1 EINVAL (Invalid argument)
[pid 24099] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=15, key=0xc0000120d4, value=0xc0000120d0, flags=BPF_ANY}, 32) = 0
[pid 24099] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=15, key=0xc0000120dc, value=0xc0000120d8, flags=BPF_ANY}, 32) = 0
[pid 24099] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=15, key=0xc0000120e4, value=0xc0000120e0, flags=BPF_ANY}, 32) = 0
[pid 24099] bpf(BPF_MAP_UPDATE_ELEM, {map_fd=15, key=0xc0000120ec, value=0xc0000120e8, flags=BPF_ANY}, 32) = 0
2023/10/25 16:52:20 Listening for events..
^Cstrace: Process 24095 detached
strace: Process 24096 detached
strace: Process 24097 detached
strace: Process 24098 detached
strace: Process 24099 detached
strace: Process 24100 detached
strace: Process 24101 detached
2023/10/25 16:52:22 Received signal, exiting program..