[PATCH bpf-next 0/2] bpf: keep track of verifier insn_processed

[PATCH bpf-next 0/2] bpf: keep track of verifier insn_processed

[Dave Marchevsky]

This is a followup to discussion around RFC patchset "bpf: keep track of
prog verification stats" [0]. The RFC elaborates on my usecase, but to
summarize: keeping track of verifier stats for programs as they - and
the kernels they run on - change over time can help developers of
individual programs and BPF kernel folks.

The RFC added a verif_stats to the uapi which contained most of the info
which verifier prints currently. Feedback here was to avoid polluting
uapi with stats that might be meaningless after major changes to the
verifier, but that insn_processed or conceptually similar number would
exist in the long term and was safe to expose.

So let's expose just insn_processed via bpf_prog_info and fdinfo for now
and explore good ways of getting more complicated stats in the future.

[0] https://lore.kernel.org/bpf/20210920151112.3770991-1-davemarchevsky@fb.com/

Dave Marchevsky (2):
  bpf: add insn_processed to bpf_prog_info and fdinfo
  selftests/bpf: add verif_stats test

 include/linux/bpf.h                           |  1 +
 include/uapi/linux/bpf.h                      |  1 +
 kernel/bpf/syscall.c                          |  8 +++--
 kernel/bpf/verifier.c                         |  1 +
 tools/include/uapi/linux/bpf.h                |  1 +
 .../selftests/bpf/prog_tests/verif_stats.c    | 31 +++++++++++++++++++
 6 files changed, 41 insertions(+), 2 deletions(-)
 create mode 100644 tools/testing/selftests/bpf/prog_tests/verif_stats.c

-- 
2.30.2

[PATCH bpf-next 1/2] bpf: add insn_processed to bpf_prog_info and fdinfo

[Dave Marchevsky]

This stat is currently printed in the verifier log and not stored
anywhere. To ease consumption of this data, add a field to bpf_prog_aux
so it can be exposed via BPF_OBJ_GET_INFO_BY_FD and fdinfo.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 include/linux/bpf.h            | 1 +
 include/uapi/linux/bpf.h       | 1 +
 kernel/bpf/syscall.c           | 8 ++++++--
 kernel/bpf/verifier.c          | 1 +
 tools/include/uapi/linux/bpf.h | 1 +
 5 files changed, 10 insertions(+), 2 deletions(-)

diff --git a/include/linux/bpf.h b/include/linux/bpf.h
index d604c8251d88..921ad62b892c 100644
--- a/include/linux/bpf.h
+++ b/include/linux/bpf.h
@@ -887,6 +887,7 @@ struct bpf_prog_aux {
 	struct bpf_prog *prog;
 	struct user_struct *user;
 	u64 load_time; /* ns since boottime */
+	u64 verif_insn_processed;
 	struct bpf_map *cgroup_storage[MAX_BPF_CGROUP_STORAGE_TYPE];
 	char name[BPF_OBJ_NAME_LEN];
 #ifdef CONFIG_SECURITY
diff --git a/include/uapi/linux/bpf.h b/include/uapi/linux/bpf.h
index 6fc59d61937a..89be6ecf9204 100644
--- a/include/uapi/linux/bpf.h
+++ b/include/uapi/linux/bpf.h
@@ -5613,6 +5613,7 @@ struct bpf_prog_info {
 	__u64 run_time_ns;
 	__u64 run_cnt;
 	__u64 recursion_misses;
+	__u64 verif_insn_processed;
 } __attribute__((aligned(8)));
 
 struct bpf_map_info {
diff --git a/kernel/bpf/syscall.c b/kernel/bpf/syscall.c
index 4e50c0bfdb7d..ea452ced2296 100644
--- a/kernel/bpf/syscall.c
+++ b/kernel/bpf/syscall.c
@@ -1848,7 +1848,8 @@ static void bpf_prog_show_fdinfo(struct seq_file *m, struct file *filp)
 		   "prog_id:\t%u\n"
 		   "run_time_ns:\t%llu\n"
 		   "run_cnt:\t%llu\n"
-		   "recursion_misses:\t%llu\n",
+		   "recursion_misses:\t%llu\n"
+		   "verif_insn_processed:\t%llu\n",
 		   prog->type,
 		   prog->jited,
 		   prog_tag,
@@ -1856,7 +1857,8 @@ static void bpf_prog_show_fdinfo(struct seq_file *m, struct file *filp)
 		   prog->aux->id,
 		   stats.nsecs,
 		   stats.cnt,
-		   stats.misses);
+		   stats.misses,
+		   prog->aux->verif_insn_processed);
 }
 #endif
 
