Re: [PATCH bpf-next v5 1/3] bpf: Show more useful info in stack depth stats

["Kumar Kartikeya Dwivedi" <memxor@gmail.com>]

On Tue Aug 4, 2026 at 11:31 AM CEST, bot+bpf-ci wrote:
>> diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
>> index b274004fccfd9..80c249906fd39 100644
>> --- a/kernel/bpf/verifier.c
>> +++ b/kernel/bpf/verifier.c
>> @@ -18777,15 +18777,21 @@ static void print_verification_stats(struct bpf_verifier_env *env)
>>  	if (env->log.level & BPF_LOG_STATS) {
>>  		verbose(env, "verification time %lld usec\n",
>>  			div_u64(env->verification_time, 1000));
>> -		verbose(env, "stack depth %d", env->subprog_info[0].stack_depth);
>> -		for (i = 1; i < subprog_cnt; i++)
>> -			verbose(env, "+%d", env->subprog_info[i].stack_depth);
>> -		verbose(env, " max %d\n", env->max_stack_depth);
>> -		verbose(env, "insns processed %d", env->subprog_info[0].insn_processed);
>> -		for (i = 1; i < subprog_cnt; i++)
>> -			if (bpf_subprog_is_global(env, i))
>> -				verbose(env, "+%d", env->subprog_info[i].insn_processed);
>> -		verbose(env, "\n");
>> +		verbose(env, "stack depth max %d\n", env->max_stack_depth);
>> +		for (i = 0; i < subprog_cnt; i++) {
>> +			const char *name = env->subprog_info[i].name;
>> +
>> +			if (!name || !name[0])
>> +				name = "<unknown>";
>> +			if (i == 0)
>> +				verbose(env, "prog (%s) insns %d stack %d\n", name,
>> +					env->subprog_info[i].insn_processed,
>> +					env->subprog_info[i].stack_depth);
>> +			else
>> +				verbose(env, "subprog %d (%s) insns %d stack %d\n", i, name,
>> +					env->subprog_info[i].insn_processed,
>> +					env->subprog_info[i].stack_depth);
>> +		}
>>  	}
>
> The new loop prints insns %d for every subprogram, but
> subprog_info[i].insn_processed is only ever written for the main program
> and for global subprograms. The old code encoded exactly that with an
> explicit filter:
>
> kernel/bpf/verifier.c (old):
>     verbose(env, "insns processed %d", env->subprog_info[0].insn_processed);
>     for (i = 1; i < subprog_cnt; i++)
>         if (bpf_subprog_is_global(env, i))          /* <-- filter removed */
>             verbose(env, "+%d", env->subprog_info[i].insn_processed);
>
> The only two writers are do_check_main() and do_check_subprogs(). The
> latter is reached only after:
>
> kernel/bpf/verifier.c:18711
>     if (!bpf_subprog_is_global(env, i))
>         continue;
>
> and the whole function returns early at:
>
> kernel/bpf/check_btf.c:1070
>     if (!aux->func_info)
>         return 0;
>
> env is kvzalloc'd, so for every static subprogram, callback (bpf_loop,
> timer), and every subprogram of a program loaded without BTF func_info,
> insn_processed is structurally always 0. Those instructions were counted
> into the caller's record, because static subprogs are verified inline as
> part of the calling frame.
>
> Does this mean that for any program using static subprograms or callbacks
> the new per-subprog insns field shows 0 rather than where verifier work is
> actually spent?
>
> The patch's own new expectations confirm this. Every "subprog N (...) insns"
> line added in this commit is for a non-global subprogram (dummy_loop_callback,
> cumulative_stack_depth_subprog, timer_cb1, subprog1, subprog2), and each
> uses the permissive {{[0-9]+}} regex that matches 0.
>
> This directly contradicts the stated purpose: "it is hard to see where
> verifier work is spent". Either the bpf_subprog_is_global() filter should
> be kept (omit the field, or the whole record, for subprograms that are not
> independently verified), or the field should be marked as not-measured
> (e.g. insns -) so that 0 is not mistaken for a real measurement.
>

This is valid, and should be considered.

> Related coverage loss from the same root cause:
>
>> diff --git a/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c b/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c
>> index 67dc352addfd7..1755f133f0205 100644
>> --- a/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c
>> +++ b/tools/testing/selftests/bpf/progs/verifier_global_subprogs.c
>> @@ -52,7 +52,7 @@ __msg("('global_calls_good_only') is global and assumed valid.")
>>  /* eventually global_good() is transitively validated as well */
>>  __msg("Validating global_good() func")
>>  __msg("('global_good') is safe for any args that match its prototype")
>> -__msg("insns processed {{[0-9]+\\+[0-9]+\\+[0-9]+$}}")
>> +__msg("prog (chained_global_func_calls_success) insns {{[0-9]+}} stack")
>
> The old anchored pattern asserted that exactly three independent counts
> were emitted (main + global_calls_good_only + global_good). The
> replacement checks only the main-program record and asserts nothing about
> the two global subprogram records. Could the one test that actually
> validated per-global-subprog instruction accounting be preserved?
>
>
> The BPF_LOG_STATS payload grows roughly an order of magnitude per
> subprogram, which can turn a previously-succeeding program load into
> -ENOSPC for callers that pass their own fixed log buffer.
>
> Old stats output scaled at about 4 bytes per subprogram ("+%d" for the
> stack chain, plus "+%d" only for global subprogs). New output emits a full
> line per subprogram: "subprog %d (%s) insns %d stack %d\n", roughly 40-50
> bytes plus the BTF name, which btf_name_valid_identifier() bounds only by
> KSYM_NAME_LEN == 512. With BPF_MAX_SUBPROGS == 256 permitted subprograms
> the stats section goes from under ~2 KB to well over ~12 KB, and far more
> with long function names.
>
> Does this matter? Looking at the load path:
>
> kernel/bpf/log.c:45-58 bpf_vlog_update_len_max()
>     tracks the required size in log->len_max.
>
> kernel/bpf/log.c:295 bpf_vlog_finalize()
>     returns -ENOSPC when log->ubuf && log->len_max > log->len_total.
>
> kernel/bpf/verifier.c:20397-20402 bpf_check()
>     err = bpf_log_attr_finalize(attr_log, &env->log);
>     if (err) ret = err;
>     if (ret) goto err_release_maps;
>
> so the successful verification is turned into a failed BPF_PROG_LOAD.
>
> A userspace loader that sets log_level = 4 (stats only) with a modest,
> fixed log_buf sized against the old output will start failing to load
> multi-subprogram programs after this change. libbpf only auto-retries with
> a larger buffer when it owns the buffer:
>
> tools/lib/bpf/libbpf.c:8064-8071
>     if (own_log_buf && errno == ENOSPC ...)
>
> so callers supplying their own log_buf get the failure.
>
> Could the number of per-subprog records be bounded, or emitted only above
> some log level, to avoid the behaviour change for stats-only callers?
>

This is a stretch. In practice, we won't have such small buffers.

>
> ---
> AI reviewed your patch. Please fix the bug or email reply why it's not a bug.
> See: https://github.com/kernel-patches/vmtest/blob/master/ci/claude/README.md
>
> CI run summary: https://github.com/kernel-patches/bpf/actions/runs/30891720984