[bpf-next] selftests/bpf: reduce verboseness of reg_bounds selftest logs

Commit Message

Andrii Nakryiko Nov. 20, 2023, 6:04 p.m. UTC

Reduce verboseness of test_progs' output in reg_bounds set of tests with
two changes.

First, instead of each different operator (<, <=, >, ...) being it's own
subtest, combine all different ops for the same (x, y, init_t, cond_t)
values into single subtest. Instead of getting 6 subtests, we get one
generic one, e.g.:

  #192/53  reg_bounds_crafted/(s64)[0xffffffffffffffff; 0] (s64)<op> 0xffffffff00000000:OK

Second, for random generated test cases, treat all of them as a single
test to eliminate very verbose output with random values in them. So now
we'll just get one line per each combination of (init_t, cond_t),
instead of 6 x 25 = 150 subtests before this change:

  #225     reg_bounds_rand_consts_s32_s32:OK

Given we reduce verboseness so much, it makes sense to do a bit more
random testing, so we also bump default number of random tests to 100,
up from 25. This doesn't increase runtime significantly, especially in
parallelized mode.

With all the above changes we still make sure that we have all the
information necessary for reproducing test case if it happens to fail.
That includes reporting random seed and specific operator that is
failing. Those will only be printed to console if related test/subtest
fails, so it doesn't have any added verboseness implications.

Signed-off-by: Andrii Nakryiko <[e-mail]>
---
 .../selftests/bpf/prog_tests/reg_bounds.c     | 32 ++++++++++++-------
 1 file changed, 21 insertions(+), 11 deletions(-)

Comments

Alexei Starovoitov Nov. 20, 2023, 8:57 p.m. UTC | #1

On Mon, Nov 20, 2023 at 10:05 AM Andrii Nakryiko <[e-mail]> wrote:
>
> Reduce verboseness of test_progs' output in reg_bounds set of tests with
> two changes.
>
> First, instead of each different operator (<, <=, >, ...) being it's own
> subtest, combine all different ops for the same (x, y, init_t, cond_t)
> values into single subtest. Instead of getting 6 subtests, we get one
> generic one, e.g.:
>
>   #192/53  reg_bounds_crafted/(s64)[0xffffffffffffffff; 0] (s64)<op> 0xffffffff00000000:OK
>
> Second, for random generated test cases, treat all of them as a single
> test to eliminate very verbose output with random values in them. So now
> we'll just get one line per each combination of (init_t, cond_t),
> instead of 6 x 25 = 150 subtests before this change:
>
>   #225     reg_bounds_rand_consts_s32_s32:OK
>
> Given we reduce verboseness so much, it makes sense to do a bit more
> random testing, so we also bump default number of random tests to 100,
> up from 25. This doesn't increase runtime significantly, especially in
> parallelized mode.
>
> With all the above changes we still make sure that we have all the
> information necessary for reproducing test case if it happens to fail.
> That includes reporting random seed and specific operator that is
> failing. Those will only be printed to console if related test/subtest
> fails, so it doesn't have any added verboseness implications.

Thanks for the quick fix. Applied.

I also noticed:
#200     reg_bounds_gen_consts_s64_u64:SKIP
#201     reg_bounds_gen_consts_u32_s32:SKIP
#202     reg_bounds_gen_consts_u32_s64:SKIP
#203     reg_bounds_gen_consts_u32_u32:SKIP
#204     reg_bounds_gen_consts_u32_u64:SKIP

what is the reason for SKIP ?

[e-mail] Nov. 20, 2023, 9 p.m. UTC | #2

Hello:

This patch was applied to bpf/bpf-next.git (master)
by Alexei Starovoitov <[e-mail]>:

