Skip to contentSkip to conversation

Improve stack depth verification stats output

PATCH Applied Kumar Kartikeya Dwivedi 5 participants 13 messages Aug 12 – Aug 13

Subsystems (4)
lore
Share & tools
lore

Kumar Kartikeya Dwivedi

author maintainer
#0 lore raw

v8 cover 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/[email protected]

* 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/[email protected]

* 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/[email protected]

* 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/[email protected]

* 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/[email protected]

* 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/[email protected]

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

v1 -> v2
v1: https://lore.kernel.org/bpf/[email protected]

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

Kumar Kartikeya Dwivedi (6):
bpf: Track verifier instruction stats for each subprogram
bpf: Attribute async callback instructions to verification roots
bpf: Show more useful info in stack depth stats selftests/bpf: Adjust veristat stack depth parsing selftests/bpf: Test stack depth stats without BTF subprog names selftests/bpf: Test subprogram instruction statistics

 include/linux/bpf_verifier.h                  |   5 +-
 kernel/bpf/verifier.c                         |  84 +++++--
 .../selftests/bpf/prog_tests/verifier.c       |   2 +
 .../bpf/progs/verifier_basic_stack.c          |   6 +-
 .../bpf/progs/verifier_bpf_fastcall.c         |  28 ++-
 .../bpf/progs/verifier_global_subprogs.c      |   5 +-
 .../bpf/progs/verifier_private_stack.c        |  15 +-
 .../bpf/progs/verifier_subprog_insn_stats.c   | 223 ++++++++++++++++++
 .../selftests/bpf/progs/verifier_var_off.c    |   6 +-
 tools/testing/selftests/bpf/test_verifier.c   |   2 +-
 tools/testing/selftests/bpf/verifier/calls.c  |  12 +-
 tools/testing/selftests/bpf/veristat.c        |  23 +-
 12 files changed, 372 insertions(+), 39 deletions(-)
 create mode 100644 tools/testing/selftests/bpf/progs/verifier_subprog_insn_stats.c

base-commit: 3a59f11e0f989bdd637c87151992605a6559a7cb

Signature · 1 line
2.53.0
author maintainer
#1 lore raw

PATCH v8 1/6 bpf: Track verifier instruction stats for each subprogram

The verifier currently records one instruction count for the main program and each global subprogram checked independently. Static subprograms are explored within callers, so their verification cost cannot be reported separately.

Track both self and inclusive instruction counts for every subprogram. Charge each processed instruction as self work to the current subprogram and to a path-local subtotal in its function frame. When a function returns, add the callee subtotal to its inclusive count and to its parent subtotal. Fold any remaining frames when a path terminates or is pruned.

Instruction subtotals are accounting state, not semantic verifier state. Clear them when a verifier state is copied so work before a path fork is charged once, rather than again when a saved branch is explored. If copying a saved state fails before all frames are allocated, skip missing frames while folding the current path.

This generic frame accounting also records self and inclusive totals when an asynchronous callback starts as a fresh frame-zero state. It does not yet charge that independently explored callback path back to the main or global exploration root which scheduled it. That will be done in subsequent changes.

This does not change the verification statistics output format. It only prepares the counters for per-subprogram reporting.

---
 include/linux/bpf_verifier.h |  5 +++-
 kernel/bpf/verifier.c        | 55 ++++++++++++++++++++++++++++++------
 2 files changed, 50 insertions(+), 10 deletions(-)
include/linux/bpf_verifier.h +4 -1
index 93f7c2075eea..7c376451db82 100644
@@ -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 +46 -9

127 lines not on this page · raw message

Signature · 1 line
2.53.0
author maintainer
#2 lore raw

PATCH v8 2/6 bpf: Attribute async callback instructions to verification roots

In reply to Kumar Kartikeya Dwivedi

Asynchronous callbacks are explored as fresh frame-zero verifier states, so normal callee-to-caller accounting cannot propagate their instruction budget to the main or global subprogram whose verification scheduled them.

