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

--===============4204528012165586130==
Content-Type: text/plain; charset="us-ascii"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit

> 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.

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?


---
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
--===============4204528012165586130==--