On Mon, 20 Nov 2023 10:04:52 -0800 you wrote:
> Reduce verboseness of test_progs' output in reg_bounds set of tests with
> two changes.
> 
> First, instead of each different operator (<, <=, >, ...) being it's own
> subtest, combine all different ops for the same (x, y, init_t, cond_t)
> values into single subtest. Instead of getting 6 subtests, we get one
> generic one, e.g.:
> 
> [...]

Here is the summary with links:
  - [bpf-next] selftests/bpf: reduce verboseness of reg_bounds selftest logs
    https://git.kernel.org/bpf/bpf-next/c/57b97ecb40ca

You are awesome, thank you!

Andrii Nakryiko Nov. 21, 2023, 12:33 a.m. UTC | #3

On Mon, Nov 20, 2023 at 12:57 PM Alexei Starovoitov
<[e-mail]> wrote:
>
> On Mon, Nov 20, 2023 at 10:05 AM Andrii Nakryiko <[e-mail]> wrote:
> >
> > Reduce verboseness of test_progs' output in reg_bounds set of tests with
> > two changes.
> >
> > First, instead of each different operator (<, <=, >, ...) being it's own
> > subtest, combine all different ops for the same (x, y, init_t, cond_t)
> > values into single subtest. Instead of getting 6 subtests, we get one
> > generic one, e.g.:
> >
> >   #192/53  reg_bounds_crafted/(s64)[0xffffffffffffffff; 0] (s64)<op> 0xffffffff00000000:OK
> >
> > Second, for random generated test cases, treat all of them as a single
> > test to eliminate very verbose output with random values in them. So now
> > we'll just get one line per each combination of (init_t, cond_t),
> > instead of 6 x 25 = 150 subtests before this change:
> >
> >   #225     reg_bounds_rand_consts_s32_s32:OK
> >
> > Given we reduce verboseness so much, it makes sense to do a bit more
> > random testing, so we also bump default number of random tests to 100,
> > up from 25. This doesn't increase runtime significantly, especially in
> > parallelized mode.
> >
> > With all the above changes we still make sure that we have all the
> > information necessary for reproducing test case if it happens to fail.
> > That includes reporting random seed and specific operator that is
> > failing. Those will only be printed to console if related test/subtest
> > fails, so it doesn't have any added verboseness implications.
>
> Thanks for the quick fix. Applied.
>
> I also noticed:
> #200     reg_bounds_gen_consts_s64_u64:SKIP
> #201     reg_bounds_gen_consts_u32_s32:SKIP
> #202     reg_bounds_gen_consts_u32_s64:SKIP
> #203     reg_bounds_gen_consts_u32_u32:SKIP
> #204     reg_bounds_gen_consts_u32_u64:SKIP
>
> what is the reason for SKIP ?

Those are "slow tests". If they don't see `SLOW_TESTS=1` envvar, they
will mark themselves as skipped. This patch didn't change this
behavior, it was like that before.

Patch

diff --git a/tools/testing/selftests/bpf/prog_tests/reg_bounds.c b/tools/testing/selftests/bpf/prog_tests/reg_bounds.c
index fd4ab23e6f54..0c9abd279e18 100644
--- a/tools/testing/selftests/bpf/prog_tests/reg_bounds.c
+++ b/tools/testing/selftests/bpf/prog_tests/reg_bounds.c
@@ -1361,11 +1361,11 @@  struct subtest_case {
 	enum op op;
 };
 
-static void subtest_case_str(struct strbuf *sb, struct subtest_case *t)
+static void subtest_case_str(struct strbuf *sb, struct subtest_case *t, bool use_op)
 {
 	snappendf(sb, "(%s)", t_str(t->init_t));
 	snprintf_range(t->init_t, sb, t->x);
-	snappendf(sb, " (%s)%s ", t_str(t->cond_t), op_str(t->op));
+	snappendf(sb, " (%s)%s ", t_str(t->cond_t), use_op ? op_str(t->op) : "<op>");
 	snprintf_range(t->init_t, sb, t->y);
 }
 
