Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
From:   Song Liu <songliubraving@fb.com>
To:     Arnaldo Carvalho de Melo <acme@kernel.org>
CC:     open list <linux-kernel@vger.kernel.org>,
        Peter Zijlstra <peterz@infradead.org>,
        Ingo Molnar <mingo@redhat.com>,
        Alexander Shishkin <alexander.shishkin@linux.intel.com>,
        Namhyung Kim <namhyung@kernel.org>,
        Mark Rutland <mark.rutland@arm.com>,
        Jiri Olsa <jolsa@redhat.com>,
        "Kernel Team" <Kernel-team@fb.com>
Subject: Re: [PATCH v7 3/3] perf-stat: enable counting events for BPF programs
Thread-Topic: [PATCH v7 3/3] perf-stat: enable counting events for BPF
 programs
Thread-Index: AQHW3iuRYm1YXRRzOkq8jjAuk5Kmsqot5piAgABWngCAAOYQgIAAAxqAgAAeVYCAAFpfAA==
Date:   Tue, 19 Jan 2021 21:54:50 +0000
Message-ID: <417ABE57-E527-4944-BE16-35AB92D071E9@fb.com>
References: <20201229214214.3413833-1-songliubraving@fb.com>
 <20201229214214.3413833-4-songliubraving@fb.com>
 <20210118193817.GG12699@kernel.org>
 <379919CC-594F-40C5-A10E-97E048F73AE2@fb.com>
 <20210119143143.GJ12699@kernel.org> <20210119144249.GK12699@kernel.org>
 <20210119163123.GM12699@kernel.org>
In-Reply-To: <20210119163123.GM12699@kernel.org>
Accept-Language: en-US
Content-Language: en-US
Content-Type: text/plain; charset="us-ascii"
Content-ID: <053F96DABC8B10499CB79C75C357BFED@namprd15.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-MS-Exchange-CrossTenant-Network-Message-Id: 89f8d7a6-8ff3-4359-3971-08d8bcc4d8ad
X-MS-Exchange-CrossTenant-originalarrivaltime: 19 Jan 2021 21:54:50.7188
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: 8ae927fe-1255-47a7-a2af-5f3a069daaa2
X-MS-Exchange-CrossTenant-mailboxtype: HOSTED
X-MS-Exchange-CrossTenant-userprincipalname: QHsQyada/YKJuNquUjcsVkoCIK1NfHInbukyOobxW5QMWAoIKggJKrjYEimdyFWecU62daEHkzBwdjAg1sNj2A==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BYAPR15MB2952
X-OriginatorOrg: fb.com
X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.343,18.0.737
 definitions=2021-01-19_12:2021-01-18,2021-01-19 signatures=0
X-Proofpoint-Spam-Details: rule=fb_default_notspam policy=fb_default score=0 lowpriorityscore=0
 clxscore=1015 suspectscore=0 spamscore=0 malwarescore=0 impostorscore=0
 priorityscore=1501 phishscore=0 mlxscore=0 bulkscore=0 mlxlogscore=999
 adultscore=0 classifier=spam adjust=0 reason=mlx scancount=1
 engine=8.12.0-2009150000 definitions=main-2101190117
X-FB-Internal: deliver
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org


