Skip to content

Commit d9439c2

Browse files
anakryikoAlexei Starovoitov
anakryiko
authored and
Alexei Starovoitov
committed
bpf: improve precision backtrack logging
Add helper to format register and stack masks in more human-readable format. Adjust logging a bit during backtrack propagation and especially during forcing precision fallback logic to make it clearer what's going on (with log_level=2, of course), and also start reporting affected frame depth. This is in preparation for having more than one active frame later when precision propagation between subprog calls is added. Signed-off-by: Andrii Nakryiko <andrii@kernel.org> Link: https://lore.kernel.org/r/20230505043317.3629845-5-andrii@kernel.org Signed-off-by: Alexei Starovoitov <ast@kernel.org>
1 parent 407958a commit d9439c2

3 files changed

Lines changed: 128 additions & 63 deletions

File tree

‎include/linux/bpf_verifier.h‎

Lines changed: 9 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -18,8 +18,11 @@
1818
* that converting umax_value to int cannot overflow.
1919
*/
2020
#define BPF_MAX_VAR_SIZ (1 << 29)
21-
/* size of type_str_buf in bpf_verifier. */
22-
#define TYPE_STR_BUF_LEN 128
21+
/* size of tmp_str_buf in bpf_verifier.
22+
* we need at least 306 bytes to fit full stack mask representation
23+
* (in the "-8,-16,...,-512" form)
24+
*/
25+
#define TMP_STR_BUF_LEN 320
2326

2427
/* Liveness marks, used for registers and spilled-regs (in stack slots).
2528
* Read marks propagate upwards until they find a write mark; they record that
@@ -620,8 +623,10 @@ struct bpf_verifier_env {
620623
/* Same as scratched_regs but for stack slots */
621624
u64 scratched_stack_slots;
622625
u64 prev_log_pos, prev_insn_print_pos;
623-
/* buffer used in reg_type_str() to generate reg_type string */
624-
char type_str_buf[TYPE_STR_BUF_LEN];
626+
/* buffer used to generate temporary string representations,
627+
* e.g., in reg_type_str() to generate reg_type string
628+
*/
629+
char tmp_str_buf[TMP_STR_BUF_LEN];
625630
};
626631