@@ -1440,8 +1440,8 @@  static int verify_case_op(enum num_t init_t, enum num_t cond_t,
 /* Given setup ranges and number types, go over all supported operations,
  * generating individual subtest for each allowed combination
  */
-static int verify_case(struct ctx *ctx, enum num_t init_t, enum num_t cond_t,
-		       struct range x, struct range y)
+static int verify_case_opt(struct ctx *ctx, enum num_t init_t, enum num_t cond_t,
+			   struct range x, struct range y, bool is_subtest)
 {
 	DEFINE_STRBUF(sb, 256);
 	int err;
@@ -1452,11 +1452,14 @@  static int verify_case(struct ctx *ctx, enum num_t init_t, enum num_t cond_t,
 		.y = y,
 	};
 
+	sb->pos = 0; /* reset position in strbuf */
+	subtest_case_str(sb, &sub, false /* ignore op */);
+	if (is_subtest && !test__start_subtest(sb->buf))
+		return 0;
+
 	for (sub.op = first_op; sub.op <= last_op; sub.op++) {
 		sb->pos = 0; /* reset position in strbuf */
-		subtest_case_str(sb, &sub);
-		if (!test__start_subtest(sb->buf))
-			continue;
+		subtest_case_str(sb, &sub, true /* print op */);
 
 		if (env.verbosity >= VERBOSE_NORMAL) /* this speeds up debugging */
 			printf("TEST CASE: %s\n", sb->buf);
@@ -1491,6 +1494,12 @@  static int verify_case(struct ctx *ctx, enum num_t init_t, enum num_t cond_t,
 	return 0;
 }
 
+static int verify_case(struct ctx *ctx, enum num_t init_t, enum num_t cond_t,
+		       struct range x, struct range y)
+{
+	return verify_case_opt(ctx, init_t, cond_t, x, y, true /* is_subtest */);
+}
+
 /* ================================
  * GENERATED CASES FROM SEED VALUES
  * ================================
@@ -1913,7 +1922,7 @@  void test_reg_bounds_gen_ranges_s32_s64(void) { validate_gen_range_vs_range(S32,
 void test_reg_bounds_gen_ranges_s32_u32(void) { validate_gen_range_vs_range(S32, U32); }
 void test_reg_bounds_gen_ranges_s32_s32(void) { validate_gen_range_vs_range(S32, S32); }
 
-#define DEFAULT_RAND_CASE_CNT 25
+#define DEFAULT_RAND_CASE_CNT 100
 
 #define RAND_21BIT_MASK ((1 << 22) - 1)
 
@@ -1968,7 +1977,6 @@  static void validate_rand_ranges(enum num_t init_t, enum num_t cond_t, bool cons
 		 "[RANDOM SEED %u] RANGE x %s, %s -> %s",
 		 ctx.rand_seed, const_range ? "CONST" : "RANGE",
 		 t_str(init_t), t_str(cond_t));
-	fprintf(env.stdout, "%s\n", ctx.progress_ctx);
 
 	for (i = 0; i < ctx.rand_case_cnt; i++) {
 		range1 = rand_range(init_t);
@@ -1980,14 +1988,16 @@  static void validate_rand_ranges(enum num_t init_t, enum num_t cond_t, bool cons
 		}
 
 		/* <range1> x <range2> */
-		if (verify_case(&ctx, init_t, cond_t, range1, range2))
+		if (verify_case_opt(&ctx, init_t, cond_t, range1, range2, false /* !is_subtest */))
 			goto cleanup;
 		/* <range2> x <range1> */
-		if (verify_case(&ctx, init_t, cond_t, range2, range1))
+		if (verify_case_opt(&ctx, init_t, cond_t, range2, range1, false /* !is_subtest */))
 			goto cleanup;
 	}
 
 cleanup:
+	/* make sure we report random seed for reproducing */
+	ASSERT_TRUE(true, ctx.progress_ctx);
 	cleanup_ctx(&ctx);
 }