> On Jan 19, 2021, at 8:31 AM, Arnaldo Carvalho de Melo <acme@kernel.org> w=
rote:
>=20
> Em Tue, Jan 19, 2021 at 11:42:49AM -0300, Arnaldo Carvalho de Melo escrev=
eu:
>> Em Tue, Jan 19, 2021 at 11:31:44AM -0300, Arnaldo Carvalho de Melo escre=
veu:
>>> Em Tue, Jan 19, 2021 at 12:48:19AM +0000, Song Liu escreveu:
>>>>> On Jan 18, 2021, at 11:38 AM, Arnaldo Carvalho de Melo <acme@kernel.o=
rg> wrote:
>>>> We are looking at two issues:
>>>> 1. Cannot recursively attach;
>>>> 2. prog FD 3 doesn't have valid btf.=20
>>=20
>>>> #1 was caused by the verifier disallowing attaching fentry/fexit progr=
am=20
>>>> to program with type BPF_PROG_TYPE_TRACING (in bpf_check_attach_target=
).=20
>>>> 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=
=20
>>>> "tp_btf/", "fmod_ret" and "iter/". Therefore, it is good time to revis=
it=20
>>>> this constraint. I will work on this.=20
>>=20
>>>> For #2, we require the target program to have BTF. I guess we won't re=
move
>>>> this requirement.
>>=20
>>>> While I work on improving #1, could you please test with some kprobe=20
>>>> programs? For example, we can use fileslower.py from bcc.=20
>>=20
>>> Sure, and please consider improving the error messages to state what yo=
u
>>> described above.
>>=20
>> Terminal 1:
>>=20
>> [root@five perf]# perf trace -e 5sec.c
>> ^C
>> [root@five perf]# cat 5sec.c
>> #include <bpf.h>
>>=20
>> #define NSEC_PER_SEC	1000000000L
>>=20
>> int probe(hrtimer_nanosleep, rqtp)(void *ctx, int err, long long sec)
>> {
>> 	return sec / NSEC_PER_SEC =3D=3D 5;
>> }
>>=20
>> license(GPL);
>> [root@five perf]# perf trace -e 5sec.c/max-stack=3D16/
>>     0.000 sleep/3739435 perf_bpf_probe:hrtimer_nanosleep(__probe_ip: -17=
43337312, rqtp: 5000000000)
>>                                       hrtimer_nanosleep ([kernel.kallsym=
s])
>>                                       common_nsleep ([kernel.kallsyms])
>>                                       __x64_sys_clock_nanosleep ([kernel=
.kallsyms])
>>                                       do_syscall_64 ([kernel.kallsyms])
>>                                       entry_SYSCALL_64_after_hwframe ([k=
ernel.kallsyms])
>>                                       __clock_nanosleep_2 (/usr/lib64/li=
bc-2.32.so)
>>=20
>>=20
>> Terminal 2:
>>=20
>> [root@five ~]# perf stat -e cycles -b 180 -I 1000
>> libbpf: elf: skipping unrecognized data section(9) .eh_frame
>> libbpf: elf: skipping relo section(15) .rel.eh_frame for section(9) .eh_=
frame
>> perf: util/bpf_counter.c:227: bpf_program_profiler__read: Assertion `ske=
l !=3D NULL' failed.
>> Aborted (core dumped)
>=20
> Out to lunch, will continue later, but this may help you figure this out
> till then :)
>=20
> Starting program: /root/bin/perf stat -e cycles -b 244 -I 1000
> [Thread debugging using libthread_db enabled]
> Using host libthread_db library "/lib64/libthread_db.so.1".
>=20
> Breakpoint 1, bpf_program_profiler_load_one (evsel=3D0xce02c0, prog_id=3D=
244) at util/bpf_counter.c:96
> 96	{
> (gdb) n
> 104		prog_fd =3D bpf_prog_get_fd_by_id(prog_id);
> (gdb)=20
> 105		if (prog_fd < 0) {
> (gdb)=20
> 109		counter =3D bpf_counter_alloc();
> (gdb)=20
> 110		if (!counter) {
> (gdb) n
> 115		skel =3D bpf_prog_profiler_bpf__open();
> (gdb) p counter
> $9 =3D (struct bpf_counter *) 0xce09e0
> (gdb) p *counter
> $10 =3D {skel =3D 0x0, list =3D {next =3D 0xce09e8, prev =3D 0xce09e8}}
> (gdb) p *counter
> $11 =3D {skel =3D 0x0, list =3D {next =3D 0xce09e8, prev =3D 0xce09e8}}
> (gdb) n
> libbpf: elf: skipping unrecognized data section(9) .eh_frame
> libbpf: elf: skipping relo section(15) .rel.eh_frame for section(9) .eh_f=
rame
> 116		if (!skel) {
> (gdb)=20
> 121		skel->rodata->num_cpu =3D evsel__nr_cpus(evsel);
> (gdb)=20
> 123		bpf_map__resize(skel->maps.events, evsel__nr_cpus(evsel));
> (gdb)=20
> 124		bpf_map__resize(skel->maps.fentry_readings, 1);
> (gdb)=20
> 125		bpf_map__resize(skel->maps.accum_readings, 1);
> (gdb)=20
> 127		prog_name =3D bpf_target_prog_name(prog_fd);
> (gdb)=20
> 128		if (!prog_name) {
> (gdb)=20
> 133		bpf_object__for_each_program(prog, skel->obj) {
> (gdb)=20
> 134			err =3D bpf_program__set_attach_target(prog, prog_fd, prog_name);
> (gdb)=20
> 135			if (err) {
> (gdb)=20
> 133		bpf_object__for_each_program(prog, skel->obj) {
> (gdb) p evsel
> $12 =3D (struct evsel *) 0xce02c0
> (gdb) p evsel->name
> $13 =3D 0xce04e0 "cycles"
> (gdb) n
> 134			err =3D bpf_program__set_attach_target(prog, prog_fd, prog_name);
> (gdb)=20
> 135			if (err) {
> (gdb)=20
> 133		bpf_object__for_each_program(prog, skel->obj) {
> (gdb)=20
> 141		set_max_rlimit();
> (gdb)=20
> 142		err =3D bpf_prog_profiler_bpf__load(skel);
> (gdb)=20
> 143		if (err) {
> (gdb)=20
> 148		assert(skel !=3D NULL);
> (gdb)=20
> 149		counter->skel =3D skel;
> (gdb)=20
> 150		list_add(&counter->list, &evsel->bpf_counter_list);
> (gdb) c
> Continuing.
>=20
> Breakpoint 4, bpf_program_profiler__install_pe (evsel=3D0xce02c0, cpu=3D0=
, fd=3D3) at util/bpf_counter.c:247
> 247	{
> (gdb) n
> 252		list_for_each_entry(counter, &evsel->bpf_counter_list, list) {
> (gdb)=20
> 253			skel =3D counter->skel;
> (gdb) watch counter->skel
> Hardware watchpoint 6: counter->skel
> (gdb) p counter->skel
> $14 =3D (void *) 0xce0a00
> (gdb) n
> 254			assert(skel !=3D NULL);
> (gdb) p skel
> $15 =3D (struct bpf_prog_profiler_bpf *) 0xce0a00
> (gdb) c
> Continuing.
>=20
> Hardware watchpoint 6: counter->skel
>=20
> Old value =3D (void *) 0xce0a00
> New value =3D (void *) 0x0
> 0x00000000005cf45e in bpf_program_profiler__install_pe (evsel=3D0xce02c0,=
 cpu=3D0, fd=3D3) at util/bpf_counter.c:252
> 252		list_for_each_entry(counter, &evsel->bpf_counter_list, list) {

So it was the list operation that set counter->skel to NULL? I am really co=
nfused...

Song

> (gdb) info b
> Num     Type           Disp Enb Address            What
> 1       breakpoint     keep y   0x00000000005ceb44 in bpf_program_profile=
r_load_one at util/bpf_counter.c:96
> 	breakpoint already hit 1 time
> 2       breakpoint     keep y   0x00000000005cef2e in bpf_program_profile=
r__enable at util/bpf_counter.c:192
> 3       breakpoint     keep y   0x00000000005cf00a in bpf_program_profile=
r__read at util/bpf_counter.c:208
> 4       breakpoint     keep y   0x00000000005cf3ba in bpf_program_profile=
r__install_pe at util/bpf_counter.c:247
> 	breakpoint already hit 1 time
> 5       breakpoint     keep y   0x00000000005ce8d4 in bpf_program_profile=
r__destroy at util/bpf_counter.c:47
> 6       hw watchpoint  keep y                      counter->skel
> 	breakpoint already hit 1 time
> (gdb) p evsel
> $16 =3D (struct evsel *) 0xce02c0
> (gdb) bt
> #0  0x00000000005cf45e in bpf_program_profiler__install_pe (evsel=3D0xce0=
2c0, cpu=3D0, fd=3D3) at util/bpf_counter.c:252
> #1  0x00000000005cf4f3 in bpf_counter__install_pe (evsel=3D0xce02c0, cpu=
=3D0, fd=3D3) at util/bpf_counter.c:276
> #2  0x00000000004f3ef1 in evsel__open_cpu (evsel=3D0xce02c0, cpus=3D0xce0=
500, threads=3D0xce75c0, start_cpu=3D0, end_cpu=3D1) at util/evsel.c:1792
> #3  0x00000000004f4aa7 in evsel__open_per_cpu (evsel=3D0xce02c0, cpus=3D0=
xce0500, cpu=3D0) at util/evsel.c:1996
> #4  0x000000000057f6f2 in create_perf_stat_counter (evsel=3D0xce02c0, con=
fig=3D0xa97860 <stat_config>, target=3D0xa97660 <target>, cpu=3D0) at util/=
stat.c:568
> #5  0x0000000000435d96 in __run_perf_stat (argc=3D0, argv=3D0x7fffffffdb6=
0, run_idx=3D0) at builtin-stat.c:790
> #6  0x00000000004367e3 in run_perf_stat (argc=3D0, argv=3D0x7fffffffdb60,=
 run_idx=3D0) at builtin-stat.c:1001
> #7  0x0000000000439e35 in cmd_stat (argc=3D0, argv=3D0x7fffffffdb60) at b=
uiltin-stat.c:2415
> #8  0x00000000004cf058 in run_builtin (p=3D0xaabe00 <commands+288>, argc=
=3D7, argv=3D0x7fffffffdb60) at perf.c:312
> #9  0x00000000004cf2c5 in handle_internal_command (argc=3D7, argv=3D0x7ff=
fffffdb60) at perf.c:364
> #10 0x00000000004cf40c in run_argv (argcp=3D0x7fffffffd9ac, argv=3D0x7fff=
ffffd9a0) at perf.c:408
> #11 0x00000000004cf7d8 in main (argc=3D7, argv=3D0x7fffffffdb60) at perf.=
c:538
> (gdb) n
> 261		return 0;
>=20