Merge branch 'improve-stack-depth-verification-stats-output'

Kumar Kartikeya Dwivedi says:

====================
Improve stack depth verification stats output

Some improvements for more clarity in the stack depth verification
statistics output. See commit logs for details.

For example, ./test_progs -t subprogs/subprogs_alone loads prog4,
which has a main program, two static subprograms, and two independently
verified global subprograms. A sample run produces:

  verification time 1765 usec
  stack depth max 48
  subprog 0 (prog4) main insns_self 29 insns_total 51 stack 8
  subprog 1 (get_task_tgid) global insns_self 9 insns_total 9 stack 8
  subprog 2 (sub4) static insns_self 15 insns_total 22 stack 8
  subprog 3 (sub3) static insns_self 7 insns_total 7 stack 0
  subprog 4 (sub1) global insns_self 10 insns_total 10 stack 8
  processed 70 insns (limit 1000000) max_states_per_insn 0 total_states 7 peak_states 7 mark_read 0

The insns_self counts account for every processed instruction exactly once:

  29 + 9 + 15 + 7 + 10 = 70

The main program and global subprograms are independent exploration roots,
so their insns_total counts also account for the full processed budget:

  51 + 9 + 10 = 70

Static subprogram totals provide a nested, top-down breakdown inside their
root. In this example:

  sub4: 22 = 15 self + 7 in sub3
  prog4: 51 = 29 self + 22 in sub4

The global subprogram bodies are accounted in their own root totals rather
than being included in prog4 or the static callees which call them.

Asynchronous callbacks start from fresh frame-zero verifier states, but the
work remains part of the do_check_common() invocation for the main or global
verification root under which it was scheduled. Running:

  ./test_progs -t verifier_subprog_insn_stats/stats_async_nested -v

produces the following stats:

  stack depth max 0
  subprog 0 (stats_async_nested) main insns_self 9 insns_total 25 stack 0
  subprog 1 (stats_async_nested_schedule) static insns_self 7 insns_total 7 stack 0
  subprog 2 (stats_async_outer) static insns_self 7 insns_total 7 stack 0
  subprog 3 (stats_async_nested_leaf) static insns_self 2 insns_total 2 stack 0
  processed 25 insns

Here, 9 + 2 + 7 + 7 = 25. The main root total is the complete verifier
budget for its do_check_common() invocation, including both directly and
transitively scheduled asynchronous callbacks. Static subprogram and
callback totals remain local to their synchronous paths.

Changelog:
----------
v7 -> v8
v7: https://lore.kernel.org/bpf/20260808062601.1070988-1-memxor@gmail.com

 * Move the insns_total snapshot and delta for main and global roots into
   do_check_common() and explain why the override is needed for async
   subprograms. (Eduard)
 * Avoid splitting __msg string literals in the stack-depth stats tests.
   (Eduard)
 * Add a comment explaining why both the new per-subprogram records and the
   legacy one-line format are matched in veristat's parse_verif_log().
   (Eduard)

v6 -> v7
v6: https://lore.kernel.org/bpf/20260805011517.1717238-1-memxor@gmail.com

 * Rename insns_own to insns_self throughout. (Andrii)
 * Drop the async accounting call stack and attribute callback work to the
   scheduling main or global verification root using its processed-insn
   delta. (Eduard, Andrii)
 * Skip missing frames when folding instruction totals after a partial
   verifier state copy. (BPF CI Bot)
 * Use explicit callback argument operands in deterministic instruction-count
   tests and update tests and examples for root attribution. (BPF CI Bot)

v5 -> v6
v5: https://lore.kernel.org/bpf/20260804081114.3871564-1-memxor@gmail.com

 * Track self and inclusive instruction counts for main, global, and static
   subprograms. (Andrii, Eduard)
 * Keep instruction subtotals path-local across verifier state copies.
 * Propagate async callback budget through nested scheduling chains. (Andrii)
 * Split per-subprogram instruction accounting into a preparatory patch.
 * Add deterministic selftests with exact self, total, and processed counts.

