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: AQHW3iuRYm1YXRRzOkq8jjAuk5Kmsqot5piAgABWngA=
Date:   Tue, 19 Jan 2021 00:48:19 +0000
Message-ID: <379919CC-594F-40C5-A10E-97E048F73AE2@fb.com>
References: <20201229214214.3413833-1-songliubraving@fb.com>
 <20201229214214.3413833-4-songliubraving@fb.com>
 <20210118193817.GG12699@kernel.org>
In-Reply-To: <20210118193817.GG12699@kernel.org>
Accept-Language: en-US
Content-Language: en-US
Content-Type: text/plain; charset="us-ascii"
Content-ID: <FF4F4FC7CBD4944BAF4041FEADDAE747@namprd15.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-MS-Exchange-CrossTenant-Network-Message-Id: 37ce5c8b-fb31-4f8d-08d1-08d8bc13eabe
X-MS-Exchange-CrossTenant-originalarrivaltime: 19 Jan 2021 00:48:20.0548
 (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: +4z3OhfF/S66gP1nSob8PUeKobmV7N6o0TMaX2M2Au+fHgbOjEgzcV3qLGw0J0YT36PPIbNadHS9Z/5ORUrTzQ==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BYAPR15MB2262
X-OriginatorOrg: fb.com
X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10434:6.0.343,18.0.737
 definitions=2021-01-18_15:2021-01-18,2021-01-18 signatures=0
X-Proofpoint-Spam-Details: rule=fb_default_notspam policy=fb_default score=0 suspectscore=0
 mlxlogscore=999 lowpriorityscore=0 phishscore=0 mlxscore=0 bulkscore=0
 adultscore=0 priorityscore=1501 impostorscore=0 malwarescore=0 spamscore=0
 clxscore=1015 classifier=spam adjust=0 reason=mlx scancount=1
 engine=8.12.0-2009150000 definitions=main-2101190001
X-FB-Internal: deliver
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

Hi Arnaldo,

> On Jan 18, 2021, at 11:38 AM, Arnaldo Carvalho de Melo <acme@kernel.org> =
wrote:
>=20
> Em Tue, Dec 29, 2020 at 01:42:14PM -0800, Song Liu escreveu:
>> Introduce perf-stat -b option, which counts events for BPF programs, lik=
e:
>>=20
>> [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
>>=20
>> 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.
>=20
> So trying to get back to this after vacation:
>=20
> [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_f=
rame
> 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 pe=
ak_states 0 mark_read 0
>=20
> 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 ~]#
>=20
> [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)
>=20
> [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_f=
rame
> 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_f=
rame
> 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 pe=
ak_states 0 mark_read 0
>=20
> 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_f=
rame
> 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 pe=
ak_states 0 mark_read 0
>=20
> 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_f=
rame
> 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 pe=
ak_states 0 mark_read 0
>=20
> 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 ~]#
>=20
> 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.
>=20
> - Arnaldo

We are looking at two issues:
1. Cannot recursively attach;
2. prog FD 3 doesn't have valid btf.=20

#1 was caused by the verifier disallowing attaching fentry/fexit program=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 revisit=20
this constraint. I will work on this.=20

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=20
programs? For example, we can use fileslower.py from bcc.=20

Thanks,
Song

[...]