Re: [PATCH v7 3/3] perf-stat: enable counting events for BPF programs
From: Song Liu
Date: Mon Jan 18 2021 - 19:49:22 EST
Hi Arnaldo,
> On Jan 18, 2021, at 11:38 AM, Arnaldo Carvalho de Melo <acme@xxxxxxxxxx> wrote:
>
> Em Tue, Dec 29, 2020 at 01:42:14PM -0800, Song Liu escreveu:
>> Introduce perf-stat -b option, which counts events for BPF programs, like:
>>
>> [root@localhost ~]# ~/perf stat -e ref-cycles,cycles -b 254 -I 1000
>> 1.487903822 115,200 ref-cycles
>> 1.487903822 86,012 cycles
>> 2.489147029 80,560 ref-cycles
>> 2.489147029 73,784 cycles
>> 3.490341825 60,720 ref-cycles
>> 3.490341825 37,797 cycles
>> 4.491540887 37,120 ref-cycles
>> 4.491540887 31,963 cycles
>>
>> The example above counts cycles and ref-cycles of BPF program of id 254.
>> This is similar to bpftool-prog-profile command, but more flexible.
>
> So trying to get back to this after vacation:
>
> [root@five ~]# perf stat -vvv -e cycles -b 103
> Control descriptor is not initialized
> libbpf: elf: skipping unrecognized data section(9) .eh_frame
> libbpf: elf: skipping relo section(15) .rel.eh_frame for section(9) .eh_frame
> libbpf: load bpf program failed: Invalid argument
> libbpf: -- BEGIN DUMP LOG ---
> libbpf:
> Cannot recursively attach
> processed 0 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0
>
> libbpf: -- END LOG --
> libbpf: failed to load program 'fentry_XXX'
> libbpf: failed to load object 'bpf_prog_profiler_bpf'
> libbpf: failed to load BPF skeleton 'bpf_prog_profiler_bpf': -4007
> bpf_prog_profiler_bpf__load failed
> [root@five ~]#
>
> [root@five perf]# tools/bpf/runqslower/.output/
> bpftool/ libbpf/ runqslower
> [root@five perf]# tools/bpf/runqslower/.output/runqslower
> libbpf: elf: skipping unrecognized data section(10) .eh_frame
> libbpf: elf: skipping relo section(17) .rel.eh_frame for section(10) .eh_frame
> Tracing run queue latency higher than 10000 us
> TIME COMM PID LAT(us)
>
> [root@five ~]# bpftool prog
> 6: tracing name dump_bpf_map tag e54c922dfa54f65f gpl
> loaded_at 2021-01-15T11:14:38-0300 uid 0
> xlated 256B jited 154B memlock 4096B map_ids 3
> btf_id 6
> 8: tracing name dump_bpf_prog tag 4cb5558b902ee92e gpl
> loaded_at 2021-01-15T11:14:38-0300 uid 0
> xlated 520B jited 301B memlock 4096B map_ids 3
> btf_id 6
> 80: cgroup_device tag 8b9c33f36f812014 gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 744B jited 447B memlock 4096B
> 81: cgroup_skb tag 6deef7357e7b4530 gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 64B jited 54B memlock 4096B
> 82: cgroup_skb tag 6deef7357e7b4530 gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 64B jited 54B memlock 4096B
> 83: cgroup_device tag ee0e253c78993a24 gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 416B jited 255B memlock 4096B
> 84: cgroup_device tag e3dbd137be8d6168 gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 504B jited 309B memlock 4096B
> 85: cgroup_skb tag 6deef7357e7b4530 gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 64B jited 54B memlock 4096B
> 86: cgroup_skb tag 6deef7357e7b4530 gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 64B jited 54B memlock 4096B
> 87: cgroup_device tag c8b47a902f1cc68b gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 464B jited 288B memlock 4096B
> 88: cgroup_device tag 0ecd07b7b633809f gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 496B jited 307B memlock 4096B
> 89: cgroup_skb tag 6deef7357e7b4530 gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 64B jited 54B memlock 4096B
> 90: cgroup_skb tag 6deef7357e7b4530 gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 64B jited 54B memlock 4096B
> 91: cgroup_skb tag 6deef7357e7b4530 gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 64B jited 54B memlock 4096B
> 92: cgroup_skb tag 6deef7357e7b4530 gpl
> loaded_at 2021-01-17T18:35:22-0300 uid 0
> xlated 64B jited 54B memlock 4096B
> 100: tracing name handle__sched_w tag 00ba1f1d332f5a57 gpl
> loaded_at 2021-01-18T16:34:00-0300 uid 0
> xlated 152B jited 93B memlock 4096B map_ids 11,9
> btf_id 248
> 102: tracing name handle__sched_w tag 00ba1f1d332f5a57 gpl
> loaded_at 2021-01-18T16:34:00-0300 uid 0
> xlated 152B jited 93B memlock 4096B map_ids 11,9
> btf_id 248
> 103: tracing name handle__sched_s tag a4ac42153fd49be2 gpl
> loaded_at 2021-01-18T16:34:00-0300 uid 0
> xlated 560B jited 332B memlock 4096B map_ids 11,9,10
> btf_id 248
> [root@five ~]# perf stat -vvv -e cycles -b 92
> Control descriptor is not initialized
> libbpf: elf: skipping unrecognized data section(9) .eh_frame
> libbpf: elf: skipping relo section(15) .rel.eh_frame for section(9) .eh_frame
> prog FD 3 doesn't have valid btf
> Failed to get program name for bpf prog 92. Does it have BTF?
> [root@five ~]# perf stat -vvv -e cycles -b 103
> Control descriptor is not initialized
> libbpf: elf: skipping unrecognized data section(9) .eh_frame
> libbpf: elf: skipping relo section(15) .rel.eh_frame for section(9) .eh_frame
> libbpf: load bpf program failed: Invalid argument
> libbpf: -- BEGIN DUMP LOG ---
> libbpf:
> Cannot recursively attach
> processed 0 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0
>
> libbpf: -- END LOG --
> libbpf: failed to load program 'fentry_XXX'
> libbpf: failed to load object 'bpf_prog_profiler_bpf'
> libbpf: failed to load BPF skeleton 'bpf_prog_profiler_bpf': -4007
> bpf_prog_profiler_bpf__load failed
> [root@five ~]# perf stat -vvv -e cycles -b 102
> Control descriptor is not initialized
> libbpf: elf: skipping unrecognized data section(9) .eh_frame
> libbpf: elf: skipping relo section(15) .rel.eh_frame for section(9) .eh_frame
> libbpf: load bpf program failed: Invalid argument
> libbpf: -- BEGIN DUMP LOG ---
> libbpf:
> Cannot recursively attach
> processed 0 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0
>
> libbpf: -- END LOG --
> libbpf: failed to load program 'fentry_XXX'
> libbpf: failed to load object 'bpf_prog_profiler_bpf'
> libbpf: failed to load BPF skeleton 'bpf_prog_profiler_bpf': -4007
> bpf_prog_profiler_bpf__load failed
> [root@five ~]#
> [root@five ~]# perf stat -vvv -e cycles -b 6
> Control descriptor is not initialized
> libbpf: elf: skipping unrecognized data section(9) .eh_frame
> libbpf: elf: skipping relo section(15) .rel.eh_frame for section(9) .eh_frame
> libbpf: load bpf program failed: Invalid argument
> libbpf: -- BEGIN DUMP LOG ---
> libbpf:
> Cannot recursively attach
> processed 0 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0
>
> libbpf: -- END LOG --
> libbpf: failed to load program 'fentry_XXX'
> libbpf: failed to load object 'bpf_prog_profiler_bpf'
> libbpf: failed to load BPF skeleton 'bpf_prog_profiler_bpf': -4007
> bpf_prog_profiler_bpf__load failed
> [root@five ~]#
>
> So no more segfaults, but still something to look at, I'm pushing my
> local perf/core to tmp.perf/core, please take a look.
>
> - Arnaldo
We are looking at two issues:
1. Cannot recursively attach;
2. prog FD 3 doesn't have valid btf.
#1 was caused by the verifier disallowing attaching fentry/fexit program
to program with type BPF_PROG_TYPE_TRACING (in bpf_check_attach_target).
This constraint was added when we only had fentry/fexit in the TRACING
type. We have extended the TRACING type to many other use cases, like
"tp_btf/", "fmod_ret" and "iter/". Therefore, it is good time to revisit
this constraint. I will work on this.
For #2, we require the target program to have BTF. I guess we won't remove
this requirement.
While I work on improving #1, could you please test with some kprobe
programs? For example, we can use fileslower.py from bcc.
Thanks,
Song
[...]