v4 -> v5
v4: https://lore.kernel.org/bpf/20260803072733.191502-1-memxor@gmail.com

 * Change the format to combine instruction counts and stack depths into
   per-program records. (Andrii)
 * Adjust veristat for the new format while retaining support for the legacy
   format.
 * Explain why the legacy stack parsing buffer is zero-initialized. (BPF CI
   Bot)

v3 -> v4
v3: https://lore.kernel.org/bpf/20260803031457.3115812-1-memxor@gmail.com

 * Read names from subprog_info directly to avoid an out-of-bounds access
   when func_info validation fails. (BPF CI Bot)

v2 -> v3
v2: https://lore.kernel.org/bpf/20260802225209.2511758-1-memxor@gmail.com

 * Reuse subprog_name() to fetch subprogram names. (BPF CI Bot)

v1 -> v2
v1: https://lore.kernel.org/bpf/20260801230400.850271-1-memxor@gmail.com

 * Use multi-line format. (Eduard)
 * Adjust veristat to work with old and new format.
 * Adjust selftest log_level without new option. (Eduard)
====================

Link: https://patch.msgid.link/20260812221925.3358041-1-memxor@gmail.com
Signed-off-by: Eduard Zingerman <eddyz87@gmail.com>

include/linux/bpf_verifier.h