The callback exploration still happens within the same do_check_common() invocation as that independent verification root. Record env->insn_processed at do_check_common() entry and override the root's inclusive count with the delta before returning. This includes all directly and transitively scheduled asynchronous callbacks in the root's total without maintaining a separate accounting call stack.

Static subprogram and callback totals remain local to their synchronous call paths. Their self counts continue to account for each processed instruction exactly once.

---
 kernel/bpf/verifier.c | 10 ++++++++++
 1 file changed, 10 insertions(+)
kernel/bpf/verifier.c +10 -0
index 51d754bdef5d..fced21ec2304 100644
@@ -18448,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;
@@ -18590,6 +18591,15 @@ static int do_check_common(struct bpf_verifier_env *env, int subprog)
 	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;
 }
 
Signature · 1 line
2.53.0
maintainer Acked-by on v8 2/6
#3 lore raw

Re: [PATCH bpf-next v8 2/6] bpf: Attribute async callback instructions to verification roots

Quoted 11 lines · Kumar Kartikeya Dwivedi

Asynchronous callbacks are explored as fresh frame-zero verifier states, so normal callee-to-caller accounting cannot propagate their instruction budget to the main or global subprogram whose verification scheduled them.

The callback exploration still happens within the same do_check_common() invocation as that independent verification root. Record env->insn_processed at do_check_common() entry and override the root's inclusive count with the delta before returning. This includes all directly and transitively scheduled asynchronous callbacks in the root's total without maintaining a separate accounting call stack.

Quoted 6 lines

Static subprogram and callback totals remain local to their synchronous call paths. Their self counts continue to account for each processed instruction exactly once.

---

...

author maintainer
#4 lore raw

PATCH v8 3/6 bpf: Show more useful info in stack depth stats

In reply to Kumar Kartikeya Dwivedi

Stack depth statistics list captured depths in subprogram-number order, while per-verification instruction counts are reported separately. Since libbpf determines subprogram numbers, it is hard to associate either statistic with its subprogram name or see where verifier work is spent.

Now that self and inclusive instruction counts are available for every subprogram, keep the combined maximum stack depth on its own line and print one uniform record for each subprogram. Represent the main program as subprog 0, then classify each record as main, global, or static before reporting insns_self, insns_total, and stack depth.

The aggregate processed count is the sum of all self counts, while each total shows verifier work rooted at that subprogram.

When no subprogram name is available, print <unknown>. Keep the existing aggregate "processed ... insns" record unchanged for compatibility.

---
 kernel/bpf/verifier.c                         | 23 +++++++++------
 .../bpf/progs/verifier_basic_stack.c          |  6 ++--
 .../bpf/progs/verifier_bpf_fastcall.c         | 28 +++++++++++++------
 .../bpf/progs/verifier_global_subprogs.c      |  5 +++-
 .../bpf/progs/verifier_private_stack.c        | 15 ++++++++--
 .../selftests/bpf/progs/verifier_var_off.c    |  6 ++--
 6 files changed, 58 insertions(+), 25 deletions(-)
kernel/bpf/verifier.c +14 -9
index fced21ec2304..73d6cd563cdf 100644
@@ -18693,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].insns_total);
-		for (i = 1; i < subprog_cnt; i++)
-			if (bpf_subprog_is_global(env, i))
-				verbose(env, "+%d", env->subprog_info[i].insns_total);
-		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/progs/verifier_basic_stack.c +4 -2
index d3df7a9f1d8c..0eb495ce85c1 100644
@@ -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 +20 -8
index 83707faea049..4cfaa6b4ab40 100644
@@ -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 +4 -1
index 67dc352addfd..7b65eea97ebc 100644
@@ -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 +12 -3
index bb8206e10880..ea0a7e73331d 100644
@@ -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_var_off.c +4 -2
index 24cd0a763673..a63e33675091 100644
@@ -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)
Signature · 1 line
2.53.0
#5 lore raw

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