@@ -3625,6 +3627,8 @@ static int bpf_prog_get_info_by_fd(struct file *file,
 	info.run_cnt = stats.cnt;
 	info.recursion_misses = stats.misses;
 
+	info.verif_insn_processed = prog->aux->verif_insn_processed;
+
 	if (!bpf_capable()) {
 		info.jited_prog_len = 0;
 		info.xlated_prog_len = 0;
diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
index 20900a1bac12..9ca301191d78 100644
--- a/kernel/bpf/verifier.c
+++ b/kernel/bpf/verifier.c
@@ -14038,6 +14038,7 @@ int bpf_check(struct bpf_prog **prog, union bpf_attr *attr, bpfptr_t uattr)
 
 	env->verification_time = ktime_get_ns() - start_time;
 	print_verification_stats(env);
+	env->prog->aux->verif_insn_processed = env->insn_processed;
 
 	if (log->level && bpf_verifier_log_full(log))
 		ret = -ENOSPC;
diff --git a/tools/include/uapi/linux/bpf.h b/tools/include/uapi/linux/bpf.h
index 6fc59d61937a..89be6ecf9204 100644
--- a/tools/include/uapi/linux/bpf.h
+++ b/tools/include/uapi/linux/bpf.h
@@ -5613,6 +5613,7 @@ struct bpf_prog_info {
 	__u64 run_time_ns;
 	__u64 run_cnt;
 	__u64 recursion_misses;
+	__u64 verif_insn_processed;
 } __attribute__((aligned(8)));
 
 struct bpf_map_info {
-- 
2.30.2

[PATCH bpf-next 2/2] selftests/bpf: add verif_stats test

[Dave Marchevsky]

verif_insn_processed field was added to response of bpf_obj_get_info_by_fd
call on a prog. Confirm that it's being populated by loading a simple
program and asking for its info.

Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
---
 .../selftests/bpf/prog_tests/verif_stats.c    | 31 +++++++++++++++++++
 1 file changed, 31 insertions(+)
 create mode 100644 tools/testing/selftests/bpf/prog_tests/verif_stats.c

diff --git a/tools/testing/selftests/bpf/prog_tests/verif_stats.c b/tools/testing/selftests/bpf/prog_tests/verif_stats.c
new file mode 100644
index 000000000000..53ed2239ecad
--- /dev/null
+++ b/tools/testing/selftests/bpf/prog_tests/verif_stats.c
@@ -0,0 +1,31 @@
+// SPDX-License-Identifier: GPL-2.0
+/* Copyright (c) 2021 Facebook */
+
+#include <test_progs.h>
+
+#include "trace_vprintk.lskel.h"
+
+void test_verif_stats(void)
+{
+	__u32 len = sizeof(struct bpf_prog_info);
+	struct bpf_prog_info info = {};
+	struct trace_vprintk *skel;
+	int err;
+
+	skel = trace_vprintk__open_and_load();
+	if (!ASSERT_OK_PTR(skel, "trace_vprintk__open_and_load"))
+		goto cleanup;
+
+	if (!ASSERT_GT(skel->progs.sys_enter.prog_fd, 0, "sys_enter_fd > 0"))
+		goto cleanup;
+
+	err = bpf_obj_get_info_by_fd(skel->progs.sys_enter.prog_fd, &info, &len);
+	if (!ASSERT_OK(err, "bpf_obj_get_info_by_fd"))
+		goto cleanup;
+
+	if (!ASSERT_GT(info.verif_insn_processed, 0, "verif_stats.insn_processed"))
+		goto cleanup;
+
+cleanup:
+	trace_vprintk__destroy(skel);
+}
-- 
2.30.2

Re: [PATCH bpf-next 1/2] bpf: add insn_processed to bpf_prog_info and fdinfo

[Daniel Borkmann]

On 10/7/21 10:09 AM, Dave Marchevsky wrote:
> This stat is currently printed in the verifier log and not stored
> anywhere. To ease consumption of this data, add a field to bpf_prog_aux
> so it can be exposed via BPF_OBJ_GET_INFO_BY_FD and fdinfo.
> 
> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
> ---
>   include/linux/bpf.h            | 1 +
>   include/uapi/linux/bpf.h       | 1 +
>   kernel/bpf/syscall.c           | 8 ++++++--
>   kernel/bpf/verifier.c          | 1 +
>   tools/include/uapi/linux/bpf.h | 1 +
>   5 files changed, 10 insertions(+), 2 deletions(-)
> 
> diff --git a/include/linux/bpf.h b/include/linux/bpf.h
> index d604c8251d88..921ad62b892c 100644
> --- a/include/linux/bpf.h
> +++ b/include/linux/bpf.h
> @@ -887,6 +887,7 @@ struct bpf_prog_aux {
>   	struct bpf_prog *prog;
>   	struct user_struct *user;
>   	u64 load_time; /* ns since boottime */
> +	u64 verif_insn_processed;

nit: why u64 and not u32?

>   	struct bpf_map *cgroup_storage[MAX_BPF_CGROUP_STORAGE_TYPE];
>   	char name[BPF_OBJ_NAME_LEN];
>   #ifdef CONFIG_SECURITY
> diff --git a/include/uapi/linux/bpf.h b/include/uapi/linux/bpf.h
> index 6fc59d61937a..89be6ecf9204 100644
> --- a/include/uapi/linux/bpf.h
> +++ b/include/uapi/linux/bpf.h
> @@ -5613,6 +5613,7 @@ struct bpf_prog_info {
>   	__u64 run_time_ns;
>   	__u64 run_cnt;
>   	__u64 recursion_misses;
> +	__u64 verif_insn_processed;

There's a '__u32 :31; /* alignment pad */' which could be reused. Given this
is uapi, I'd probably just name it 'insn_processed' or 'verified_insns' (maybe
the latter is more appropriate) to avoid abbreviation on verif_ which may not
be obvious.

>   } __attribute__((aligned(8)));
>   
>   struct bpf_map_info {
> diff --git a/kernel/bpf/syscall.c b/kernel/bpf/syscall.c
> index 4e50c0bfdb7d..ea452ced2296 100644
> --- a/kernel/bpf/syscall.c
> +++ b/kernel/bpf/syscall.c
> @@ -1848,7 +1848,8 @@ static void bpf_prog_show_fdinfo(struct seq_file *m, struct file *filp)
>   		   "prog_id:\t%u\n"
>   		   "run_time_ns:\t%llu\n"
>   		   "run_cnt:\t%llu\n"
> -		   "recursion_misses:\t%llu\n",
> +		   "recursion_misses:\t%llu\n"
> +		   "verif_insn_processed:\t%llu\n",
>   		   prog->type,
>   		   prog->jited,
>   		   prog_tag,
> @@ -1856,7 +1857,8 @@ static void bpf_prog_show_fdinfo(struct seq_file *m, struct file *filp)
>   		   prog->aux->id,
>   		   stats.nsecs,
>   		   stats.cnt,
> -		   stats.misses);
> +		   stats.misses,
> +		   prog->aux->verif_insn_processed);
>   }
>   #endif
>   
> @@ -3625,6 +3627,8 @@ static int bpf_prog_get_info_by_fd(struct file *file,
>   	info.run_cnt = stats.cnt;
>   	info.recursion_misses = stats.misses;
>   
> +	info.verif_insn_processed = prog->aux->verif_insn_processed;

Bit off-topic, but stack depth might be useful as well.

> +
>   	if (!bpf_capable()) {
>   		info.jited_prog_len = 0;
>   		info.xlated_prog_len = 0;
> diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
> index 20900a1bac12..9ca301191d78 100644
> --- a/kernel/bpf/verifier.c
> +++ b/kernel/bpf/verifier.c
> @@ -14038,6 +14038,7 @@ int bpf_check(struct bpf_prog **prog, union bpf_attr *attr, bpfptr_t uattr)
>   
>   	env->verification_time = ktime_get_ns() - start_time;
>   	print_verification_stats(env);
> +	env->prog->aux->verif_insn_processed = env->insn_processed;
>   
>   	if (log->level && bpf_verifier_log_full(log))
>   		ret = -ENOSPC;
> diff --git a/tools/include/uapi/linux/bpf.h b/tools/include/uapi/linux/bpf.h
> index 6fc59d61937a..89be6ecf9204 100644
> --- a/tools/include/uapi/linux/bpf.h
> +++ b/tools/include/uapi/linux/bpf.h
> @@ -5613,6 +5613,7 @@ struct bpf_prog_info {
>   	__u64 run_time_ns;
>   	__u64 run_cnt;
>   	__u64 recursion_misses;
> +	__u64 verif_insn_processed;
>   } __attribute__((aligned(8)));
>   
>   struct bpf_map_info {
> 

Re: [PATCH bpf-next 1/2] bpf: add insn_processed to bpf_prog_info and fdinfo

[Dave Marchevsky]

On 10/7/21 5:46 PM, Daniel Borkmann wrote:   
> On 10/7/21 10:09 AM, Dave Marchevsky wrote:
>> This stat is currently printed in the verifier log and not stored
>> anywhere. To ease consumption of this data, add a field to bpf_prog_aux
>> so it can be exposed via BPF_OBJ_GET_INFO_BY_FD and fdinfo.
>>
>> Signed-off-by: Dave Marchevsky <davemarchevsky@fb.com>
>> ---
>>   include/linux/bpf.h            | 1 +
>>   include/uapi/linux/bpf.h       | 1 +
>>   kernel/bpf/syscall.c           | 8 ++++++--
>>   kernel/bpf/verifier.c          | 1 +
>>   tools/include/uapi/linux/bpf.h | 1 +
>>   5 files changed, 10 insertions(+), 2 deletions(-)
>>
>> diff --git a/include/linux/bpf.h b/include/linux/bpf.h
>> index d604c8251d88..921ad62b892c 100644
>> --- a/include/linux/bpf.h
>> +++ b/include/linux/bpf.h
>> @@ -887,6 +887,7 @@ struct bpf_prog_aux {
>>       struct bpf_prog *prog;
>>       struct user_struct *user;
>>       u64 load_time; /* ns since boottime */
>> +    u64 verif_insn_processed;
> 
> nit: why u64 and not u32?
This was an attempt to future-proof, with this comment from Alexei
on the RFC patchset in mind: 

"So it feels to me that insn_processed alone will be enough to address the
monitoring goal.
It can be exposed to fd_info and printed by bpftool.
If/when it changes with some future verifier algorithm we should be able
to approximate it."

My thinking was that, if the scenario in the last sentence of the comment
were to happen, a verifier putting an approximation of 'how hard did I have
to work to verify all the insns' in this field might have use for the extra
bytes.

That seems pretty tenuous though, as does the current verifier needing the 
full u64 anytime soon, so happy to change.

>>       struct bpf_map *cgroup_storage[MAX_BPF_CGROUP_STORAGE_TYPE];
>>       char name[BPF_OBJ_NAME_LEN];
>>   #ifdef CONFIG_SECURITY
>> diff --git a/include/uapi/linux/bpf.h b/include/uapi/linux/bpf.h
>> index 6fc59d61937a..89be6ecf9204 100644
>> --- a/include/uapi/linux/bpf.h
>> +++ b/include/uapi/linux/bpf.h
>> @@ -5613,6 +5613,7 @@ struct bpf_prog_info {
>>       __u64 run_time_ns;
>>       __u64 run_cnt;
>>       __u64 recursion_misses;
>> +    __u64 verif_insn_processed;
> 
> There's a '__u32 :31; /* alignment pad */' which could be reused. Given this
> is uapi, I'd probably just name it 'insn_processed' or 'verified_insns' (maybe
> the latter is more appropriate) to avoid abbreviation on verif_ which may not
> be obvious.

Meaning, just use those 31 bits for insn_processed?

re: your naming suggestions, I prefer 'verified_insns'. Main concern for me is
making it obvious that this field is a property of the verification of the
prog, not the prog itself like most other fields in bpf_prog_info. 

>>   } __attribute__((aligned(8)));
>>     struct bpf_map_info {
>> diff --git a/kernel/bpf/syscall.c b/kernel/bpf/syscall.c
>> index 4e50c0bfdb7d..ea452ced2296 100644
>> --- a/kernel/bpf/syscall.c
>> +++ b/kernel/bpf/syscall.c
>> @@ -1848,7 +1848,8 @@ static void bpf_prog_show_fdinfo(struct seq_file *m, struct file *filp)
>>              "prog_id:\t%u\n"
>>              "run_time_ns:\t%llu\n"
>>              "run_cnt:\t%llu\n"
>> -           "recursion_misses:\t%llu\n",
>> +           "recursion_misses:\t%llu\n"
>> +           "verif_insn_processed:\t%llu\n",
>>              prog->type,
>>              prog->jited,
>>              prog_tag,
>> @@ -1856,7 +1857,8 @@ static void bpf_prog_show_fdinfo(struct seq_file *m, struct file *filp)
>>              prog->aux->id,
>>              stats.nsecs,
>>              stats.cnt,
>> -           stats.misses);
>> +           stats.misses,
>> +           prog->aux->verif_insn_processed);
>>   }
>>   #endif
>>   @@ -3625,6 +3627,8 @@ static int bpf_prog_get_info_by_fd(struct file *file,
>>       info.run_cnt = stats.cnt;
>>       info.recursion_misses = stats.misses;
>>   +    info.verif_insn_processed = prog->aux->verif_insn_processed;
> 
> Bit off-topic, but stack depth might be useful as well.

Agreed. Since there's a stack_depth per subprog it would require handling 
similar to other dynamic-size bpf_prog_info fields, so I didn't add it 
to the RFC patchset either, thinking it would be better to start with 
simple stats and see if anyone uses. Feedback there was to avoid adding 
too many verifier stats fields to bpf_prog_info, instead relying on a 
post-verification bare tracepoint (Andrii) or other BPF hook (John, Alexei)
for extraction of other verifier stats.

>> +
>>       if (!bpf_capable()) {
>>           info.jited_prog_len = 0;
>>           info.xlated_prog_len = 0;
>> diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
>> index 20900a1bac12..9ca301191d78 100644
>> --- a/kernel/bpf/verifier.c
>> +++ b/kernel/bpf/verifier.c
>> @@ -14038,6 +14038,7 @@ int bpf_check(struct bpf_prog **prog, union bpf_attr *attr, bpfptr_t uattr)
>>         env->verification_time = ktime_get_ns() - start_time;
>>       print_verification_stats(env);
>> +    env->prog->aux->verif_insn_processed = env->insn_processed;
>>         if (log->level && bpf_verifier_log_full(log))
>>           ret = -ENOSPC;
>> diff --git a/tools/include/uapi/linux/bpf.h b/tools/include/uapi/linux/bpf.h
>> index 6fc59d61937a..89be6ecf9204 100644
>> --- a/tools/include/uapi/linux/bpf.h
>> +++ b/tools/include/uapi/linux/bpf.h
>> @@ -5613,6 +5613,7 @@ struct bpf_prog_info {
>>       __u64 run_time_ns;
>>       __u64 run_cnt;
>>       __u64 recursion_misses;
>> +    __u64 verif_insn_processed;
>>   } __attribute__((aligned(8)));
>>     struct bpf_map_info {
>>
>