@@ -380,6 +380,8 @@ struct bpf_func_state {
 	 *                           | number of simulations is tracked in frame N
 	 */
 	u32 callback_depth;
+	/* Instructions processed in this frame and callees on the current path. */
+	u32 insns_subtotal;
 
 	/* The following fields should be last. See copy_func_state() */
 	/* The state of the stack. Each element of the array describes BPF_REG_SIZE
@@ -798,7 +800,8 @@ 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;
+	u32 insns_total;
+	u32 insns_self;
 	/* offsets in range [stack_depth .. fastcall_stack_off)
 	 * are used for bpf_fastcall spills and fills.
 	 */

kernel/bpf/verifier.c

@@ -1593,6 +1593,8 @@ static int copy_func_state(struct bpf_func_state *dst,
 			   const struct bpf_func_state *src)
 {
 	memcpy(dst, src, offsetof(struct bpf_func_state, stack));
+	/* Instruction accounting is path-local, not part of verifier state. */
+	dst->insns_subtotal = 0;
 	return copy_stack_state(dst, src);
 }
 
@@ -9708,6 +9710,42 @@ static int set_task_work_schedule_callback_state(struct bpf_verifier_env *env,
 
 static bool is_rbtree_lock_required_kfunc(u32 btf_id);
 
+static void account_processed_insn(struct bpf_verifier_env *env)
+{
+	struct bpf_func_state *frame = cur_func(env);
+
+	env->insn_processed++;
+	frame->insns_subtotal++;
+	env->subprog_info[frame->subprogno].insns_self++;
+}
+
+static void account_processed_insns(struct bpf_verifier_env *env,
+				    struct bpf_func_state *callee,
+				    struct bpf_func_state *caller)
+{
+	u32 insns;
+
+	if (!callee)
+		return;
+
+	insns = callee->insns_subtotal;
+
+	env->subprog_info[callee->subprogno].insns_total += insns;
+	if (caller)
+		caller->insns_subtotal += insns;
+	callee->insns_subtotal = 0;
+}
+
+static void account_current_path(struct bpf_verifier_env *env)
+{
+	struct bpf_verifier_state *state = env->cur_state;
+	int frame;
+
+	for (frame = state->curframe; frame >= 0; frame--)
+		account_processed_insns(env, state->frame[frame],
+					frame ? state->frame[frame - 1] : NULL);
+}
+
 /* Are we currently verifying the callback for a rbtree helper that must
  * be called with lock held? If so, no need to complain about unreleased
  * lock
@@ -9804,6 +9842,7 @@ static int prepare_func_exit(struct bpf_verifier_env *env, int *insn_idx)
 		verbose(env, "to caller at %d:\n", *insn_idx);
 		print_verifier_state(env, state, caller->frameno, true);
 	}
+	account_processed_insns(env, callee, caller);
 	/* clear everything in the callee. In case of exceptional exits using
 	 * bpf_throw, this will be done by copy_verifier_state for extra frames. */
 	free_func_state(callee);
@@ -17359,7 +17398,9 @@ static int do_check(struct bpf_verifier_env *env)
 		insn = &insns[env->insn_idx];
 		insn_aux = &env->insn_aux_data[env->insn_idx];
 
-		if (++env->insn_processed > BPF_COMPLEXITY_LIMIT_INSNS) {
+		account_processed_insn(env);
+
+		if (env->insn_processed > BPF_COMPLEXITY_LIMIT_INSNS) {
 			verbose(env,
 				"BPF program is too large. Processed %d insn\n",
 				env->insn_processed);
@@ -17500,6 +17541,7 @@ static int do_check(struct bpf_verifier_env *env)
 					    "speculation barrier after jump instruction may not have the desired effect"))
 				return -EFAULT;
 process_bpf_exit:
+			account_current_path(env);
 			mark_verifier_state_scratched(env);
 			err = bpf_update_branch_counts(env, env->cur_state);
 			if (err)
@@ -18406,6 +18448,7 @@ static int do_check_common(struct bpf_verifier_env *env, int subprog)
 	struct bpf_prog_aux *aux = env->prog->aux;
 	struct bpf_verifier_state *state;
 	struct bpf_reg_state *regs;
+	u32 insn_processed = env->insn_processed;
 	int ret, i;
 
 	env->prev_linfo = NULL;
@@ -18544,9 +18587,19 @@ static int do_check_common(struct bpf_verifier_env *env, int subprog)
 
 	ret = do_check(env);
 out:
+	account_current_path(env);
 	if (!ret && pop_log)
 		bpf_vlog_reset(&env->log, 0);
 	free_states(env);
+
+	/*
+	 * The override is needed to account for async subprograms, which
+	 * are verified with their own set of stack frames and thus are
+	 * not accounted as callees by account_current_path().
+	 * Accumulate their total counts as total counts of the main or
+	 * global subprog hosting the async call.
+	 */
+	env->subprog_info[subprog].insns_total = env->insn_processed - insn_processed;
 	return ret;
 }
 
@@ -18575,7 +18628,6 @@ 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;
@@ -18590,8 +18642,6 @@ 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;
@@ -18599,7 +18649,6 @@ 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) {
@@ -18626,12 +18675,10 @@ 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;
@@ -18646,15 +18693,20 @@ 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;
+			const char *kind;
+
+			if (!name || !name[0])
+				name = "<unknown>";
+			kind = i == 0 ? "main" :
+			       bpf_subprog_is_global(env, i) ? "global" : "static";
+			verbose(env, "subprog %d (%s) %s insns_self %d insns_total %d stack %d\n",
+				i, name, kind, env->subprog_info[i].insns_self,
+				env->subprog_info[i].insns_total,
+				env->subprog_info[i].stack_depth);
+		}
 	}
 	verbose(env, "processed %d insns (limit %d) max_states_per_insn %d "
 		"total_states %d peak_states %d mark_read %d\n",

tools/testing/selftests/bpf/prog_tests/verifier.c

@@ -102,6 +102,7 @@
 #include "verifier_stack_arg_order.skel.h"
 #include "verifier_stack_ptr.skel.h"
 #include "verifier_store_release.skel.h"
+#include "verifier_subprog_insn_stats.skel.h"
 #include "verifier_subprog_precision.skel.h"
 #include "verifier_subprog_topo.skel.h"
 #include "verifier_subreg.skel.h"
@@ -262,6 +263,7 @@ void test_verifier_stack_arg(void)            { RUN(verifier_stack_arg); }
 void test_verifier_stack_arg_order(void)      { RUN(verifier_stack_arg_order); }
 void test_verifier_stack_ptr(void)            { RUN(verifier_stack_ptr); }
 void test_verifier_store_release(void)        { RUN(verifier_store_release); }
+void test_verifier_subprog_insn_stats(void)   { RUN(verifier_subprog_insn_stats); }
 void test_verifier_subprog_precision(void)    { RUN(verifier_subprog_precision); }
 void test_verifier_subprog_topo(void)        { RUN(verifier_subprog_topo); }
 void test_verifier_subreg(void)               { RUN(verifier_subreg); }

tools/testing/selftests/bpf/progs/verifier_basic_stack.c

@@ -27,7 +27,8 @@ __naked void stack_out_of_bounds(void)
 
 SEC("socket")
 __description("uninitialized stack1")
-__success __log_level(4) __msg("stack depth 8")
+__success __log_level(4)
+__msg("subprog 0 (uninitialized_stack1) main {{.*}} stack 8")
 __failure_unpriv __msg_unpriv("invalid read from stack")
 __naked void uninitialized_stack1(void)
 {
@@ -45,7 +46,8 @@ __naked void uninitialized_stack1(void)
 
 SEC("socket")
 __description("uninitialized stack2")
-__success __log_level(4) __msg("stack depth 8")
+__success __log_level(4)
+__msg("subprog 0 (uninitialized_stack2) main insns_self {{[0-9]+}} insns_total {{[0-9]+}} stack 8")
 __failure_unpriv __msg_unpriv("invalid read from stack")
 __naked void uninitialized_stack2(void)
 {

tools/testing/selftests/bpf/progs/verifier_bpf_fastcall.c

@@ -10,7 +10,8 @@
 
 SEC("raw_tp")
 __arch_x86_64
-__log_level(4) __msg("stack depth 8")
+__log_level(4)
+__msg("subprog 0 (simple) main insns_self {{[0-9]+}} insns_total {{[0-9]+}} stack 8")
 __xlated("4: r5 = 5")
 __xlated("5: r0 = ")
 __xlated("6: r0 = &(void __percpu *)(r0)")
@@ -96,7 +97,8 @@ __naked void canary_zero_spills(void)
 
 SEC("raw_tp")
 __arch_x86_64
-__log_level(4) __msg("stack depth 16")
+__log_level(4)
+__msg("subprog 0 (wrong_reg_in_pattern1) main {{.*}} stack 16")
 __xlated("1: *(u64 *)(r10 -16) = r1")
 __xlated("...")
 __xlated("3: r0 = &(void __percpu *)(r0)")
@@ -598,7 +600,8 @@ __naked static void subprogs_use_independent_offsets_aux(void)
 
 SEC("raw_tp")
 __arch_x86_64
-__log_level(4) __msg("stack depth 8")
+__log_level(4)
+__msg("subprog 0 (helper_call_does_not_prevent_bpf_fastcall) main {{.*}} stack 8")
 __xlated("2: r0 = &(void __percpu *)(r0)")
 __success
 __naked void helper_call_does_not_prevent_bpf_fastcall(void)
@@ -620,7 +623,8 @@ __naked void helper_call_does_not_prevent_bpf_fastcall(void)
 
 SEC("raw_tp")
 __arch_x86_64
-__log_level(4) __msg("stack depth 24")
+__log_level(4)
+__msg("subprog 0 (may_goto_interaction_x86_64) main {{.*}} stack 24")
 /* may_goto counter at -24 */
 __xlated("0: *(u64 *)(r10 -24) =")
 /* may_goto timestamp at -16 */
@@ -661,7 +665,8 @@ __naked void may_goto_interaction_x86_64(void)
 SEC("raw_tp")
 __arch_arm64
 __arch_riscv64
-__log_level(4) __msg("stack depth 24")
+__log_level(4)
+__msg("subprog 0 (may_goto_interaction) main {{.*}} stack 24")
 /* may_goto counter at -24 */
 __xlated("0: *(u64 *)(r10 -24) =")
 /* may_goto timestamp at -16 */
@@ -708,7 +713,9 @@ __naked static void dummy_loop_callback(void)
 
 SEC("raw_tp")
 __arch_x86_64
-__log_level(4) __msg("stack depth 32+0")
+__log_level(4)
+__msg("subprog 0 (bpf_loop_interaction1) main {{.*}} stack 32")
+__msg("subprog 1 (dummy_loop_callback) static {{.*}} stack 0")
 __xlated("2: r1 = 1")
 __xlated("3: r0 =")
 __xlated("4: r0 = &(void __percpu *)(r0)")
@@ -756,7 +763,9 @@ __naked int bpf_loop_interaction1(void)
 
 SEC("raw_tp")
 __arch_x86_64
-__log_level(4) __msg("stack depth 40+0")
+__log_level(4)
+__msg("subprog 0 (bpf_loop_interaction2) main {{.*}} stack 40")
+__msg("subprog 1 (dummy_loop_callback) static {{.*}} stack 0")
 /* call bpf_get_smp_processor_id */
 __xlated("2: r1 = 42")
 __xlated("3: r0 =")
@@ -800,7 +809,10 @@ __naked int bpf_loop_interaction2(void)
 
 SEC("raw_tp")
 __arch_x86_64
-__log_level(4) __msg("stack depth 512+0 max 512")
+__log_level(4)
+__msg("stack depth max 512")
+__msg("subprog 0 (cumulative_stack_depth) main {{.*}} stack 512")
+__msg("subprog 1 (cumulative_stack_depth_subprog) static {{.*}} stack 0")
 /* just to print xlated version when debugging */
 __xlated("r0 = &(void __percpu *)(r0)")
 __success

tools/testing/selftests/bpf/progs/verifier_global_subprogs.c

@@ -52,7 +52,10 @@ __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("subprog 0 (chained_global_func_calls_success) main insns_self 7 insns_total 7 stack")
+__msg("subprog {{[0-9]+}} (global_calls_good_only) global insns_self 2 insns_total 2 stack")
+__msg("subprog {{[0-9]+}} (global_good) global insns_self 5 insns_total 5 stack")
+__msg("processed 14 insns")
 int chained_global_func_calls_success(void)
 {
 	int sum = 0;

tools/testing/selftests/bpf/progs/verifier_private_stack.c

@@ -86,7 +86,9 @@ __naked static void cumulative_stack_depth_subprog(void)
 SEC("kprobe")
 __description("Private stack, subtree > MAX_BPF_STACK")
 __success
-__log_level(4) __msg("stack depth 512+32 max 512")
+__log_level(4) __msg("stack depth max 512")
+__msg("subprog 0 (private_stack_nested_1) main {{.*}} stack 512")
+__msg("subprog 1 (cumulative_stack_depth_subprog) static {{.*}} stack 32")
 __arch_x86_64
 /* private stack fp for the main prog */
 __jited("	movabsq	$0x{{.*}}, %r9")
@@ -331,7 +333,11 @@ SEC("fentry/bpf_fentry_test9")
 __description("Private stack, async callback, potential nesting")
 __success __retval(0)
 __load_if_JITed()
-__log_level(4) __msg("stack depth 8+0+256+0 max 272")
+__log_level(4) __msg("stack depth max 272")
+__msg("subprog 0 (private_stack_async_callback_2) main {{.*}} stack 8")
+__msg("subprog 1 (timer_cb1) static {{.*}} stack 0")
+__msg("subprog 2 (subprog1) static {{.*}} stack 256")
+__msg("subprog 3 (subprog2) static {{.*}} stack 0")
 __arch_x86_64
 __jited("	subq	$0x100, %rsp")
 __arch_arm64
@@ -355,7 +361,10 @@ int private_stack_async_callback_2(void)
 SEC("fentry/bpf_fentry_test9")
 __description("private stack, max stack depth is private stack")
 __success
-__log_level(4) __msg("stack depth 8+256+0 max 256")
+__log_level(4) __msg("stack depth max 256")
+__msg("subprog 0 (private_stack_max_depth) main {{.*}} stack 8")
+__msg("subprog 1 (subprog1) static insns_self {{[0-9]+}} insns_total {{[0-9]+}} stack 256")
+__msg("subprog 2 (subprog2) static insns_self {{[0-9]+}} insns_total {{[0-9]+}} stack 0")
 int private_stack_max_depth(void)
 {
 	int x = 0;

tools/testing/selftests/bpf/progs/verifier_subprog_insn_stats.c

@@ -0,0 +1,223 @@
+// SPDX-License-Identifier: GPL-2.0
+
+#include <vmlinux.h>
+#include <bpf/bpf_helpers.h>
+#include "bpf_misc.h"
+
+struct timer_value {
+	struct bpf_timer timer;
+};
+
+struct {
+	__uint(type, BPF_MAP_TYPE_ARRAY);
+	__uint(max_entries, 1);
+	__type(key, __u32);
+	__type(value, struct timer_value);
+} timer_map SEC(".maps");
+
+SEC("?raw_tp")
+__success __log_level(4)
+__msg("subprog 0 (stats_main_only) main insns_self 2 insns_total 2 stack 0")
+__msg("processed 2 insns")
+__naked int stats_main_only(void)
+{
+	asm volatile (
+		"r0 = 0;"
+		"exit;"
+	);
+}
+
+__naked __noinline __used
+static int stats_chain_leaf(void)
+{
+	asm volatile (
+		"r0 = 0;"
+		"exit;"
+	);
+}
+
+__naked __noinline __used
+static int stats_chain_parent(void)
+{
+	asm volatile (
+		"call stats_chain_leaf;"
+		"exit;"
+	);
+}
+
+SEC("?raw_tp")
+__success __log_level(4)
+/*
+ * self: 2 + 2 + 2 = 6
+ * totals: leaf 2, parent 2 + 2 = 4, main 2 + 4 = 6
+ */
+__msg("subprog 0 (stats_static_chain) main insns_self 2 insns_total 6 stack 0")
+__msg("subprog {{[0-9]+}} (stats_chain_parent) static insns_self 2 insns_total 4 stack 0")
+__msg("subprog {{[0-9]+}} (stats_chain_leaf) static insns_self 2 insns_total 2 stack 0")
+__msg("processed 6 insns")
+__naked int stats_static_chain(void)
+{
+	asm volatile (
+		"call stats_chain_parent;"
+		"exit;"
+	);
+}
+
+__naked __noinline __used
+static int stats_shared_leaf(void)
+{
+	asm volatile (
+		"r0 = 0;"
+		"exit;"
+	);
+}
+
+__naked __noinline __used
+int stats_global_root(void)
+{
+	asm volatile (
+		"call stats_shared_leaf;"
+		"exit;"
+	);
+}
+
+SEC("?raw_tp")
+__success __log_level(4)
+/*
+ * stats_shared_leaf is explored once under each independent root.
+ * self: main 3 + leaf 4 + global 2 = 9
+ * root totals: main 5 + global 4 = 9
+ */
+__msg("subprog 0 (stats_shared_roots) main insns_self 3 insns_total 5 stack 0")
+__msg("subprog {{[0-9]+}} (stats_shared_leaf) static insns_self 4 insns_total 4 stack 0")
+__msg("subprog {{[0-9]+}} (stats_global_root) global insns_self 2 insns_total 4 stack 0")
+__msg("processed 9 insns")
+__naked int stats_shared_roots(void)
+{
+	asm volatile (
+		"call stats_shared_leaf;"
+		"call stats_global_root;"
+		"exit;"
+	);
+}
+
+__noinline __used
+static int stats_async_leaf(void *map, __u32 *key, struct bpf_timer *timer)
+{
+	return 0;
+}
+
+__noinline __used
+static __u64 stats_async_schedule(struct bpf_map *map, __u32 *key,
+				  struct timer_value *value, void *ctx)
+{
+	asm volatile (
+		"r1 = %[timer];"
+		"r2 = %[stats_async_leaf];"
+		"call %[bpf_timer_set_callback];"
+		:
+		: [timer] "r" (value),
+		  __imm_ptr(stats_async_leaf),
+		  __imm(bpf_timer_set_callback)
+		: __clobber_common
+	);
+	return 0;
+}
+
+SEC("?raw_tp")
+__success __log_level(4)
+/*
+ * self: 9 + 7 + 2 = 18
+ * totals: leaf 2, scheduler 7, main root 18
+ */
+__msg("subprog 0 (stats_async_direct) main insns_self 9 insns_total 18 stack 0")
+__msg("subprog {{[0-9]+}} (stats_async_schedule) static insns_self 7 insns_total 7 stack 0")
+__msg("subprog {{[0-9]+}} (stats_async_leaf) static insns_self 2 insns_total 2 stack 0")
+__msg("processed 18 insns")
+__naked int stats_async_direct(void)
+{
+	asm volatile (
+		"r1 = %[timer_map] ll;"
+		"r2 = %[stats_async_schedule];"
+		"r3 = 0;"
+		"r4 = 0;"
+		"call %[bpf_for_each_map_elem];"
+		"r0 = 0;"
+		"exit;"
+		:
+		: __imm_addr(timer_map),
+		  __imm_ptr(stats_async_schedule),
+		  __imm(bpf_for_each_map_elem)
+		: __clobber_common
+	);
+}
+
+__noinline __used
+static int stats_async_nested_leaf(void *map, __u32 *key, struct bpf_timer *timer)
+{
+	return 0;
+}
+
+__noinline __used
+static int stats_async_outer(void *map, __u32 *key, struct bpf_timer *timer)
+{
+	asm volatile (
+		"r1 = %[timer];"
+		"r2 = %[stats_async_nested_leaf];"
+		"call %[bpf_timer_set_callback];"
+		:
+		: [timer] "r" (timer),
+		  __imm_ptr(stats_async_nested_leaf),
+		  __imm(bpf_timer_set_callback)
+		: __clobber_common
+	);
+	return 0;
+}
+
+__noinline __used
+static __u64 stats_async_nested_schedule(struct bpf_map *map, __u32 *key,
+					 struct timer_value *value, void *ctx)
+{
+	asm volatile (
+		"r1 = %[timer];"
+		"r2 = %[stats_async_outer];"
+		"call %[bpf_timer_set_callback];"
+		:
+		: [timer] "r" (value),
+		  __imm_ptr(stats_async_outer),
+		  __imm(bpf_timer_set_callback)
+		: __clobber_common
+	);
+	return 0;
+}
+
+SEC("?raw_tp")
+__success __log_level(4)
+/*
+ * self: 9 + 7 + 7 + 2 = 25
+ * totals: leaf 2, outer 7, scheduler 7, main root 25
+ */
+__msg("subprog 0 (stats_async_nested) main insns_self 9 insns_total 25 stack 0")
+__msg("subprog {{[0-9]+}} (stats_async_nested_schedule) static insns_self 7 insns_total 7 stack 0")
+__msg("subprog {{[0-9]+}} (stats_async_outer) static insns_self 7 insns_total 7 stack 0")
+__msg("subprog {{[0-9]+}} (stats_async_nested_leaf) static insns_self 2 insns_total 2 stack 0")
+__msg("processed 25 insns")
+__naked int stats_async_nested(void)
+{
+	asm volatile (
+		"r1 = %[timer_map] ll;"
+		"r2 = %[stats_async_nested_schedule];"
+		"r3 = 0;"
+		"r4 = 0;"
+		"call %[bpf_for_each_map_elem];"
+		"r0 = 0;"
+		"exit;"
+		:
+		: __imm_addr(timer_map),
+		  __imm_ptr(stats_async_nested_schedule),
+		  __imm(bpf_for_each_map_elem)
+		: __clobber_common
+	);
+}
+
+char _license[] SEC("license") = "GPL";

tools/testing/selftests/bpf/progs/verifier_var_off.c

@@ -198,7 +198,8 @@ __success
 /* Check that the maximum stack depth is correctly maintained according to the
  * maximum possible variable offset.
  */
-__log_level(4) __msg("stack depth 16")
+__log_level(4)
+__msg("subprog 0 (stack_write_priv_vs_unpriv) main {{.*}} stack 16")
 __failure_unpriv
 /* Variable stack access is rejected for unprivileged.
  */
@@ -238,7 +239,8 @@ __success
 /* Check that the maximum stack depth is correctly maintained according to the
  * maximum possible variable offset.
  */
-__log_level(4) __msg("stack depth 16")
+__log_level(4)
+__msg("subprog 0 (stack_write_followed_by_read) main {{.*}} stack 16")
 __failure_unpriv
 __msg_unpriv("R2 variable stack access prohibited for !root")
 __retval(0)

tools/testing/selftests/bpf/test_verifier.c

@@ -1560,7 +1560,7 @@ static void do_test_single(struct bpf_test *test, bool unpriv,
 
 	opts.expected_attach_type = test->expected_attach_type;
 	if (expected_ret == VERBOSE_ACCEPT)
-		opts.log_level = 2;
+		opts.log_level = 2 | 4;
 	else if (verbose)
 		opts.log_level = verif_log_level | 4; /* force stats */
 	else

tools/testing/selftests/bpf/verifier/calls.c

@@ -1091,7 +1091,17 @@
 	/* stack_main=32, stack_A=256, stack_B=64
 	 * and max(main+A, main+A+B) < 512
 	 */
-	.result = ACCEPT,
+	.result = VERBOSE_ACCEPT,
+	.errstr = "stack depth max 352\t"
+		  "subprog 0 (<unknown>) main insns_self \t"
+		  " insns_total \t"
+		  " stack 32\t"
+		  "subprog 1 (<unknown>) static insns_self \t"
+		  " insns_total \t"
+		  " stack 256\t"
+		  "subprog 2 (<unknown>) static insns_self \t"
+		  " insns_total \t"
+		  " stack 64",
 },
 {
 	"calls: stack depth check using three frames. test2",

tools/testing/selftests/bpf/veristat.c

@@ -993,13 +993,15 @@ static void free_verif_stats(struct verif_stats *stats, size_t stat_cnt)
 
 static char verif_log_buf[64 * 1024];
 
-#define MAX_PARSED_LOG_LINES 100
+/* Keep room for all 256 subprogram records and trailing statistics. */
+#define MAX_PARSED_LOG_LINES 300
 
 static int parse_verif_log(char * const buf, size_t buf_sz, struct verif_stats *s)
 {
 	const char *cur;
-	int pos, lines, sub_stack, cnt = 0;
-	char *state = NULL, *token, stack[512];
+	long sub_stack;
+	int pos, lines, cnt = 0;
+	char *state = NULL, *token, stack[512] = {};
 
 	buf[buf_sz - 1] = '\0';
 
@@ -1025,11 +1027,24 @@ static int parse_verif_log(char * const buf, size_t buf_sz, struct verif_stats *
 				&s->stats[MARK_READ_MAX_LEN]))
 			continue;
 
+		/*
+		 * New kernels emit one "subprog <id> (<name>) <kind>" record
+		 * per subprogram with the stack depth at the end, while old
+		 * kernels emit a single "stack depth <a+...+n> max <max>"
+		 * line. Match both formats so veristat works against either
+		 * kernel.
+		 */
+		if (sscanf(cur, "stack depth max %ld", &s->stats[MAX_STACK]) == 1)
+			continue;
+		if (sscanf(cur, "subprog %*d %*s %*s insns_self %*d insns_total %*d stack %ld", &sub_stack) == 1) {
+			s->stats[STACK] += sub_stack;
+			continue;
+		}
 		if (2 == sscanf(cur, "stack depth %511s max %ld", stack, &s->stats[MAX_STACK]))
 			continue;
 	}
 	while ((token = strtok_r(cnt++ ? NULL : stack, "+", &state))) {
-		if (sscanf(token, "%d", &sub_stack) == 0)
+		if (sscanf(token, "%ld", &sub_stack) == 0)
 			break;
 		s->stats[STACK] += sub_stack;
 	}