Thank you for your contribution! Sashiko AI review found 1 potential issue(s) to consider: - [Medium] The patch breaks `veristat`'s ability to parse and track the BPF verifier's stack depth…

Thank you for your contribution! Sashiko AI review found 1 potential issue(s) to consider:
- [Medium] The patch breaks veristat's ability to parse and track the BPF verifier's stack depth statistics (both STACK and MAX_STACK metrics). --

--- Patch [3]: [PATCH bpf-next v8 3/6] bpf: Show more useful info in stack depth stats --- commit de454cf9ad70eafec58298c609cb8cd8aea82368
Author: Kumar Kartikeya Dwivedi <[email protected]>

bpf: Show more useful info in stack depth stats

This commit updates the BPF verifier statistics to report stack depth and instruction counts separately per subprogram. It changes the log output format to display subprogram-specific metrics more clearly, rather than appending depths in a single line.

Quoted 8 lines
kernel/bpf/verifier.c +0 -0
index fced21ec23040..73d6cd563cdf8 100644
@@ -18693,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));

kernel/bpf/verifier.c static void print_verification_stats(struct bpf_verifier_env *env) · line 18696

Quoted 10 lines
kernel/bpf/verifier.c +1 -9
-		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].insns_total);
-		for (i = 1; i < subprog_cnt; i++)
-			if (bpf_subprog_is_global(env, i))
-				verbose(env, "+%d", env->subprog_info[i].insns_total);
-		verbose(env, "\n");
+		verbose(env, "stack depth max %d\n", env->max_stack_depth);

[Severity: Medium]
Does this change in output format break the veristat tool's parsing logic?

Looking at tools/testing/selftests/bpf/veristat.c:parse_verif_log():

	if (2 == sscanf(cur, "stack depth %511s max %ld", stack, &s->stats[MAX_STACK])) {
		...
	}

Because the output format changed from "stack depth %d+%d... max %d\n" to "stack depth max %d\n", sscanf() will match "%511s" to the literal string "max". The expected literal " max " then fails to match the remainder of the string.

This causes sscanf to return 1, leaving s->stats[MAX_STACK] untouched and breaking the stack calculator which tries to parse "max" for integers. Should veristat be updated alongside this change to parse the new output format?

Signature · 1 line
Sashiko AI review · https://sashiko.dev/#/patchset/[email protected]?part=3
#6 lore raw

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

In reply to Kumar Kartikeya Dwivedi
This isn't a bug, but does the middle paragraph add information beyond what the diff shows? It walks through the implementation (keep the max on its own line, represent main as subprog 0, classify…
Quoted 11 lines

Stack depth statistics list captured depths in subprogram-number order, while per-verification instruction counts are reported separately. Since libbpf determines subprogram numbers, it is hard to associate either statistic with its subprogram name or see where verifier work is spent.

Now that self and inclusive instruction counts are available for every subprogram, keep the combined maximum stack depth on its own line and print one uniform record for each subprogram. Represent the main program as subprog 0, then classify each record as main, global, or static before reporting insns_self, insns_total, and stack depth.

Quoted 5 lines

The aggregate processed count is the sum of all self counts, while each total shows verifier work rooted at that subprogram.

When no subprogram name is available, print <unknown>. Keep the existing aggregate "processed ... insns" record unchanged for compatibility.

This isn't a bug, but does the middle paragraph add information beyond what the diff shows? It walks through the implementation (keep the max on its own line, represent main as subprog 0, classify each record), which is visible in the code. Would it help to show the new log format verbatim instead - perhaps one example record - and note which consumers had to change for the format update?

---
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/31647029137

author maintainer
#7 lore raw

PATCH v8 4/6 selftests/bpf: Adjust veristat stack depth parsing

In reply to Kumar Kartikeya Dwivedi

