[PATCH bpf-next] verifier: add prune points to live registers print

[PATCH bpf-next] verifier: add prune points to live registers print

[Mahe Tardy]

Explicitly printing where prune points are placed within the
instructions allows for better debugging of state pruning issues.

	Live regs before insn, prune points (p), and force checkpoints (P):
	      0: ..........   (b7) r1 = 0
	      1: .1........   (63) *(u32 *)(r10 -4) = r1
	      2: ..........   (bf) r2 = r10
	      3: ..2.......   (07) r2 += -4
	      4: ..2.......   (18) r1 = 0xffff8cb747b16000
	      6: .12.......   (85) call bpf_map_lookup_elem#1
	      7: 0..345.... p (bf) r6 = r0
	      8: ...3456... p (15) if r6 == 0x0 goto pc+6
	      9: ...3456...   (b7) r1 = 5
	     10: .1.3456...   (b7) r2 = 3
	     11: .123456... p (85) call pc+5
	     12: 0.....6... p (67) r0 <<= 32
	     13: 0.....6...   (c7) r0 s>>= 32
	     14: 0.....6...   (7b) *(u64 *)(r6 +0) = r0
	     15: .......... p (b7) r0 = 0
	     16: 0.........   (95) exit
	     17: .12....... p (bf) r0 = r2
	     18: 01........   (0f) r0 += r1
	     19: 0.........   (95) exit

Also uses uppercase P for force checkpoints, which are a subset of prune
points (a force checkpoint should already be a prune point).

	Live regs before insn, prune points (p), and force checkpoints (P):
	      0: .......... p (b7) r1 = 1
	      1: .1........ P (e5) may_goto pc+1
	      2: ..........   (05) goto pc-3
	      3: .1........ p (bf) r0 = r1
	      4: 0.........   (95) exit

Existing tests on liveness tracking had to be updated with the new
output format including the prune points.

This proposal patch was presented at Linux Plumbers 2025 in Tokyo along
the "Making Sense of State Pruning" presentation[^1] with the intent of
making state pruning more transparent to the user.

[^1]: https://lpc.events/event/19/contributions/2162/

Co-developed-by: Paul Chaignon <paul.chaignon@gmail.com>
Signed-off-by: Paul Chaignon <paul.chaignon@gmail.com>
Signed-off-by: Mahe Tardy <mahe.tardy@gmail.com>
---
 kernel/bpf/verifier.c                         |   9 +-
 .../bpf/progs/compute_live_registers.c        | 172 +++++++++---------
 .../selftests/bpf/progs/verifier_live_stack.c |  18 +-
 3 files changed, 102 insertions(+), 97 deletions(-)

diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
index d6b8a77fbe3b..a82702405c12 100644
--- a/kernel/bpf/verifier.c
+++ b/kernel/bpf/verifier.c
@@ -24892,7 +24892,7 @@ static int compute_live_registers(struct bpf_verifier_env *env)
 		insn_aux[i].live_regs_before = state[i].in;

 	if (env->log.level & BPF_LOG_LEVEL2) {
-		verbose(env, "Live regs before insn:\n");
+		verbose(env, "Live regs before insn, pruning points (p), and force checkpoints (P):\n");
 		for (i = 0; i < insn_cnt; ++i) {
 			if (env->insn_aux_data[i].scc)
 				verbose(env, "%3d ", env->insn_aux_data[i].scc);
@@ -24904,7 +24904,12 @@ static int compute_live_registers(struct bpf_verifier_env *env)
 					verbose(env, "%d", j);
 				else
 					verbose(env, ".");
-			verbose(env, " ");
+			if (is_force_checkpoint(env, i))
+				verbose(env, " P ");
+			else if (is_prune_point(env, i))
+				verbose(env, " p ");
+			else
+				verbose(env, "   ");
 			verbose_insn(env, &insns[i]);
 			if (bpf_is_ldimm64(&insns[i]))
 				i++;
diff --git a/tools/testing/selftests/bpf/progs/compute_live_registers.c b/tools/testing/selftests/bpf/progs/compute_live_registers.c
index 6884ab99a421..10da72518423 100644
--- a/tools/testing/selftests/bpf/progs/compute_live_registers.c
+++ b/tools/testing/selftests/bpf/progs/compute_live_registers.c
@@ -21,18 +21,18 @@ struct {

 SEC("socket")
 __log_level(2)
-__msg(" 0: .......... (b7) r0 = 42")
-__msg(" 1: 0......... (bf) r1 = r0")
-__msg(" 2: .1........ (bf) r2 = r1")
-__msg(" 3: ..2....... (bf) r3 = r2")
-__msg(" 4: ...3...... (bf) r4 = r3")
-__msg(" 5: ....4..... (bf) r5 = r4")
-__msg(" 6: .....5.... (bf) r6 = r5")
-__msg(" 7: ......6... (bf) r7 = r6")
-__msg(" 8: .......7.. (bf) r8 = r7")
-__msg(" 9: ........8. (bf) r9 = r8")
-__msg("10: .........9 (bf) r0 = r9")
-__msg("11: 0......... (95) exit")
+__msg(" 0: ..........   (b7) r0 = 42")
+__msg(" 1: 0.........   (bf) r1 = r0")
+__msg(" 2: .1........   (bf) r2 = r1")
+__msg(" 3: ..2.......   (bf) r3 = r2")
+__msg(" 4: ...3......   (bf) r4 = r3")
+__msg(" 5: ....4.....   (bf) r5 = r4")
+__msg(" 6: .....5....   (bf) r6 = r5")
+__msg(" 7: ......6...   (bf) r7 = r6")
+__msg(" 8: .......7..   (bf) r8 = r7")
+__msg(" 9: ........8.   (bf) r9 = r8")
+__msg("10: .........9   (bf) r0 = r9")
+__msg("11: 0.........   (95) exit")
 __naked void assign_chain(void)
 {
 	asm volatile (
@@ -53,13 +53,13 @@ __naked void assign_chain(void)

 SEC("socket")
 __log_level(2)
-__msg("0: .......... (b7) r1 = 7")
-__msg("1: .1........ (07) r1 += 7")
-__msg("2: .......... (b7) r2 = 7")
-__msg("3: ..2....... (b7) r3 = 42")
-__msg("4: ..23...... (0f) r2 += r3")
-__msg("5: .......... (b7) r0 = 0")
-__msg("6: 0......... (95) exit")
+__msg("0: ..........   (b7) r1 = 7")
+__msg("1: .1........   (07) r1 += 7")
+__msg("2: ..........   (b7) r2 = 7")
+__msg("3: ..2.......   (b7) r3 = 42")
+__msg("4: ..23......   (0f) r2 += r3")
+__msg("5: ..........   (b7) r0 = 0")
+__msg("6: 0.........   (95) exit")
 __naked void arithmetics(void)
 {
 	asm volatile (
@@ -76,12 +76,12 @@ __naked void arithmetics(void)
 #ifdef CAN_USE_BPF_ST
 SEC("socket")
 __log_level(2)
-__msg("  1: .1........ (07) r1 += -8")
-__msg("  2: .1........ (7a) *(u64 *)(r1 +0) = 7")
-__msg("  3: .1........ (b7) r2 = 42")
-__msg("  4: .12....... (7b) *(u64 *)(r1 +0) = r2")
-__msg("  5: .12....... (7b) *(u64 *)(r1 +0) = r2")
-__msg("  6: .......... (b7) r0 = 0")
+__msg("  1: .1........   (07) r1 += -8")
+__msg("  2: .1........   (7a) *(u64 *)(r1 +0) = 7")
+__msg("  3: .1........   (b7) r2 = 42")
+__msg("  4: .12.......   (7b) *(u64 *)(r1 +0) = r2")
+__msg("  5: .12.......   (7b) *(u64 *)(r1 +0) = r2")
+__msg("  6: ..........   (b7) r0 = 0")
 __naked void store(void)
 {
 	asm volatile (
@@ -99,9 +99,9 @@ __naked void store(void)

 SEC("socket")
 __log_level(2)
-__msg("1: ....4..... (07) r4 += -8")
-__msg("2: ....4..... (79) r5 = *(u64 *)(r4 +0)")
-__msg("3: ....45.... (07) r4 += -8")
+__msg("1: ....4.....   (07) r4 += -8")
+__msg("2: ....4.....   (79) r5 = *(u64 *)(r4 +0)")
+__msg("3: ....45....   (07) r4 += -8")
 __naked void load(void)
 {
 	asm volatile (
@@ -116,9 +116,9 @@ __naked void load(void)

 SEC("socket")
 __log_level(2)
-__msg("0: .1........ (61) r2 = *(u32 *)(r1 +0)")
-__msg("1: ..2....... (d4) r2 = le64 r2")
-__msg("2: ..2....... (bf) r0 = r2")
+__msg("0: .1........   (61) r2 = *(u32 *)(r1 +0)")
+__msg("1: ..2.......   (d4) r2 = le64 r2")
+__msg("2: ..2.......   (bf) r0 = r2")
 __naked void endian(void)
 {
 	asm volatile (
@@ -131,13 +131,13 @@ __naked void endian(void)

 SEC("socket")
 __log_level(2)
-__msg(" 8: 0......... (b7) r1 = 1")
-__msg(" 9: 01........ (db) r1 = atomic64_fetch_add((u64 *)(r0 +0), r1)")
-__msg("10: 01........ (c3) lock *(u32 *)(r0 +0) += r1")
-__msg("11: 01........ (db) r1 = atomic64_xchg((u64 *)(r0 +0), r1)")
-__msg("12: 01........ (bf) r2 = r0")
-__msg("13: .12....... (bf) r0 = r1")
-__msg("14: 012....... (db) r0 = atomic64_cmpxchg((u64 *)(r2 +0), r0, r1)")
+__msg(" 8: 0.........   (b7) r1 = 1")
+__msg(" 9: 01........   (db) r1 = atomic64_fetch_add((u64 *)(r0 +0), r1)")
+__msg("10: 01........   (c3) lock *(u32 *)(r0 +0) += r1")
+__msg("11: 01........   (db) r1 = atomic64_xchg((u64 *)(r0 +0), r1)")
+__msg("12: 01........   (bf) r2 = r0")
+__msg("13: .12.......   (bf) r0 = r1")
+__msg("14: 012.......   (db) r0 = atomic64_cmpxchg((u64 *)(r2 +0), r0, r1)")
 __naked void atomic(void)
 {
 	asm volatile (
@@ -167,9 +167,9 @@ __naked void atomic(void)

 SEC("socket")
 __log_level(2)
-__msg("2: .12....... (db) store_release((u64 *)(r2 -8), r1)")
-__msg("3: .......... (bf) r3 = r10")
-__msg("4: ...3...... (db) r4 = load_acquire((u64 *)(r3 -8))")
+__msg("2: .12.......   (db) store_release((u64 *)(r2 -8), r1)")
+__msg("3: ..........   (bf) r3 = r10")
+__msg("4: ...3......   (db) r4 = load_acquire((u64 *)(r3 -8))")
 __naked void atomic_load_acq_store_rel(void)
 {
 	asm volatile (
@@ -192,8 +192,8 @@ __naked void atomic_load_acq_store_rel(void)

 SEC("socket")
 __log_level(2)
-__msg("4: .12....7.. (85) call bpf_trace_printk#6")
-__msg("5: 0......7.. (0f) r0 += r7")
+__msg("4: .12....7..   (85) call bpf_trace_printk#6")
+__msg("5: 0......7.. p (0f) r0 += r7")
 __naked void regular_call(void)
 {
 	asm volatile (
@@ -211,8 +211,8 @@ __naked void regular_call(void)

 SEC("socket")
 __log_level(2)
-__msg("2: 012....... (25) if r1 > 0x7 goto pc+1")
-__msg("3: ..2....... (bf) r0 = r2")
+__msg("2: 012....... p (25) if r1 > 0x7 goto pc+1")
+__msg("3: ..2.......   (bf) r0 = r2")
 __naked void if1(void)
 {
 	asm volatile (
@@ -226,8 +226,8 @@ __naked void if1(void)

 SEC("socket")
 __log_level(2)
-__msg("3: 0123...... (2d) if r1 > r3 goto pc+1")
-__msg("4: ..2....... (bf) r0 = r2")
+__msg("3: 0123...... p (2d) if r1 > r3 goto pc+1")
+__msg("4: ..2.......   (bf) r0 = r2")
 __naked void if2(void)
 {
 	asm volatile (
@@ -243,7 +243,7 @@ __naked void if2(void)
 /* Verifier misses that r2 is alive if jset is not handled properly */
 SEC("socket")
 __log_level(2)
-__msg("2: 012....... (45) if r1 & 0x7 goto pc+1")
+__msg("2: 012....... p (45) if r1 & 0x7 goto pc+1")
 __naked void if3_jset_bug(void)
 {
 	asm volatile (
@@ -258,15 +258,15 @@ __naked void if3_jset_bug(void)

 SEC("socket")
 __log_level(2)
-__msg("0: .......... (b7) r1 = 0")
-__msg("1: .1........ (b7) r2 = 7")
-__msg("2: .12....... (25) if r1 > 0x7 goto pc+4")
-__msg("3: .12....... (07) r1 += 1")
-__msg("4: .12....... (27) r2 *= 2")
-__msg("5: .12....... (05) goto pc+0")
-__msg("6: .12....... (05) goto pc-5")
-__msg("7: .......... (b7) r0 = 0")
-__msg("8: 0......... (95) exit")
+__msg("0: ..........   (b7) r1 = 0")
+__msg("1: .1........   (b7) r2 = 7")
+__msg("2: .12....... p (25) if r1 > 0x7 goto pc+4")
+__msg("3: .12.......   (07) r1 += 1")
+__msg("4: .12.......   (27) r2 *= 2")
+__msg("5: .12.......   (05) goto pc+0")
+__msg("6: .12....... p (05) goto pc-5")
+__msg("7: .......... p (b7) r0 = 0")
+__msg("8: 0.........   (95) exit")
 __naked void loop(void)
 {
 	asm volatile (
@@ -287,11 +287,11 @@ __naked void loop(void)
 #ifdef CAN_USE_GOTOL
 SEC("socket")
 __log_level(2)
-__msg("2: .123...... (25) if r1 > 0x7 goto pc+2")
-__msg("3: ..2....... (bf) r0 = r2")
-__msg("4: 0......... (06) gotol pc+1")
-__msg("5: ...3...... (bf) r0 = r3")
-__msg("6: 0......... (95) exit")
+__msg("2: .123...... p (25) if r1 > 0x7 goto pc+2")
+__msg("3: ..2.......   (bf) r0 = r2")
+__msg("4: 0.........   (06) gotol pc+1")
+__msg("5: ...3...... p (bf) r0 = r3")
+__msg("6: 0......... p (95) exit")
 __naked void gotol(void)
 {
 	asm volatile (
@@ -310,11 +310,11 @@ __naked void gotol(void)

 SEC("socket")
 __log_level(2)
-__msg("0: .......... (b7) r1 = 1")
-__msg("1: .1........ (e5) may_goto pc+1")
-__msg("2: .......... (05) goto pc-3")
-__msg("3: .1........ (bf) r0 = r1")
-__msg("4: 0......... (95) exit")
+__msg("0: .......... p (b7) r1 = 1")
+__msg("1: .1........ P (e5) may_goto pc+1")
+__msg("2: ..........   (05) goto pc-3")
+__msg("3: .1........ p (bf) r0 = r1")
+__msg("4: 0.........   (95) exit")
 __naked void may_goto(void)
 {
 	asm volatile (
@@ -331,8 +331,8 @@ __naked void may_goto(void)

 SEC("socket")
 __log_level(2)
-__msg("1: 0......... (18) r2 = 0x7")
-__msg("3: 0.2....... (0f) r0 += r2")
+__msg("1: 0.........   (18) r2 = 0x7")
+__msg("3: 0.2.......   (0f) r0 += r2")
 __naked void ldimm64(void)
 {
 	asm volatile (
@@ -347,11 +347,11 @@ __naked void ldimm64(void)
 /* No rules specific for LD_ABS/LD_IND, default behaviour kicks in */
 SEC("socket")
 __log_level(2)
-__msg("2: 0123456789 (30) r0 = *(u8 *)skb[42]")
-__msg("3: 012.456789 (0f) r7 += r0")
-__msg("4: 012.456789 (b7) r3 = 42")
-__msg("5: 0123456789 (50) r0 = *(u8 *)skb[r3 + 0]")
-__msg("6: 0......7.. (0f) r7 += r0")
+__msg("2: 0123456789   (30) r0 = *(u8 *)skb[42]")
+__msg("3: 012.456789   (0f) r7 += r0")
+__msg("4: 012.456789   (b7) r3 = 42")
+__msg("5: 0123456789   (50) r0 = *(u8 *)skb[r3 + 0]")
+__msg("6: 0......7..   (0f) r7 += r0")
 __naked void ldabs(void)
 {
 	asm volatile (
@@ -373,9 +373,9 @@ __naked void ldabs(void)
 #ifdef __BPF_FEATURE_ADDR_SPACE_CAST
 SEC("?fentry.s/" SYS_PREFIX "sys_getpgid")
 __log_level(2)
-__msg(" 6: .12345.... (85) call bpf_arena_alloc_pages")
-__msg(" 7: 0......... (bf) r1 = addr_space_cast(r0, 0, 1)")
-__msg(" 8: .1........ (b7) r2 = 42")
+__msg(" 6: .12345....   (85) call bpf_arena_alloc_pages")
+__msg(" 7: 0......... p (bf) r1 = addr_space_cast(r0, 0, 1)")
+__msg(" 8: .1........   (b7) r2 = 42")
 __naked void addr_space_cast(void)
 {
 	asm volatile (
@@ -408,17 +408,17 @@ static __used __naked int aux1(void)

 SEC("socket")
 __log_level(2)
-__msg("0: ....45.... (b7) r1 = 1")
-__msg("1: .1..45.... (b7) r2 = 2")
-__msg("2: .12.45.... (b7) r3 = 3")
+__msg("0: ....45....   (b7) r1 = 1")
+__msg("1: .1..45....   (b7) r2 = 2")
+__msg("2: .12.45....   (b7) r3 = 3")
 /* Conservative liveness for subprog parameters. */
-__msg("3: .12345.... (85) call pc+2")
-__msg("4: .......... (b7) r0 = 0")
-__msg("5: 0......... (95) exit")
-__msg("6: .12....... (bf) r0 = r1")
-__msg("7: 0.2....... (0f) r0 += r2")
+__msg("3: .12345.... p (85) call pc+2")
+__msg("4: .......... p (b7) r0 = 0")
+__msg("5: 0.........   (95) exit")
+__msg("6: .12....... p (bf) r0 = r1")
+__msg("7: 0.2.......   (0f) r0 += r2")
 /* Conservative liveness for subprog return value. */
-__msg("8: 0......... (95) exit")
+__msg("8: 0.........   (95) exit")
 __naked void subprog1(void)
 {
 	asm volatile (
diff --git a/tools/testing/selftests/bpf/progs/verifier_live_stack.c b/tools/testing/selftests/bpf/progs/verifier_live_stack.c
index 2de105057bbc..105b453be6d3 100644
--- a/tools/testing/selftests/bpf/progs/verifier_live_stack.c
+++ b/tools/testing/selftests/bpf/progs/verifier_live_stack.c
@@ -136,12 +136,12 @@ static __used __naked void write_first_param(void)
 SEC("socket")
 __log_level(2)
 /* caller_stack_read() function */
-__msg("2: .12345.... (85) call pc+4")
-__msg("5: .12345.... (85) call pc+1")
-__msg("6: 0......... (95) exit")
+__msg("2: .12345.... p (85) call pc+4")
+__msg("5: .12345.... p (85) call pc+1")
+__msg("6: 0......... p (95) exit")
 /* read_first_param() function */
-__msg("7: .1........ (79) r0 = *(u64 *)(r1 +0)")
-__msg("8: 0......... (95) exit")
+__msg("7: .1........ p (79) r0 = *(u64 *)(r1 +0)")
+__msg("8: 0.........   (95) exit")
 /* update for callsite at (2) */
 __msg("(2,7) frame 0 insn 7 +live -8")
 __msg("(2,7) live stack update done in 2 iterations")
@@ -177,10 +177,10 @@ SEC("socket")
 __flag(BPF_F_TEST_STATE_FREQ)
 __log_level(2)
 /* read_first_param2() function */
-__msg(" 9: .1........ (79) r0 = *(u64 *)(r1 +0)")
-__msg("10: .......... (b7) r0 = 0")
-__msg("11: 0......... (05) goto pc+0")
-__msg("12: 0......... (95) exit")
+__msg(" 9: .1........ p (79) r0 = *(u64 *)(r1 +0)")
+__msg("10: ..........   (b7) r0 = 0")
+__msg("11: 0.........   (05) goto pc+0")
+__msg("12: 0......... p (95) exit")
 /*
  * The purpose of the test is to check that checkpoint in
  * read_first_param2() stops path traversal. This will only happen if
--
2.34.1

Re: [PATCH bpf-next] verifier: add prune points to live registers print

[Yonghong Song]

On 12/22/25 10:58 AM, Mahe Tardy wrote:
> Explicitly printing where prune points are placed within the
> instructions allows for better debugging of state pruning issues.
>
> 	Live regs before insn, prune points (p), and force checkpoints (P):
> 	      0: ..........   (b7) r1 = 0
> 	      1: .1........   (63) *(u32 *)(r10 -4) = r1
> 	      2: ..........   (bf) r2 = r10
> 	      3: ..2.......   (07) r2 += -4
> 	      4: ..2.......   (18) r1 = 0xffff8cb747b16000
> 	      6: .12.......   (85) call bpf_map_lookup_elem#1
> 	      7: 0..345.... p (bf) r6 = r0
> 	      8: ...3456... p (15) if r6 == 0x0 goto pc+6
> 	      9: ...3456...   (b7) r1 = 5
> 	     10: .1.3456...   (b7) r2 = 3
> 	     11: .123456... p (85) call pc+5
> 	     12: 0.....6... p (67) r0 <<= 32
> 	     13: 0.....6...   (c7) r0 s>>= 32
> 	     14: 0.....6...   (7b) *(u64 *)(r6 +0) = r0
> 	     15: .......... p (b7) r0 = 0
> 	     16: 0.........   (95) exit
> 	     17: .12....... p (bf) r0 = r2
> 	     18: 01........   (0f) r0 += r1
> 	     19: 0.........   (95) exit
>
> Also uses uppercase P for force checkpoints, which are a subset of prune
> points (a force checkpoint should already be a prune point).
>
> 	Live regs before insn, prune points (p), and force checkpoints (P):
> 	      0: .......... p (b7) r1 = 1
> 	      1: .1........ P (e5) may_goto pc+1
> 	      2: ..........   (05) goto pc-3
> 	      3: .1........ p (bf) r0 = r1
> 	      4: 0.........   (95) exit
>
> Existing tests on liveness tracking had to be updated with the new
> output format including the prune points.
>
> This proposal patch was presented at Linux Plumbers 2025 in Tokyo along
> the "Making Sense of State Pruning" presentation[^1] with the intent of
> making state pruning more transparent to the user.
>
> [^1]: https://lpc.events/event/19/contributions/2162/
>
> Co-developed-by: Paul Chaignon <paul.chaignon@gmail.com>
> Signed-off-by: Paul Chaignon <paul.chaignon@gmail.com>
> Signed-off-by: Mahe Tardy <mahe.tardy@gmail.com>

Acked-by: Yonghong Song <yonghong.song@linux.dev>

Re: [PATCH bpf-next] verifier: add prune points to live registers print

[Alexei Starovoitov]

On Mon, Dec 22, 2025 at 8:58 AM Mahe Tardy <mahe.tardy@gmail.com> wrote:
>
> Explicitly printing where prune points are placed within the
> instructions allows for better debugging of state pruning issues.
>
>         Live regs before insn, prune points (p), and force checkpoints (P):
>               0: ..........   (b7) r1 = 0
>               1: .1........   (63) *(u32 *)(r10 -4) = r1
>               2: ..........   (bf) r2 = r10
>               3: ..2.......   (07) r2 += -4
>               4: ..2.......   (18) r1 = 0xffff8cb747b16000
>               6: .12.......   (85) call bpf_map_lookup_elem#1
>               7: 0..345.... p (bf) r6 = r0
>               8: ...3456... p (15) if r6 == 0x0 goto pc+6
>               9: ...3456...   (b7) r1 = 5
>              10: .1.3456...   (b7) r2 = 3
>              11: .123456... p (85) call pc+5
>              12: 0.....6... p (67) r0 <<= 32
>              13: 0.....6...   (c7) r0 s>>= 32
>              14: 0.....6...   (7b) *(u64 *)(r6 +0) = r0
>              15: .......... p (b7) r0 = 0
>              16: 0.........   (95) exit
>              17: .12....... p (bf) r0 = r2
>              18: 01........   (0f) r0 += r1
>              19: 0.........   (95) exit
>
> Also uses uppercase P for force checkpoints, which are a subset of prune
> points (a force checkpoint should already be a prune point).
>
>         Live regs before insn, prune points (p), and force checkpoints (P):
>               0: .......... p (b7) r1 = 1
>               1: .1........ P (e5) may_goto pc+1
>               2: ..........   (05) goto pc-3
>               3: .1........ p (bf) r0 = r1
>               4: 0.........   (95) exit
>
> Existing tests on liveness tracking had to be updated with the new
> output format including the prune points.
>
> This proposal patch was presented at Linux Plumbers 2025 in Tokyo along
> the "Making Sense of State Pruning" presentation[^1] with the intent of
> making state pruning more transparent to the user.
>
> [^1]: https://lpc.events/event/19/contributions/2162/
>
> Co-developed-by: Paul Chaignon <paul.chaignon@gmail.com>
> Signed-off-by: Paul Chaignon <paul.chaignon@gmail.com>
> Signed-off-by: Mahe Tardy <mahe.tardy@gmail.com>
> ---
>  kernel/bpf/verifier.c                         |   9 +-
>  .../bpf/progs/compute_live_registers.c        | 172 +++++++++---------
>  .../selftests/bpf/progs/verifier_live_stack.c |  18 +-
>  3 files changed, 102 insertions(+), 97 deletions(-)
>
> diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
> index d6b8a77fbe3b..a82702405c12 100644
> --- a/kernel/bpf/verifier.c
> +++ b/kernel/bpf/verifier.c
> @@ -24892,7 +24892,7 @@ static int compute_live_registers(struct bpf_verifier_env *env)
>                 insn_aux[i].live_regs_before = state[i].in;
>
>         if (env->log.level & BPF_LOG_LEVEL2) {
> -               verbose(env, "Live regs before insn:\n");
> +               verbose(env, "Live regs before insn, pruning points (p), and force checkpoints (P):\n");
>                 for (i = 0; i < insn_cnt; ++i) {
>                         if (env->insn_aux_data[i].scc)
>                                 verbose(env, "%3d ", env->insn_aux_data[i].scc);
> @@ -24904,7 +24904,12 @@ static int compute_live_registers(struct bpf_verifier_env *env)
>                                         verbose(env, "%d", j);
>                                 else
>                                         verbose(env, ".");
> -                       verbose(env, " ");
> +                       if (is_force_checkpoint(env, i))
> +                               verbose(env, " P ");
> +                       else if (is_prune_point(env, i))
> +                               verbose(env, " p ");
> +                       else
> +                               verbose(env, "   ");

tbh I don't quite see the value. I never needed to know
the exact pruning points while working on the verifier.
It has to work with existing pruning heuristics and with
BPF_F_TEST_STATE_FREQ. So pruning points shouldn't matter
to the verifier algorithms. If they are we have a bigger problem
to solve than show them in the verifier log to users
who won't be able to make much sense of them.

It's my .02. If other folks feel that it's definitely
useful we can introduce this extra verbosity,
but all the churn in the selftests is another indication
of a feature that "nice, but..."

pw-bot: cr

Re: [PATCH bpf-next] verifier: add prune points to live registers print

[Mahe Tardy]

On Mon, Dec 22, 2025 at 08:32:57PM -1000, Alexei Starovoitov wrote:
> On Mon, Dec 22, 2025 at 8:58 AM Mahe Tardy <mahe.tardy@gmail.com> wrote:
> > diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
> > index d6b8a77fbe3b..a82702405c12 100644
> > --- a/kernel/bpf/verifier.c
> > +++ b/kernel/bpf/verifier.c
> > @@ -24892,7 +24892,7 @@ static int compute_live_registers(struct bpf_verifier_env *env)
> >                 insn_aux[i].live_regs_before = state[i].in;
> >
> >         if (env->log.level & BPF_LOG_LEVEL2) {
> > -               verbose(env, "Live regs before insn:\n");
> > +               verbose(env, "Live regs before insn, pruning points (p), and force checkpoints (P):\n");
> >                 for (i = 0; i < insn_cnt; ++i) {
> >                         if (env->insn_aux_data[i].scc)
> >                                 verbose(env, "%3d ", env->insn_aux_data[i].scc);
> > @@ -24904,7 +24904,12 @@ static int compute_live_registers(struct bpf_verifier_env *env)
> >                                         verbose(env, "%d", j);
> >                                 else
> >                                         verbose(env, ".");
> > -                       verbose(env, " ");
> > +                       if (is_force_checkpoint(env, i))
> > +                               verbose(env, " P ");
> > +                       else if (is_prune_point(env, i))
> > +                               verbose(env, " p ");
> > +                       else
> > +                               verbose(env, "   ");
> 
> tbh I don't quite see the value. I never needed to know
> the exact pruning points while working on the verifier.
> It has to work with existing pruning heuristics and with
> BPF_F_TEST_STATE_FREQ. So pruning points shouldn't matter
> to the verifier algorithms. If they are we have a bigger problem
> to solve than show them in the verifier log to users
> who won't be able to make much sense of them.

Yeah I think we would agree with Paul on that. And as you mention, with
the addition of the heuristics on top of prune points, it would maybe be
more useful to know when the verifier actually saves a new state (but
that would increase log verbosity).

> It's my .02. If other folks feel that it's definitely
> useful we can introduce this extra verbosity,
> but all the churn in the selftests is another indication
> of a feature that "nice, but..."

Tbh that's also when I realized that indeed it was "nice, but..." since
because of those changes, all those liveness tests would depend on the
position of prune points. 

At the same time, the new print would allow us to write a series of
tests to check for all the possible cases of prune points as presented
in the talk, not sure it's actually useful as well...

Re: [PATCH bpf-next] verifier: add prune points to live registers print

[Eduard Zingerman]

On Tue, 2025-12-23 at 11:12 +0100, Mahe Tardy wrote:
> On Mon, Dec 22, 2025 at 08:32:57PM -1000, Alexei Starovoitov wrote:
> > On Mon, Dec 22, 2025 at 8:58 AM Mahe Tardy <mahe.tardy@gmail.com> wrote:
> > > diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
> > > index d6b8a77fbe3b..a82702405c12 100644
> > > --- a/kernel/bpf/verifier.c
> > > +++ b/kernel/bpf/verifier.c
> > > @@ -24892,7 +24892,7 @@ static int compute_live_registers(struct bpf_verifier_env *env)
> > >                 insn_aux[i].live_regs_before = state[i].in;
> > > 
> > >         if (env->log.level & BPF_LOG_LEVEL2) {
> > > -               verbose(env, "Live regs before insn:\n");
> > > +               verbose(env, "Live regs before insn, pruning points (p), and force checkpoints (P):\n");
> > >                 for (i = 0; i < insn_cnt; ++i) {
> > >                         if (env->insn_aux_data[i].scc)
> > >                                 verbose(env, "%3d ", env->insn_aux_data[i].scc);
> > > @@ -24904,7 +24904,12 @@ static int compute_live_registers(struct bpf_verifier_env *env)
> > >                                         verbose(env, "%d", j);
> > >                                 else
> > >                                         verbose(env, ".");
> > > -                       verbose(env, " ");
> > > +                       if (is_force_checkpoint(env, i))
> > > +                               verbose(env, " P ");
> > > +                       else if (is_prune_point(env, i))
> > > +                               verbose(env, " p ");
> > > +                       else
> > > +                               verbose(env, "   ");
> > 
> > tbh I don't quite see the value. I never needed to know
> > the exact pruning points while working on the verifier.
> > It has to work with existing pruning heuristics and with
> > BPF_F_TEST_STATE_FREQ. So pruning points shouldn't matter
> > to the verifier algorithms. If they are we have a bigger problem
> > to solve than show them in the verifier log to users
> > who won't be able to make much sense of them.
> 
> Yeah I think we would agree with Paul on that. And as you mention, with
> the addition of the heuristics on top of prune points, it would maybe be
> more useful to know when the verifier actually saves a new state (but
> that would increase log verbosity).
> 
> > It's my .02. If other folks feel that it's definitely
> > useful we can introduce this extra verbosity,
> > but all the churn in the selftests is another indication
> > of a feature that "nice, but..."
> 
> Tbh that's also when I realized that indeed it was "nice, but..." since
> because of those changes, all those liveness tests would depend on the
> position of prune points. 
> 
> At the same time, the new print would allow us to write a series of
> tests to check for all the possible cases of prune points as presented
> in the talk, not sure it's actually useful as well...

Hi Everyone,

Sorry, a bit late to the discussion, here are another .02 cents.
Tbh, I'm neither for nor against printing these marks.
Knowing where exactly the checkpoints are is helpful to me sometimes
when I'd like to construct a specific test. On the other hand,
I can always add debug prints locally + you do learn the rules for
checkpoints after some time.  If we go for it, we should probably
distinguish between prune points and "force checkpoints" ('f'?).

Imo, it would be indeed more interesting to print where checkpoint
match had been attempted and why it failed, e.g. as I do in [1].
Here is a sample:

  cache miss at (140, 5389): frame=1, reg=0, spi=-1, loop=0 (cur: 1) vs (old: P0)
  from 5387 to 5389: frame1: R0=1 R1=0xffffffff ...

However, in the current form it slows down log level 2 output
significantly (~5 times). Okay for my debugging purposes but is not
good for upstream submission.

Thanks,
Eduard.

[1] https://github.com/kernel-patches/bpf/commit/65fcd66d03ad9d6979df79628e569b90563d5368

Re: [PATCH bpf-next] verifier: add prune points to live registers print

[Alexei Starovoitov]

On Mon, Dec 29, 2025 at 10:48 AM Eduard Zingerman <eddyz87@gmail.com> wrote:
>
> On Tue, 2025-12-23 at 11:12 +0100, Mahe Tardy wrote:
> > On Mon, Dec 22, 2025 at 08:32:57PM -1000, Alexei Starovoitov wrote:
> > > On Mon, Dec 22, 2025 at 8:58 AM Mahe Tardy <mahe.tardy@gmail.com> wrote:
> > > > diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
> > > > index d6b8a77fbe3b..a82702405c12 100644
> > > > --- a/kernel/bpf/verifier.c
> > > > +++ b/kernel/bpf/verifier.c
> > > > @@ -24892,7 +24892,7 @@ static int compute_live_registers(struct bpf_verifier_env *env)
> > > >                 insn_aux[i].live_regs_before = state[i].in;
> > > >
> > > >         if (env->log.level & BPF_LOG_LEVEL2) {
> > > > -               verbose(env, "Live regs before insn:\n");
> > > > +               verbose(env, "Live regs before insn, pruning points (p), and force checkpoints (P):\n");
> > > >                 for (i = 0; i < insn_cnt; ++i) {
> > > >                         if (env->insn_aux_data[i].scc)
> > > >                                 verbose(env, "%3d ", env->insn_aux_data[i].scc);
> > > > @@ -24904,7 +24904,12 @@ static int compute_live_registers(struct bpf_verifier_env *env)
> > > >                                         verbose(env, "%d", j);
> > > >                                 else
> > > >                                         verbose(env, ".");
> > > > -                       verbose(env, " ");
> > > > +                       if (is_force_checkpoint(env, i))
> > > > +                               verbose(env, " P ");
> > > > +                       else if (is_prune_point(env, i))
> > > > +                               verbose(env, " p ");
> > > > +                       else
> > > > +                               verbose(env, "   ");
> > >
> > > tbh I don't quite see the value. I never needed to know
> > > the exact pruning points while working on the verifier.
> > > It has to work with existing pruning heuristics and with
> > > BPF_F_TEST_STATE_FREQ. So pruning points shouldn't matter
> > > to the verifier algorithms. If they are we have a bigger problem
> > > to solve than show them in the verifier log to users
> > > who won't be able to make much sense of them.
> >
> > Yeah I think we would agree with Paul on that. And as you mention, with
> > the addition of the heuristics on top of prune points, it would maybe be
> > more useful to know when the verifier actually saves a new state (but
> > that would increase log verbosity).
> >
> > > It's my .02. If other folks feel that it's definitely
> > > useful we can introduce this extra verbosity,
> > > but all the churn in the selftests is another indication
> > > of a feature that "nice, but..."
> >
> > Tbh that's also when I realized that indeed it was "nice, but..." since
> > because of those changes, all those liveness tests would depend on the
> > position of prune points.
> >
> > At the same time, the new print would allow us to write a series of
> > tests to check for all the possible cases of prune points as presented
> > in the talk, not sure it's actually useful as well...
>
> Hi Everyone,
>
> Sorry, a bit late to the discussion, here are another .02 cents.
> Tbh, I'm neither for nor against printing these marks.
> Knowing where exactly the checkpoints are is helpful to me sometimes
> when I'd like to construct a specific test. On the other hand,
> I can always add debug prints locally + you do learn the rules for
> checkpoints after some time.  If we go for it, we should probably
> distinguish between prune points and "force checkpoints" ('f'?).

and this kind of bikeshedding is why I think we shouldn't print either:
prune point, force checkpoint, jmp point.
They are useful in some debugging, but rarely universally needed.
Also the change may or may not screw up bpfvv parsing.
Not saying that we shouldn't improve verifier logging, but
it really needs to have a strong signal.

> Imo, it would be indeed more interesting to print where checkpoint
> match had been attempted and why it failed, e.g. as I do in [1].
> Here is a sample:
>
>   cache miss at (140, 5389): frame=1, reg=0, spi=-1, loop=0 (cur: 1) vs (old: P0)
>   from 5387 to 5389: frame1: R0=1 R1=0xffffffff ...
>
> However, in the current form it slows down log level 2 output
> significantly (~5 times). Okay for my debugging purposes but is not
> good for upstream submission.
>
> Thanks,
> Eduard.
>
> [1] https://github.com/kernel-patches/bpf/commit/65fcd66d03ad9d6979df79628e569b90563d5368

bpf_print_stack_state() refactor can land.
While the rest potentially bpfvv can do.
With log_level==2 all the previous paths through particular instruction
will be in the log earlier, so I can imagine clicking on an insn
and it will show current and all previous seen states.
The verifier heuristic will drop some of them, so it will show more
than actually known during the verification, but that's probably ok
for debugging to see why states don't converge.
bpfvv can make it easier to see the difference too instead of
"frame=1, reg=0, spi=-1, loop=0 (cur: 1) vs (old: P0)"
which is not easy to understand.
Only after reading the diff I realized that reg R0 is the one
that caused a mismatch.

Re: [PATCH bpf-next] verifier: add prune points to live registers print

[Eduard Zingerman]

On Mon, 2025-12-29 at 16:42 -0800, Alexei Starovoitov wrote:

[...]

> > Imo, it would be indeed more interesting to print where checkpoint
> > match had been attempted and why it failed, e.g. as I do in [1].
> > Here is a sample:
> > 
> >   cache miss at (140, 5389): frame=1, reg=0, spi=-1, loop=0 (cur: 1) vs (old: P0)
> >   from 5387 to 5389: frame1: R0=1 R1=0xffffffff ...
> > 
> > However, in the current form it slows down log level 2 output
> > significantly (~5 times). Okay for my debugging purposes but is not
> > good for upstream submission.
> > 
> > Thanks,
> > Eduard.
> > 
> > [1] https://github.com/kernel-patches/bpf/commit/65fcd66d03ad9d6979df79628e569b90563d5368
> 
> bpf_print_stack_state() refactor can land.
> While the rest potentially bpfvv can do.
> With log_level==2 all the previous paths through particular instruction
> will be in the log earlier, so I can imagine clicking on an insn
> and it will show current and all previous seen states.
> The verifier heuristic will drop some of them, so it will show more
> than actually known during the verification, but that's probably ok
> for debugging to see why states don't converge.
> bpfvv can make it easier to see the difference too instead of
> "frame=1, reg=0, spi=-1, loop=0 (cur: 1) vs (old: P0)"
> which is not easy to understand.
> Only after reading the diff I realized that reg R0 is the one
> that caused a mismatch.

In theory this can be handled in post-processing completely,
however I'd expect mirroring states-equal logic in bpfvv
(or any other tool) to be error prone. Which is very undesirable when
you are debugging. To make post-processing simpler I'd print:
- state id upon state creation
- state ids upon cache miss + register or spi number.

This way post-processing tool would only need to collect register
values for state ids in question.

Idk, not sure if any of this should be upstreamed, I'm fine with it
living in my debug branch. On the other hand, this might be useful for
people debugging 1M instruction issues, as I discussed with
Paul Chaignon and Shung-Hsi Yu at LPC.

Re: [PATCH bpf-next] verifier: add prune points to live registers print

[Alexei Starovoitov]

On Mon, Dec 29, 2025 at 5:13 PM Eduard Zingerman <eddyz87@gmail.com> wrote:
>
> On Mon, 2025-12-29 at 16:42 -0800, Alexei Starovoitov wrote:
>
> [...]
>
> > > Imo, it would be indeed more interesting to print where checkpoint
> > > match had been attempted and why it failed, e.g. as I do in [1].
> > > Here is a sample:
> > >
> > >   cache miss at (140, 5389): frame=1, reg=0, spi=-1, loop=0 (cur: 1) vs (old: P0)
> > >   from 5387 to 5389: frame1: R0=1 R1=0xffffffff ...
> > >
> > > However, in the current form it slows down log level 2 output
> > > significantly (~5 times). Okay for my debugging purposes but is not
> > > good for upstream submission.
> > >
> > > Thanks,
> > > Eduard.
> > >
> > > [1] https://github.com/kernel-patches/bpf/commit/65fcd66d03ad9d6979df79628e569b90563d5368
> >
> > bpf_print_stack_state() refactor can land.
> > While the rest potentially bpfvv can do.
> > With log_level==2 all the previous paths through particular instruction
> > will be in the log earlier, so I can imagine clicking on an insn
> > and it will show current and all previous seen states.
> > The verifier heuristic will drop some of them, so it will show more
> > than actually known during the verification, but that's probably ok
> > for debugging to see why states don't converge.
> > bpfvv can make it easier to see the difference too instead of
> > "frame=1, reg=0, spi=-1, loop=0 (cur: 1) vs (old: P0)"
> > which is not easy to understand.
> > Only after reading the diff I realized that reg R0 is the one
> > that caused a mismatch.
>
> In theory this can be handled in post-processing completely,
> however I'd expect mirroring states-equal logic in bpfvv
> (or any other tool) to be error prone. Which is very undesirable when
> you are debugging. To make post-processing simpler I'd print:
> - state id upon state creation
> - state ids upon cache miss + register or spi number.
>
> This way post-processing tool would only need to collect register
> values for state ids in question.

that will make post processing easier, but print on every miss
will greatly increase log_level=2 size, right ?
and whole new concept of state ids just to make a post processing
better. I'm not convinced it's worth doing.

Re: [PATCH bpf-next] verifier: add prune points to live registers print

[Eduard Zingerman]

On Tue, 2025-12-30 at 10:06 -0800, Alexei Starovoitov wrote:
> On Mon, Dec 29, 2025 at 5:13 PM Eduard Zingerman <eddyz87@gmail.com> wrote:
> > 
> > On Mon, 2025-12-29 at 16:42 -0800, Alexei Starovoitov wrote:
> > 
> > [...]
> > 
> > > > Imo, it would be indeed more interesting to print where checkpoint
> > > > match had been attempted and why it failed, e.g. as I do in [1].
> > > > Here is a sample:
> > > > 
> > > >   cache miss at (140, 5389): frame=1, reg=0, spi=-1, loop=0 (cur: 1) vs (old: P0)
> > > >   from 5387 to 5389: frame1: R0=1 R1=0xffffffff ...
> > > > 
> > > > However, in the current form it slows down log level 2 output
> > > > significantly (~5 times). Okay for my debugging purposes but is not
> > > > good for upstream submission.
> > > > 
> > > > Thanks,
> > > > Eduard.
> > > > 
> > > > [1] https://github.com/kernel-patches/bpf/commit/65fcd66d03ad9d6979df79628e569b90563d5368
> > > 
> > > bpf_print_stack_state() refactor can land.
> > > While the rest potentially bpfvv can do.
> > > With log_level==2 all the previous paths through particular instruction
> > > will be in the log earlier, so I can imagine clicking on an insn
> > > and it will show current and all previous seen states.
> > > The verifier heuristic will drop some of them, so it will show more
> > > than actually known during the verification, but that's probably ok
> > > for debugging to see why states don't converge.
> > > bpfvv can make it easier to see the difference too instead of
> > > "frame=1, reg=0, spi=-1, loop=0 (cur: 1) vs (old: P0)"
> > > which is not easy to understand.
> > > Only after reading the diff I realized that reg R0 is the one
> > > that caused a mismatch.
> > 
> > In theory this can be handled in post-processing completely,
> > however I'd expect mirroring states-equal logic in bpfvv
> > (or any other tool) to be error prone. Which is very undesirable when
> > you are debugging. To make post-processing simpler I'd print:
> > - state id upon state creation
> > - state ids upon cache miss + register or spi number.
> > 
> > This way post-processing tool would only need to collect register
> > values for state ids in question.
> 
> that will make post processing easier, but print on every miss
> will greatly increase log_level=2 size, right ?

Here are some stats for pyperf180:

| Experiment                                  | Log   | Log  |
| Kind                                        | Lines | Size |
|---------------------------------------------+-------+------|
| Print cache hits, misses and diffing values | 626K  | 88M  |
| Print cache misses and diffing values       | 618K  | 88M  |
| Print cache misses                          | 618K  | 87M  |
| Default level 2 log                         | 577K  | 85M  |

By "cache hit", "cache miss", "cache miss and diffing values" I mean
printing lines like:

  cache hit at (44677): loop=0
  cache miss at (36030): frame=0, reg=7, spi=-1, loop=0
  cache miss at (36030): frame=0, reg=7, spi=-1, loop=0 (cur: scalar(id=3618)) vs (old: Pscalar(id=3258,umin=1))

Didn't try printing message at each new state creation.

> and whole new concept of state ids just to make a post processing
> better. I'm not convinced it's worth doing.

That might be true.
But we do need some instrument to help debugging 1M instructions situation.

Re: [PATCH bpf-next] verifier: add prune points to live registers print

[Alexei Starovoitov]

On Tue, Dec 30, 2025 at 10:44 AM Eduard Zingerman <eddyz87@gmail.com> wrote:
>
> >
> > that will make post processing easier, but print on every miss
> > will greatly increase log_level=2 size, right ?
>
> Here are some stats for pyperf180:
>
> | Experiment                                  | Log   | Log  |
> | Kind                                        | Lines | Size |
> |---------------------------------------------+-------+------|
> | Print cache hits, misses and diffing values | 626K  | 88M  |
> | Print cache misses and diffing values       | 618K  | 88M  |
> | Print cache misses                          | 618K  | 87M  |
> | Default level 2 log                         | 577K  | 85M  |

hmm. That's not that much.
Then I don't understand why you said:
"slows down log level 2 output significantly (~5 times)"

If the total output is roughly the same, how come it's 5 times slower??

> By "cache hit", "cache miss", "cache miss and diffing values" I mean
> printing lines like:
>
>   cache hit at (44677): loop=0
>   cache miss at (36030): frame=0, reg=7, spi=-1, loop=0
>   cache miss at (36030): frame=0, reg=7, spi=-1, loop=0 (cur: scalar(id=3618)) vs (old: Pscalar(id=3258,umin=1))
>
> Didn't try printing message at each new state creation.
>
> > and whole new concept of state ids just to make a post processing
> > better. I'm not convinced it's worth doing.
>
> That might be true.
> But we do need some instrument to help debugging 1M instructions situation.

Re: [PATCH bpf-next] verifier: add prune points to live registers print

[Eduard Zingerman]

On Tue, 2025-12-30 at 17:11 -0800, Alexei Starovoitov wrote:
> On Tue, Dec 30, 2025 at 10:44 AM Eduard Zingerman <eddyz87@gmail.com> wrote:
> > 
> > > 
> > > that will make post processing easier, but print on every miss
> > > will greatly increase log_level=2 size, right ?
> > 
> > Here are some stats for pyperf180:
> > 
> > > Experiment                                  | Log   | Log  |
> > > Kind                                        | Lines | Size |
> > > ---------------------------------------------+-------+------|
> > > Print cache hits, misses and diffing values | 626K  | 88M  |
> > > Print cache misses and diffing values       | 618K  | 88M  |
> > > Print cache misses                          | 618K  | 87M  |
> > > Default level 2 log                         | 577K  | 85M  |
> 
> hmm. That's not that much.
> Then I don't understand why you said:
> "slows down log level 2 output significantly (~5 times)"
> 
> If the total output is roughly the same, how come it's 5 times slower??

That's an interesting question.
Double checked the log for the failing program I was debugging
(internal, hits 1M limit): 6M lines total, 1.4M lines are "cache ...",
so 20% instead of 8% for pyperf180.
Still does not explain the performance difference.
I'll check what happens using profiler.