[PATCH bpf-next v2 1/2] bpf: Print breakdown of insns processed by subprogs

[PATCH bpf-next v2 1/2] bpf: Print breakdown of insns processed by subprogs

[Paul Chaignon]

When using global functions (i.e. subprogs), the verifier performs
function-by-function verification. In that case, the sum of the
instructions processed in each global function and in the main program
counts towards the 1 million instructions limit. Only that sum is
reported in the verifier logs.

While starting to use global functions in Cilium (finally!), we found it
can be useful to have the breakdown per global function, to understand
exactly where the budget is currently spent. This patch implements this
breakdown, under BPF_LOG_STATS, as done for the stack depths.

Signed-off-by: Paul Chaignon <paul.chaignon@gmail.com>
---
Changes in v2:
  - None for this patch.

 include/linux/bpf_verifier.h |  1 +
 kernel/bpf/verifier.c        | 14 ++++++++++++++
 2 files changed, 15 insertions(+)

diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
index 101ca6cc5424..976e2b2f40e8 100644
--- a/include/linux/bpf_verifier.h
+++ b/include/linux/bpf_verifier.h
@@ -779,6 +779,7 @@ struct bpf_subprog_info {
 	u32 exit_idx; /* Index of one of the BPF_EXIT instructions in this subprogram */
 	u16 stack_depth; /* max. stack depth used by this function */
 	u16 stack_extra;
+	u32 insn_processed;
 	/* offsets in range [stack_depth .. fastcall_stack_off)
 	 * are used for bpf_fastcall spills and fills.
 	 */
diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
index 03f9e16c2abe..b48389b48eb6 100644
--- a/kernel/bpf/verifier.c
+++ b/kernel/bpf/verifier.c
@@ -18183,6 +18183,7 @@ static int do_check_common(struct bpf_verifier_env *env, int subprog)
 	}
 
 	ret = do_check(env);
+
 out:
 	if (!ret && pop_log)
 		bpf_vlog_reset(&env->log, 0);
@@ -18215,6 +18216,7 @@ static int do_check_subprogs(struct bpf_verifier_env *env)
 	struct bpf_prog_aux *aux = env->prog->aux;
 	struct bpf_func_info_aux *sub_aux;
 	int i, ret, new_cnt;
+	u32 insn_processed;
 
 	if (!aux->func_info)
 		return 0;
@@ -18229,6 +18231,8 @@ static int do_check_subprogs(struct bpf_verifier_env *env)
 		if (!bpf_subprog_is_global(env, i))
 			continue;
 
+		insn_processed = env->insn_processed;
+
 		sub_aux = subprog_aux(env, i);
 		if (!sub_aux->called || sub_aux->verified)
 			continue;
@@ -18236,6 +18240,7 @@ static int do_check_subprogs(struct bpf_verifier_env *env)
 		env->insn_idx = env->subprog_info[i].start;
 		WARN_ON_ONCE(env->insn_idx == 0);
 		ret = do_check_common(env, i);
+		env->subprog_info[i].insn_processed = env->insn_processed - insn_processed;
 		if (ret) {
 			return ret;
 		} else if (env->log.level & BPF_LOG_LEVEL) {
@@ -18262,10 +18267,12 @@ static int do_check_subprogs(struct bpf_verifier_env *env)
 
 static int do_check_main(struct bpf_verifier_env *env)
 {
+	u32 insn_processed = env->insn_processed;
 	int ret;
 
 	env->insn_idx = 0;
 	ret = do_check_common(env, 0);
+	env->subprog_info[0].insn_processed = env->insn_processed - insn_processed;
 	if (!ret)
 		env->prog->aux->stack_depth = env->subprog_info[0].stack_depth;
 	return ret;
@@ -18288,6 +18295,13 @@ static void print_verification_stats(struct bpf_verifier_env *env)
 				verbose(env, "+");
 		}
 		verbose(env, "\n");
+		verbose(env, "insns processed %d", env->subprog_info[0].insn_processed);
+		for (i = 1; i < env->subprog_cnt; i++) {
+			if (!bpf_subprog_is_global(env, i))
+				continue;
+			verbose(env, "+%d", env->subprog_info[i].insn_processed);
+		}
+		verbose(env, "\n");
 	}
 	verbose(env, "processed %d insns (limit %d) max_states_per_insn %d "
 		"total_states %d peak_states %d mark_read %d\n",
-- 
2.43.0

[PATCH bpf-next v2 2/2] selftests/bpf: Test insns processed breakdown

[Paul Chaignon]

This patch covers in global subprog selftests the new verifier log with
the breakdown of instructions processed by global subprogs.

Signed-off-by: Paul Chaignon <paul.chaignon@gmail.com>
---
Changes in v2:
  - Adapted the tests to pass on cpu=v4 and alu32.

 .../bpf/progs/verifier_global_subprogs.c      | 55 ++++++++++++-------
 1 file changed, 35 insertions(+), 20 deletions(-)

diff --git a/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c b/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c
index 1e08aff7532e..7092a046c018 100644
--- a/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c
+++ b/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c
@@ -46,7 +46,7 @@ __noinline long global_dead(void)
 }
 
 SEC("?raw_tp")