The verifier now reports instruction and stack depth statistics using uniform "subprog <id> (<name>) <kind>" records. Subprogram 0 is classified as main, while other records are global or static. Each record carries insns_self, insns_total, and stack depth.

Teach veristat to parse the new records while retaining support for the legacy one-line stack depth format used by older kernels. Skip both instruction counts and match only through the stack value so fields can still be appended without breaking parsing.

Increase the bounded backward scan so it can include all 256 per-subprogram records.

Zero-initialize the legacy stack buffer because logs using the new format do not populate it before the trailing tokenizer loop. This makes the loop see an empty string instead of reading uninitialized data.

---
 tools/testing/selftests/bpf/veristat.c | 23 +++++++++++++++++++----
 1 file changed, 19 insertions(+), 4 deletions(-)
tools/testing/selftests/bpf/veristat.c +19 -4
index c9c257784ee3..5c0ec3edce72 100644
@@ -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;
 	}
Signature · 1 line
2.53.0
#8 lore raw

Re: [PATCH bpf-next v8 4/6] selftests/bpf: Adjust veristat stack depth parsing

This isn't a bug, but would it read better to keep the same N == sscanf(...) form as the neighbouring checks in this loop, so the block stays consistent?
Quoted 4 lines
tools/testing/selftests/bpf/veristat.c +0 -0
index c9c257784ee3d..5c0ec3edce720 100644

[ ... ]

Quoted 4 lines
tools/testing/selftests/bpf/veristat.c +0 -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;
 