627632
__printf(2, 0) void bpf_verifier_vlog(struct bpf_verifier_log *log,

‎kernel/bpf/verifier.c‎

Lines changed: 65 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -605,9 +605,9 @@ static const char *reg_type_str(struct bpf_verifier_env *env,
605605
type & PTR_TRUSTED ? "trusted_" : ""
606606
);
607607

608-
snprintf(env->type_str_buf, TYPE_STR_BUF_LEN, "%s%s%s",
608+
snprintf(env->tmp_str_buf, TMP_STR_BUF_LEN, "%s%s%s",
609609
prefix, str[base_type(type)], postfix);
610-
return env->type_str_buf;
610+
return env->tmp_str_buf;
611611
}
612612

613613
static char slot_type_char[] = {
@@ -3308,6 +3308,45 @@ static inline bool bt_is_slot_set(struct backtrack_state *bt, u32 slot)
33083308
return bt->stack_masks[bt->frame] & (1ull << slot);
33093309
}
33103310

3311+
/* format registers bitmask, e.g., "r0,r2,r4" for 0x15 mask */
3312+
static void fmt_reg_mask(char *buf, ssize_t buf_sz, u32 reg_mask)
3313+
{
3314+
DECLARE_BITMAP(mask, 64);
3315+
bool first = true;
3316+
int i, n;
3317+
3318+
buf[0] = '\0';
3319+
3320+
bitmap_from_u64(mask, reg_mask);
3321+
for_each_set_bit(i, mask, 32) {
3322+
n = snprintf(buf, buf_sz, "%sr%d", first ? "" : ",", i);
3323+
first = false;
3324+
buf += n;
3325+
buf_sz -= n;
3326+
if (buf_sz < 0)
3327+
break;
3328+
}
3329+
}
3330+
/* format stack slots bitmask, e.g., "-8,-24,-40" for 0x15 mask */
3331+
static void fmt_stack_mask(char *buf, ssize_t buf_sz, u64 stack_mask)
3332+
{
3333+
DECLARE_BITMAP(mask, 64);
3334+
bool first = true;
3335+
int i, n;
3336+
3337+
buf[0] = '\0';
3338+
3339+
bitmap_from_u64(mask, stack_mask);
3340+
for_each_set_bit(i, mask, 64) {
3341+
n = snprintf(buf, buf_sz, "%s%d", first ? "" : ",", -(i + 1) * 8);
3342+
first = false;
3343+
buf += n;
3344+
buf_sz -= n;
3345+
if (buf_sz < 0)
3346+
break;
3347+
}
3348+
}
3349+
33113350
/* For given verifier state backtrack_insn() is called from the last insn to
33123351
* the first insn. Its purpose is to compute a bitmask of registers and
33133352
* stack slots that needs precision in the parent verifier state.
@@ -3331,7 +3370,11 @@ static int backtrack_insn(struct bpf_verifier_env *env, int idx,
33313370
if (insn->code == 0)
33323371
return 0;
33333372
if (env->log.level & BPF_LOG_LEVEL2) {
3334-
verbose(env, "regs=%x stack=%llx before ", bt_reg_mask(bt), bt_stack_mask(bt));
3373+
fmt_reg_mask(env->tmp_str_buf, TMP_STR_BUF_LEN, bt_reg_mask(bt));
3374+
verbose(env, "mark_precise: frame%d: regs=%s ",
3375+
bt->frame, env->tmp_str_buf);
3376+
fmt_stack_mask(env->tmp_str_buf, TMP_STR_BUF_LEN, bt_stack_mask(bt));
3377+
verbose(env, "stack=%s before ", env->tmp_str_buf);
33353378
verbose(env, "%d: ", idx);
33363379
print_bpf_insn(&cbs, insn, env->allow_ptr_leaks);
33373380
}
@@ -3531,6 +3574,11 @@ static void mark_all_scalars_precise(struct bpf_verifier_env *env,
35313574
struct bpf_reg_state *reg;
35323575
int i, j;
35333576

3577+
if (env->log.level & BPF_LOG_LEVEL2) {
3578+
verbose(env, "mark_precise: frame%d: falling back to forcing all scalars precise\n",
3579+
st->curframe);
3580+
}
3581+
35343582
/* big hammer: mark all scalars precise in this path.
35353583
* pop_stack may still get !precise scalars.
35363584
* We also skip current state and go straight to first parent state,
@@ -3542,17 +3590,25 @@ static void mark_all_scalars_precise(struct bpf_verifier_env *env,
35423590
func = st->frame[i];
35433591
for (j = 0; j < BPF_REG_FP; j++) {
35443592
reg = &func->regs[j];
3545-
if (reg->type != SCALAR_VALUE)
3593+
if (reg->type != SCALAR_VALUE || reg->precise)
35463594
continue;
35473595
reg->precise = true;
3596+
if (env->log.level & BPF_LOG_LEVEL2) {
3597+
verbose(env, "force_precise: frame%d: forcing r%d to be precise\n",
3598+
i, j);
3599+
}
35483600
}
35493601
for (j = 0; j < func->allocated_stack / BPF_REG_SIZE; j++) {
35503602
if (!is_spilled_reg(&func->stack[j]))
35513603
continue;
35523604
reg = &func->stack[j].spilled_ptr;
3553-
if (reg->type != SCALAR_VALUE)
3605+
if (reg->type != SCALAR_VALUE || reg->precise)
35543606
continue;
35553607
reg->precise = true;
3608+
if (env->log.level & BPF_LOG_LEVEL2) {
3609+
verbose(env, "force_precise: frame%d: forcing fp%d to be precise\n",
3610+
i, -(j + 1) * 8);
3611+
}
35563612
}
35573613
}
35583614
}
@@ -3716,8 +3772,10 @@ static int __mark_chain_precision(struct bpf_verifier_env *env, int frame, int r
37163772
DECLARE_BITMAP(mask, 64);
37173773
u32 history = st->jmp_history_cnt;
37183774

3719-
if (env->log.level & BPF_LOG_LEVEL2)
3720-
verbose(env, "last_idx %d first_idx %d\n", last_idx, first_idx);
3775+
if (env->log.level & BPF_LOG_LEVEL2) {
3776+
verbose(env, "mark_precise: frame%d: last_idx %d first_idx %d\n",
3777+
bt->frame, last_idx, first_idx);
3778+
}
37213779

37223780
if (last_idx < 0) {
37233781
/* we are at the entry into subprog, which

‎tools/testing/selftests/bpf/verifier/precise.c‎

Lines changed: 54 additions & 52 deletions
Original file line numberDiff line numberDiff line change
@@ -38,25 +38,24 @@
3838
.fixup_map_array_48b = { 1 },
3939
.result = VERBOSE_ACCEPT,
4040
.errstr =
41-
"26: (85) call bpf_probe_read_kernel#113\
42-
last_idx 26 first_idx 20\
43-
regs=4 stack=0 before 25\
44-
regs=4 stack=0 before 24\
45-
regs=4 stack=0 before 23\
46-
regs=4 stack=0 before 22\
47-
regs=4 stack=0 before 20\
48-
parent didn't have regs=4 stack=0 marks\
49-
last_idx 19 first_idx 10\
50-
regs=4 stack=0 before 19\
51-
regs=200 stack=0 before 18\
52-
regs=300 stack=0 before 17\
53-
regs=201 stack=0 before 15\
54-
regs=201 stack=0 before 14\
55-
regs=200 stack=0 before 13\
56-
regs=200 stack=0 before 12\
57-
regs=200 stack=0 before 11\
58-
regs=200 stack=0 before 10\
59-
parent already had regs=0 stack=0 marks",
41+
"mark_precise: frame0: last_idx 26 first_idx 20\
42+
mark_precise: frame0: regs=r2 stack= before 25\
43+
mark_precise: frame0: regs=r2 stack= before 24\
44+
mark_precise: frame0: regs=r2 stack= before 23\
45+
mark_precise: frame0: regs=r2 stack= before 22\
46+
mark_precise: frame0: regs=r2 stack= before 20\
47+
parent didn't have regs=4 stack=0 marks:\
48+
mark_precise: frame0: last_idx 19 first_idx 10\
49+
mark_precise: frame0: regs=r2 stack= before 19\
50+
mark_precise: frame0: regs=r9 stack= before 18\
51+
mark_precise: frame0: regs=r8,r9 stack= before 17\
52+
mark_precise: frame0: regs=r0,r9 stack= before 15\
53+
mark_precise: frame0: regs=r0,r9 stack= before 14\
54+
mark_precise: frame0: regs=r9 stack= before 13\
55+
mark_precise: frame0: regs=r9 stack= before 12\
56+
mark_precise: frame0: regs=r9 stack= before 11\
57+
mark_precise: frame0: regs=r9 stack= before 10\
58+
parent already had regs=0 stack=0 marks:",
6059
},
6160
{
6261
"precise: test 2",
@@ -100,20 +99,20 @@
10099
.flags = BPF_F_TEST_STATE_FREQ,
101100
.errstr =
102101
"26: (85) call bpf_probe_read_kernel#113\
103-
last_idx 26 first_idx 22\
104-
regs=4 stack=0 before 25\
105-
regs=4 stack=0 before 24\
106-
regs=4 stack=0 before 23\
107-
regs=4 stack=0 before 22\
108-
parent didn't have regs=4 stack=0 marks\
109-
last_idx 20 first_idx 20\
110-
regs=4 stack=0 before 20\
111-
parent didn't have regs=4 stack=0 marks\
112-
last_idx 19 first_idx 17\
113-
regs=4 stack=0 before 19\
114-
regs=200 stack=0 before 18\
115-
regs=300 stack=0 before 17\
116-
parent already had regs=0 stack=0 marks",
102+
mark_precise: frame0: last_idx 26 first_idx 22\
103+
mark_precise: frame0: regs=r2 stack= before 25\
104+
mark_precise: frame0: regs=r2 stack= before 24\
105+
mark_precise: frame0: regs=r2 stack= before 23\
106+
mark_precise: frame0: regs=r2 stack= before 22\
107+
parent didn't have regs=4 stack=0 marks:\
108+
mark_precise: frame0: last_idx 20 first_idx 20\
109+
mark_precise: frame0: regs=r2 stack= before 20\
110+
parent didn't have regs=4 stack=0 marks:\
111+
mark_precise: frame0: last_idx 19 first_idx 17\
112+
mark_precise: frame0: regs=r2 stack= before 19\
113+
mark_precise: frame0: regs=r9 stack= before 18\
114+
mark_precise: frame0: regs=r8,r9 stack= before 17\
115+
parent already had regs=0 stack=0 marks:",
117116
},
118117
{
119118
"precise: cross frame pruning",
@@ -153,15 +152,15 @@
153152
},
154153
.prog_type = BPF_PROG_TYPE_XDP,
155154
.flags = BPF_F_TEST_STATE_FREQ,
156-
.errstr = "5: (2d) if r4 > r0 goto pc+0\
157-
last_idx 5 first_idx 5\
158-
parent didn't have regs=10 stack=0 marks\
159-
last_idx 4 first_idx 2\
160-
regs=10 stack=0 before 4\
161-
regs=10 stack=0 before 3\
162-
regs=0 stack=1 before 2\
163-
last_idx 5 first_idx 5\
164-
parent didn't have regs=1 stack=0 marks",
155+
.errstr = "mark_precise: frame0: last_idx 5 first_idx 5\
156+
parent didn't have regs=10 stack=0 marks:\
157+
mark_precise: frame0: last_idx 4 first_idx 2\
158+
mark_precise: frame0: regs=r4 stack= before 4\
159+
mark_precise: frame0: regs=r4 stack= before 3\
160+
mark_precise: frame0: regs= stack=-8 before 2\
161+
mark_precise: frame0: falling back to forcing all scalars precise\
162+
mark_precise: frame0: last_idx 5 first_idx 5\
163+
parent didn't have regs=1 stack=0 marks:",
165164
.result = VERBOSE_ACCEPT,
166165
.retval = -1,
167166
},
@@ -179,16 +178,19 @@
179178
},
180179
.prog_type = BPF_PROG_TYPE_XDP,
181180
.flags = BPF_F_TEST_STATE_FREQ,
182-
.errstr = "last_idx 6 first_idx 6\
183-
parent didn't have regs=10 stack=0 marks\
184-
last_idx 5 first_idx 3\
185-
regs=10 stack=0 before 5\
186-
regs=10 stack=0 before 4\
187-
regs=0 stack=1 before 3\
188-
last_idx 6 first_idx 6\
189-
parent didn't have regs=1 stack=0 marks\
190-
last_idx 5 first_idx 3\
191-
regs=1 stack=0 before 5",
181+
.errstr = "mark_precise: frame0: last_idx 6 first_idx 6\
182+
parent didn't have regs=10 stack=0 marks:\
183+
mark_precise: frame0: last_idx 5 first_idx 3\
184+
mark_precise: frame0: regs=r4 stack= before 5\
185+
mark_precise: frame0: regs=r4 stack= before 4\
186+
mark_precise: frame0: regs= stack=-8 before 3\
187+
mark_precise: frame0: falling back to forcing all scalars precise\
188+
force_precise: frame0: forcing r0 to be precise\
189+
force_precise: frame0: forcing r0 to be precise\
190+
mark_precise: frame0: last_idx 6 first_idx 6\
191+
parent didn't have regs=1 stack=0 marks:\
192+
mark_precise: frame0: last_idx 5 first_idx 3\
193+
mark_precise: frame0: regs=r0 stack= before 5",
192194
.result = VERBOSE_ACCEPT,
193195
.retval = -1,
194196
},

0 commit comments

Comments
 (0)