-__success __log_level(2)
+__success __log_level(6)
 /* main prog is validated completely first */
 __msg("('global_calls_good_only') is global and assumed valid.")
 /* eventually global_good() is transitively validated as well */
@@ -86,7 +86,8 @@ __noinline int global_unsupp(const int *mem)
 const volatile bool skip_unsupp_global = true;
 
 SEC("?raw_tp")
-__success
+__success __log_level(4)
+__msg("insns processed 5")
 int guarded_unsupp_global_called(void)
 {
 	if (!skip_unsupp_global)
@@ -142,7 +143,7 @@ int anon_user_mem_invalid(void *ctx)
 }
 
 SEC("?tracepoint")
-__success __log_level(2)
+__success __log_level(6)
 __msg("Func#1 ('subprog_user_anon_mem') is safe for any args that match its prototype")
 int anon_user_mem_valid(void *ctx)
 {
@@ -159,7 +160,7 @@ __noinline __weak int subprog_nonnull_ptr_good(int *p1 __arg_nonnull, int *p2 __
 int x = 47;
 
 SEC("?raw_tp")
-__success __log_level(2)
+__success __log_level(6)
 int arg_tag_nonnull_ptr_good(void *ctx)
 {
 	int y = 74;
@@ -186,21 +187,24 @@ __weak int raw_tp_u64_array(u64 *ctx __arg_ctx)
 }
 
 SEC("?raw_tp")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 12+5+2+2")
 int arg_tag_ctx_raw_tp(void *ctx)
 {
 	return subprog_ctx_tag(ctx) + raw_tp_canonical(ctx) + raw_tp_u64_array(ctx);
 }
 
 SEC("?raw_tp.w")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 12+5+2+2")
 int arg_tag_ctx_raw_tp_writable(void *ctx)
 {
 	return subprog_ctx_tag(ctx) + raw_tp_canonical(ctx) + raw_tp_u64_array(ctx);
 }
 
 SEC("?tp_btf/sys_enter")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 12+5+2+2")
 int arg_tag_ctx_raw_tp_btf(void *ctx)
 {
 	return subprog_ctx_tag(ctx) + raw_tp_canonical(ctx) + raw_tp_u64_array(ctx);
@@ -214,7 +218,8 @@ __weak int tp_whatever(struct whatever *ctx __arg_ctx)
 }
 
 SEC("?tp")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 7+5+2")
 int arg_tag_ctx_tp(void *ctx)
 {
 	return subprog_ctx_tag(ctx) + tp_whatever(ctx);
@@ -231,7 +236,8 @@ __weak int kprobe_subprog_typedef(bpf_user_pt_regs_t *ctx __arg_ctx)
 }
 
 SEC("?kprobe")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 12+5+2+2")
 int arg_tag_ctx_kprobe(void *ctx)
 {
 	return subprog_ctx_tag(ctx) +
@@ -266,7 +272,8 @@ __weak int perf_subprog_canonical(struct bpf_perf_event_data *ctx __arg_ctx)
 }
 
 SEC("?perf_event")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 15+5+2+2+2")
 int arg_tag_ctx_perf(void *ctx)
 {
 	return subprog_ctx_tag(ctx) +
@@ -286,7 +293,8 @@ __weak int iter_subprog_typed(struct bpf_iter__task *ctx __arg_ctx)
 }
 
 SEC("?iter/task")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 8+2+2")
 int arg_tag_ctx_iter_task(struct bpf_iter__task *ctx)
 {
 	return (iter_subprog_void(ctx) + iter_subprog_typed(ctx)) & 1;
@@ -305,7 +313,8 @@ __weak int tracing_subprog_u64(u64 *ctx __arg_ctx)
 int acc;
 
 SEC("?fentry/" SYS_PREFIX "sys_nanosleep")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 12+2+2")
 int BPF_PROG(arg_tag_ctx_fentry)
 {
 	acc += tracing_subprog_void(ctx) + tracing_subprog_u64(ctx);
@@ -313,7 +322,8 @@ int BPF_PROG(arg_tag_ctx_fentry)
 }
 
 SEC("?fexit/" SYS_PREFIX "sys_nanosleep")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 12+2+2")
 int BPF_PROG(arg_tag_ctx_fexit)
 {
 	acc += tracing_subprog_void(ctx) + tracing_subprog_u64(ctx);
@@ -321,14 +331,15 @@ int BPF_PROG(arg_tag_ctx_fexit)
 }
 
 SEC("?fmod_ret/" SYS_PREFIX "sys_nanosleep")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 7+2+2")
 int BPF_PROG(arg_tag_ctx_fmod_ret)
 {
 	return tracing_subprog_void(ctx) + tracing_subprog_u64(ctx);
 }
 
 SEC("?lsm/bpf")
-__success __log_level(2)
+__success __log_level(6)
 int BPF_PROG(arg_tag_ctx_lsm)
 {
 	int ret;
@@ -339,7 +350,8 @@ int BPF_PROG(arg_tag_ctx_lsm)
 }
 
 SEC("?struct_ops/test_1")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 7+2+2")
 int BPF_PROG(arg_tag_ctx_struct_ops)
 {
 	return tracing_subprog_void(ctx) + tracing_subprog_u64(ctx);
@@ -351,7 +363,8 @@ struct bpf_dummy_ops dummy_1 = {
 };
 
 SEC("?syscall")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 12+2+2+2")
 int arg_tag_ctx_syscall(void *ctx)
 {
 	return tracing_subprog_void(ctx) + tracing_subprog_u64(ctx) + tp_whatever(ctx);
@@ -369,7 +382,8 @@ __weak int syscall_array_bpf_for(void *ctx __arg_ctx)
 }
 
 SEC("?syscall")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 2+58")
 int arg_tag_ctx_syscall_bpf_for(void *ctx)
 {
 	return syscall_array_bpf_for(ctx);
@@ -394,7 +408,8 @@ struct {
 };
 
 SEC("?syscall")
-__success __log_level(2)
+__success __log_level(6)
+__msg("insns processed 5")
 int arg_tag_ctx_syscall_tailcall(void *ctx)
 {
 	bpf_tail_call(ctx, &syscall_prog_array, 0);
@@ -471,7 +486,7 @@ __weak int subprog_dynptr(struct bpf_dynptr *dptr)
 }
 
 SEC("?xdp")
-__success __log_level(2)
+__success __log_level(6)
 int arg_tag_dynptr(struct xdp_md *ctx)
 {
 	struct bpf_dynptr dptr;
-- 
2.43.0

Re: [PATCH bpf-next v2 1/2] bpf: Print breakdown of insns processed by subprogs

[sashiko-bot]

Thank you for your contribution! Sashiko AI review found 1 potential issue(s) to consider:
- [High] Out-of-bounds array read of `env->prog->aux->func_info_aux` in `bpf_subprog_is_global` during `print_verification_stats`.
--

commit ef2118bdc82dd49b98dca03db90f551c13fc5d86
Author: Paul Chaignon <paul.chaignon@gmail.com>

bpf: Print breakdown of insns processed by subprogs

When using global functions, the verifier performs function-by-function
verification, and only the sum of instructions processed is reported.
This patch implements a breakdown of instructions processed per global
function under BPF_LOG_STATS, as is done for stack depths.

> diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
> --- a/kernel/bpf/verifier.c
> +++ b/kernel/bpf/verifier.c

[ ... ]

> @@ -18288,6 +18295,13 @@ static void print_verification_stats(struct bpf_verifier_env *env)
>  				verbose(env, "+");
>  		}
>  		verbose(env, "\n");
> +		verbose(env, "insns processed %d", env->subprog_info[0].insn_processed);
> +		for (i = 1; i < env->subprog_cnt; i++) {
> +			if (!bpf_subprog_is_global(env, i))

Does this code cause an out-of-bounds read of the func_info_aux array?

If a default exception callback is injected during verification,
add_hidden_subprog() increments env->subprog_cnt but does not resize the
func_info_aux array.

When print_verification_stats() later iterates up to the new env->subprog_cnt
and calls bpf_subprog_is_global(env, i):

kernel/bpf/verifier.c:bpf_subprog_is_global() {
	struct bpf_func_info_aux *aux = env->prog->aux->func_info_aux;

	return aux && aux[subprog].linkage == BTF_FUNC_GLOBAL;
}

Could this read past the end of the aux array when i reaches the index of
the newly added hidden subprogram?

> +				continue;
> +			verbose(env, "+%d", env->subprog_info[i].insn_processed);
> +		}
> +		verbose(env, "\n");
>  	}

-- 
Sashiko AI review · https://sashiko.dev/#/patchset/5c3514dbc879f22ba3f9eff8a2c730e13bd0572c.1777398528.git.paul.chaignon@gmail.com?part=1

Re: [PATCH bpf-next v2 2/2] selftests/bpf: Test insns processed breakdown

[sashiko-bot]

Thank you for your contribution! Sashiko AI review found 2 potential issue(s) to consider:
- [Medium] Asserting exact verifier instruction counts in C-based BPF selftests causes test flakiness.
- [Low] Unused test configuration from blindly elevating log levels to 6 without corresponding assertions.
--

commit c4e03a953efa7cd8cf2e1a288a0c55c4f73cace2
Author: Paul Chaignon <paul.chaignon@gmail.com>

selftests/bpf: Test insns processed breakdown

This patch updates global subprog selftests to verify the new verifier
log breakdown of instructions processed by global subprogs. It does this
by increasing log levels and adding new message assertions.

> diff --git a/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c b/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c
> index 1e08aff7532e..7092a046c018 100644
> --- a/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c
> +++ b/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c

[ ... ]

> @@ -186,21 +187,24 @@ __weak int raw_tp_u64_array(u64 *ctx __arg_ctx)
>  }
>  
>  SEC("?raw_tp")
> -__success __log_level(2)
> +__success __log_level(6)
> +__msg("insns processed 12+5+2+2")
>  int arg_tag_ctx_raw_tp(void *ctx)

Will hardcoding exact instruction counts cause the tests to become flaky across
different LLVM/Clang versions or optimization levels?

Since test_loader.c natively supports regex matching within __msg using the
{{...}} syntax, would it be more reliable to use a pattern to validate the
log format?

For example, __msg("insns processed {{[0-9]+(\+[0-9]+)*}}") might prevent
failures when the compiler generates slightly different assembly.

[ ... ]

> @@ -321,14 +331,15 @@ int BPF_PROG(arg_tag_ctx_fexit)
>  }
>  
>  SEC("?fmod_ret/" SYS_PREFIX "sys_nanosleep")
> -__success __log_level(2)
> +__success __log_level(6)
> +__msg("insns processed 7+2+2")
>  int BPF_PROG(arg_tag_ctx_fmod_ret)
>  {
>  	return tracing_subprog_void(ctx) + tracing_subprog_u64(ctx);
>  }
>  
>  SEC("?lsm/bpf")
> -__success __log_level(2)
> +__success __log_level(6)
>  int BPF_PROG(arg_tag_ctx_lsm)
>  {
>  	int ret;

Is the log level increase to 6 intentional for arg_tag_ctx_lsm and other
similar tests in this patch (like anon_user_mem_valid and arg_tag_dynptr)?

These tests don't appear to have corresponding __msg assertions added to
actually verify the resulting stats breakdown, which might just add
unnecessary overhead and log data to the test execution.

-- 
Sashiko AI review · https://sashiko.dev/#/patchset/5c3514dbc879f22ba3f9eff8a2c730e13bd0572c.1777398528.git.paul.chaignon@gmail.com?part=2

Re: [PATCH bpf-next v2 2/2] selftests/bpf: Test insns processed breakdown

[Alexei Starovoitov]

On Tue Apr 28, 2026 at 7:36 PM PDT, sashiko-bot wrote:
> Thank you for your contribution! Sashiko AI review found 2 potential issue(s) to consider:
> - [Medium] Asserting exact verifier instruction counts in C-based BPF selftests causes test flakiness.
> - [Low] Unused test configuration from blindly elevating log levels to 6 without corresponding assertions.
> --
>
> commit c4e03a953efa7cd8cf2e1a288a0c55c4f73cace2
> Author: Paul Chaignon <paul.chaignon@gmail.com>
>
> selftests/bpf: Test insns processed breakdown
>
> This patch updates global subprog selftests to verify the new verifier
> log breakdown of instructions processed by global subprogs. It does this
> by increasing log levels and adding new message assertions.
>
>> diff --git a/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c b/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c
>> index 1e08aff7532e..7092a046c018 100644
>> --- a/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c
>> +++ b/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c
>
> [ ... ]
>
>> @@ -186,21 +187,24 @@ __weak int raw_tp_u64_array(u64 *ctx __arg_ctx)
>>  }
>>  
>>  SEC("?raw_tp")
>> -__success __log_level(2)
>> +__success __log_level(6)
>> +__msg("insns processed 12+5+2+2")
>>  int arg_tag_ctx_raw_tp(void *ctx)
>
> Will hardcoding exact instruction counts cause the tests to become flaky across
> different LLVM/Clang versions or optimization levels?
>
> Since test_loader.c natively supports regex matching within __msg using the
> {{...}} syntax, would it be more reliable to use a pattern to validate the
> log format?
>
> For example, __msg("insns processed {{[0-9]+(\+[0-9]+)*}}") might prevent
> failures when the compiler generates slightly different assembly.

I have to agree with sashk here.
It's way too many tests with hard coded insn counts.
Just one test with above regex is plenty.

pw-bot: cr