tools/testing/selftests/bpf/veristat.c static int parse_verif_log(char * const buf, size_t buf_sz, struct verif_stats * · line 1039

Quoted 10 lines
tools/testing/selftests/bpf/veristat.c +10 -0
+	/*
+	 * 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) {

This isn't a bug, but would it read better to keep the same N == sscanf(...) form as the neighbouring checks in this loop, so the block stays consistent?

The pre-existing checks just above use:

if (1 == sscanf(cur, "verification time %ld usec\n", ...))

if (5 == sscanf(cur, "processed %ld insns (limit %*d) ...

and the legacy check just below uses:

if (2 == sscanf(cur, "stack depth %511s max %ld", ...

so the new checks alternate the comparison direction within about fifteen lines.

tools/testing/selftests/bpf/veristat.c static int parse_verif_log(char * const buf, size_t buf_sz, struct verif_stats * · line 1045

Quoted 6 lines
tools/testing/selftests/bpf/veristat.c +3 -0
+		s->stats[STACK] += sub_stack;
+		continue;
+	}
 	if (2 == sscanf(cur, "stack depth %511s max %ld", stack, &s->stats[MAX_STACK]))
 		continue;
 }

[ ... ]

---
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/31647029137

author maintainer
#9 lore raw

PATCH v8 5/6 selftests/bpf: Test stack depth stats without BTF subprog names

In reply to Kumar Kartikeya Dwivedi

Test the per-program insns_self, insns_total, and stack depth statistics emitted when BTF function info does not provide subprogram names. Check that the subprog 0 main record and static-subprogram records use <unknown>.

Make VERBOSE_ACCEPT request verifier statistics so the raw-insn test can validate the output without a test-specific log level.

---
 tools/testing/selftests/bpf/test_verifier.c  |  2 +-
 tools/testing/selftests/bpf/verifier/calls.c | 12 +++++++++++-
 2 files changed, 12 insertions(+), 2 deletions(-)
tools/testing/selftests/bpf/test_verifier.c +1 -1
index a8ae03c57bba..bffb7360434c 100644
@@ -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 +11 -1
index 8cd626e04551..eb6e3baef412 100644
@@ -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",
Signature · 1 line
2.53.0
#10 lore raw

Re: [PATCH bpf-next v8 5/6] selftests/bpf: Test stack depth stats without BTF subprog names

This isn't a bug, but since the expected log splits around the insns_self/insns_total values, would it read more accurately to say this checks the record format (names, kind, stack depths) rather…
Quoted 9 lines

Test the per-program insns_self, insns_total, and stack depth statistics emitted when BTF function info does not provide subprogram names. Check that the subprog 0 main record and static-subprogram records use <unknown>.

Make VERBOSE_ACCEPT request verifier statistics so the raw-insn test can validate the output without a test-specific log level.

This isn't a bug, but since the expected log splits around the insns_self/insns_total values, would it read more accurately to say this checks the record format (names, kind, stack depths) rather than the instruction statistics themselves?

Looking at the test's expected string:

.errstr = "stack depth max 352\t"
"subprog 0 (<unknown>) main insns_self \t" " insns_total \t"
" stack 32\t"

The cmp_str_seq() matching only verifies the label text exists, not the actual counts. What gets pinned is the record layout, the subprog ordering, the '<unknown>' names, the main/static classification and the stack depths (32, 256, 64, max 352), but not the instruction counts themselves.

---
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/31647029137

author maintainer
#11 lore raw

PATCH v8 6/6 selftests/bpf: Test subprogram instruction statistics

In reply to Kumar Kartikeya Dwivedi

Add small verifier programs with deterministic instruction streams to exercise per-subprogram self and inclusive instruction accounting. Use assembly for normal call chains and straight-line callback bodies containing only moves, calls, and returns or exits, so control-flow pruning does not make the expected counts unstable. Pass callback arguments as explicit assembly operands so the compiler keeps their registers live across the asm block.

Cover asynchronous callback attribution separately: main verification-root totals include all callback exploration, while static and callback totals remain local to their synchronous paths.

---
 .../selftests/bpf/prog_tests/verifier.c       |   2 +
 .../bpf/progs/verifier_subprog_insn_stats.c   | 223 ++++++++++++++++++
 2 files changed, 225 insertions(+)
 create mode 100644 tools/testing/selftests/bpf/progs/verifier_subprog_insn_stats.c
tools/testing/selftests/bpf/prog_tests/verifier.c +2 -0
index 5b265af3b1d5..8113fea7ba86 100644
@@ -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_subprog_insn_stats.c new file +223 -0

223 lines not on this page · raw message

Signature · 1 line
2.53.0
#12 lore raw
In reply to Kumar Kartikeya Dwivedi
This series was applied to bpf/bpf-next.git (master) by Eduard Zingerman <[email protected]>:

Hello:

This series was applied to bpf/bpf-next.git (master) by Eduard Zingerman <[email protected]>:

Quoted 8 lines · On Thu, 13 Aug 2026 00:19:17 +0200 you wrote:

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:

[...]

Here is the summary with links:
- [bpf-next,v8,1/6] bpf: Track verifier instruction stats for each subprogram

    https://git.kernel.org/bpf/bpf-next/c/14c950ac2be8
  - [bpf-next,v8,2/6] bpf: Attribute async callback instructions to verification roots
    https://git.kernel.org/bpf/bpf-next/c/6137fb7c5f83
  - [bpf-next,v8,3/6] bpf: Show more useful info in stack depth stats
    https://git.kernel.org/bpf/bpf-next/c/c2e6c7de8830
  - [bpf-next,v8,4/6] selftests/bpf: Adjust veristat stack depth parsing
    https://git.kernel.org/bpf/bpf-next/c/502686233493
  - [bpf-next,v8,5/6] selftests/bpf: Test stack depth stats without BTF subprog names
    https://git.kernel.org/bpf/bpf-next/c/b961cf317100
  - [bpf-next,v8,6/6] selftests/bpf: Test subprogram instruction statistics
    https://git.kernel.org/bpf/bpf-next/c/5cb481e1391a

You are awesome, thank you!

Signature · 2 lines
Deet-doot-dot, I am a bot.
https://korg.docs.kernel.org/patchwork/pwbot.html