[PATCH bpf-next 0/4] selftests/bpf: parallel mode improvement

[PATCH bpf-next 0/4] selftests/bpf: parallel mode improvement

[Yucong Sun]

Several patches to improve parallel execution mode, including printing
subtest status line, updating vmtest.sh and fixed two previously dropped
patch according to feedback.


Yucong Sun (4):
  selfetests/bpf: Update vmtest.sh defaults
  selftests/bpf: print subtest status line
  selftests/bpf: fix attach_probe in parallel mode
  selftests/bpf: adding a namespace reset for tc_redirect

 .../selftests/bpf/prog_tests/attach_probe.c   |  9 ++-
 .../selftests/bpf/prog_tests/tc_redirect.c    | 14 +++++
 tools/testing/selftests/bpf/test_progs.c      | 56 +++++++++++++++----
 tools/testing/selftests/bpf/test_progs.h      |  4 ++
 tools/testing/selftests/bpf/vmtest.sh         |  6 +-
 5 files changed, 74 insertions(+), 15 deletions(-)

-- 
2.30.2

[PATCH bpf-next 1/4] selfetests/bpf: Update vmtest.sh defaults

[Yucong Sun]

From: Yucong Sun <sunyucong@gmail.com>

Increase memory to 4G, 8 SMP core with host cpu passthrough. This
make it run faster in parallel mode and more likely to succeed.

Signed-off-by: Yucong Sun <sunyucong@gmail.com>
---
 tools/testing/selftests/bpf/vmtest.sh | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/tools/testing/selftests/bpf/vmtest.sh b/tools/testing/selftests/bpf/vmtest.sh
index 8889b3f55236..027198768fad 100755
--- a/tools/testing/selftests/bpf/vmtest.sh
+++ b/tools/testing/selftests/bpf/vmtest.sh
@@ -224,10 +224,10 @@ EOF
 		-nodefaults \
 		-display none \
 		-serial mon:stdio \
-		-cpu kvm64 \
+		-cpu host \
 		-enable-kvm \
-		-smp 4 \
-		-m 2G \
+		-smp 8 \
+		-m 4G \
 		-drive file="${rootfs_img}",format=raw,index=1,media=disk,if=virtio,cache=none \
 		-kernel "${kernel_bzimage}" \
 		-append "root=/dev/vda rw console=ttyS0,115200"
-- 
2.30.2

[PATCH bpf-next 2/4] selftests/bpf: print subtest status line

[Yucong Sun]

From: Yucong Sun <sunyucong@gmail.com>

This patch restores behavior that prints one status line for each
subtest executed. It works in both serial mode and parallel mode,  and
all verbosity settings.

The logic around IO hijacking could use some more simplification in the
future.

Signed-off-by: Yucong Sun <sunyucong@gmail.com>
---
 tools/testing/selftests/bpf/test_progs.c | 56 +++++++++++++++++++-----
 tools/testing/selftests/bpf/test_progs.h |  4 ++
 2 files changed, 50 insertions(+), 10 deletions(-)

diff --git a/tools/testing/selftests/bpf/test_progs.c b/tools/testing/selftests/bpf/test_progs.c
index 1f4a48566991..ff4598126f9d 100644
--- a/tools/testing/selftests/bpf/test_progs.c
+++ b/tools/testing/selftests/bpf/test_progs.c
@@ -100,6 +100,18 @@ static bool should_run(struct test_selector *sel, int num, const char *name)
 	return num < sel->num_set_len && sel->num_set[num];
 }
 
+static void dump_subtest_status(bool display) {
+	fflush(env.subtest_status_fd);
+	if (display) {
+		if (env.subtest_status_cnt) {
+			env.subtest_status_buf[env.subtest_status_cnt] = '\0';
+			fputs(env.subtest_status_buf, stdout);
+		}
+	}
+	rewind(env.subtest_status_fd);
+	fflush(env.subtest_status_fd);
+}
+
 static void dump_test_log(const struct prog_test_def *test, bool failed)
 {
 	if (stdout == env.stdout)
@@ -112,12 +124,17 @@ static void dump_test_log(const struct prog_test_def *test, bool failed)
 	fflush(stdout); /* exports env.log_buf & env.log_cnt */
 
 	if (env.verbosity > VERBOSE_NONE || test->force_log || failed) {
-		if (env.log_cnt) {
-			env.log_buf[env.log_cnt] = '\0';
-			fprintf(env.stdout, "%s", env.log_buf);
-			if (env.log_buf[env.log_cnt - 1] != '\n')
-				fprintf(env.stdout, "\n");
-		}
+		dump_subtest_status(false);
+	} else {
+		rewind(stdout);
+		dump_subtest_status(true);
+		fflush(stdout);
+	}
+	if (env.log_cnt) {
+		env.log_buf[env.log_cnt] = '\0';
+		fprintf(env.stdout, "%s", env.log_buf);
+		if (env.log_buf[env.log_cnt - 1] != '\n')
+			fprintf(env.stdout, "\n");
 	}
 }
 
@@ -183,7 +200,12 @@ void test__end_subtest(void)
 
 	dump_test_log(test, sub_error_cnt);
 
+	// Print two copies here, one as part of full logs, another one will
+	// only be used if there is no need to show full logs.
 	fprintf(stdout, "#%d/%d %s/%s:%s\n",
+		test->test_num, test->subtest_num, test->test_name, test->subtest_name,
+		sub_error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
+	fprintf(env.subtest_status_fd, "#%d/%d %s/%s:%s\n",
 	       test->test_num, test->subtest_num, test->test_name, test->subtest_name,
 	       sub_error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
 
@@ -1250,6 +1272,15 @@ static int worker_main(int sock)
 
 			run_one_test(test_to_run);
 
+			// discard logs if we don't need them
+			if (env.verbosity > VERBOSE_NONE || test->force_log || test->error_cnt) {
+				dump_subtest_status(false);
+			} else {
+				rewind(stdout);
+				dump_subtest_status(true);
+				fflush(stdout);
+			}
+
 			stdio_restore();
 
 			memset(&msg_done, 0, sizeof(msg_done));
@@ -1260,10 +1291,9 @@ static int worker_main(int sock)
 			msg_done.test_done.sub_succ_cnt = test->sub_succ_cnt;
 			msg_done.test_done.have_log = false;
 
-			if (env.verbosity > VERBOSE_NONE || test->force_log || test->error_cnt) {
-				if (env.log_cnt)
-					msg_done.test_done.have_log = true;
-			}
+			if (env.log_cnt)
+				msg_done.test_done.have_log = true;
+
 			if (send_message(sock, &msg_done) < 0) {
 				perror("Fail to send message done");
 				goto out;
@@ -1357,6 +1387,12 @@ int main(int argc, char **argv)
 
 	env.stdout = stdout;
 	env.stderr = stderr;
+	env.subtest_status_fd = open_memstream(
+		&env.subtest_status_buf, &env.subtest_status_cnt);
+	if (!env.subtest_status_fd) {
+		perror("Failed to setup env.subtest_status_fd");
+		exit(EXIT_ERR_SETUP_INFRA);
+	}
 
 	env.has_testmod = true;
 	if (!env.list_test_names && load_bpf_testmod()) {
diff --git a/tools/testing/selftests/bpf/test_progs.h b/tools/testing/selftests/bpf/test_progs.h
index 93c1ff705533..a564215a63b1 100644
--- a/tools/testing/selftests/bpf/test_progs.h
+++ b/tools/testing/selftests/bpf/test_progs.h
@@ -89,6 +89,10 @@ struct test_env {
 	pid_t *worker_pids; /* array of worker pids */
 	int *worker_socks; /* array of worker socks */
 	int *worker_current_test; /* array of current running test for each worker */
+
+	FILE* subtest_status_fd; /* fd for printing status line for subtests */
+	char *subtest_status_buf; /* buffer for subtests status */
+	size_t subtest_status_cnt;
 };
 
 #define MAX_LOG_TRUNK_SIZE 8192
-- 
2.30.2

[PATCH bpf-next 3/4] selftests/bpf: fix attach_probe in parallel mode

[Yucong Sun]

From: Yucong Sun <sunyucong@gmail.com>

This patch makes attach_probe uses its own method as attach point,
avoiding conflict with other tests like bpf_cookie.

Signed-off-by: Yucong Sun <sunyucong@gmail.com>
---
 tools/testing/selftests/bpf/prog_tests/attach_probe.c | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/tools/testing/selftests/bpf/prog_tests/attach_probe.c b/tools/testing/selftests/bpf/prog_tests/attach_probe.c
index 6c511dcd1465..d0bd51eb23c8 100644
--- a/tools/testing/selftests/bpf/prog_tests/attach_probe.c
+++ b/tools/testing/selftests/bpf/prog_tests/attach_probe.c
@@ -5,6 +5,11 @@
 /* this is how USDT semaphore is actually defined, except volatile modifier */
 volatile unsigned short uprobe_ref_ctr __attribute__((unused)) __attribute((section(".probes")));
 
+/* attach point */
+static void method(void) {
+	return ;
+}
+
 void test_attach_probe(void)
 {
 	DECLARE_LIBBPF_OPTS(bpf_uprobe_opts, uprobe_opts);
@@ -33,7 +38,7 @@ void test_attach_probe(void)
 	if (CHECK(base_addr < 0, "get_base_addr",
 		  "failed to find base addr: %zd", base_addr))
 		return;
-	uprobe_offset = get_uprobe_offset(&get_base_addr, base_addr);
+	uprobe_offset = get_uprobe_offset(&method, base_addr);
 
 	ref_ctr_offset = get_rel_offset((uintptr_t)&uprobe_ref_ctr);
 	if (!ASSERT_GE(ref_ctr_offset, 0, "ref_ctr_offset"))
@@ -98,7 +103,7 @@ void test_attach_probe(void)
 		goto cleanup;
 
 	/* trigger & validate uprobe & uretprobe */
-	get_base_addr();
+	method();
 
 	if (CHECK(skel->bss->uprobe_res != 3, "check_uprobe_res",
 		  "wrong uprobe res: %d\n", skel->bss->uprobe_res))
-- 
2.30.2

[PATCH bpf-next 4/4] selftests/bpf: adding a namespace reset for tc_redirect

[Yucong Sun]

From: Yucong Sun <sunyucong@gmail.com>

This patch delete ns_src/ns_dst/ns_redir namespaces before recreating
them, making the test more robust.

Signed-off-by: Yucong Sun <sunyucong@gmail.com>
---
 .../testing/selftests/bpf/prog_tests/tc_redirect.c | 14 ++++++++++++++
 1 file changed, 14 insertions(+)

diff --git a/tools/testing/selftests/bpf/prog_tests/tc_redirect.c b/tools/testing/selftests/bpf/prog_tests/tc_redirect.c
index 53672634bc52..4b18b73df10b 100644
--- a/tools/testing/selftests/bpf/prog_tests/tc_redirect.c
+++ b/tools/testing/selftests/bpf/prog_tests/tc_redirect.c
@@ -176,6 +176,18 @@ static int netns_setup_namespaces(const char *verb)
 	return 0;
 }
 
+static void netns_setup_namespaces_nofail(const char *verb)
+{
+	const char * const *ns = namespaces;
+	char cmd[128];
+
+	while (*ns) {
+		snprintf(cmd, sizeof(cmd), "ip netns %s %s > /dev/null 2>&1", verb, *ns);
+		system(cmd);
+		ns++;
+	}
+}
+
 struct netns_setup_result {
 	int ifindex_veth_src_fwd;
 	int ifindex_veth_dst_fwd;
@@ -762,6 +774,8 @@ static void test_tc_redirect_peer_l3(struct netns_setup_result *setup_result)
 
 static void *test_tc_redirect_run_tests(void *arg)
 {
+	netns_setup_namespaces_nofail("delete");
+
 	RUN_TEST(tc_redirect_peer);
 	RUN_TEST(tc_redirect_peer_l3);
 	RUN_TEST(tc_redirect_neigh);
-- 
2.30.2

Re: [PATCH bpf-next 2/4] selftests/bpf: print subtest status line

[Andrii Nakryiko]

On Mon, Oct 25, 2021 at 3:33 PM Yucong Sun <fallentree@fb.com> wrote:
>
> From: Yucong Sun <sunyucong@gmail.com>
>
> This patch restores behavior that prints one status line for each
> subtest executed. It works in both serial mode and parallel mode,  and
> all verbosity settings.
>
> The logic around IO hijacking could use some more simplification in the
> future.
>

This feels like a big hack, not a proper solution. What if we extend
MSG_TEST_DONE to signal also sub-test completion (along with subtest
logs)? Would that work better and result in cleaner logic?

> Signed-off-by: Yucong Sun <sunyucong@gmail.com>
> ---
>  tools/testing/selftests/bpf/test_progs.c | 56 +++++++++++++++++++-----
>  tools/testing/selftests/bpf/test_progs.h |  4 ++
>  2 files changed, 50 insertions(+), 10 deletions(-)
>
> diff --git a/tools/testing/selftests/bpf/test_progs.c b/tools/testing/selftests/bpf/test_progs.c
> index 1f4a48566991..ff4598126f9d 100644
> --- a/tools/testing/selftests/bpf/test_progs.c
> +++ b/tools/testing/selftests/bpf/test_progs.c
> @@ -100,6 +100,18 @@ static bool should_run(struct test_selector *sel, int num, const char *name)
>         return num < sel->num_set_len && sel->num_set[num];
>  }
>
> +static void dump_subtest_status(bool display) {

please run checkpatch.pl

> +       fflush(env.subtest_status_fd);
> +       if (display) {
> +               if (env.subtest_status_cnt) {
> +                       env.subtest_status_buf[env.subtest_status_cnt] = '\0';
> +                       fputs(env.subtest_status_buf, stdout);
> +               }
> +       }
> +       rewind(env.subtest_status_fd);
> +       fflush(env.subtest_status_fd);
> +}
> +
>  static void dump_test_log(const struct prog_test_def *test, bool failed)
>  {
>         if (stdout == env.stdout)
> @@ -112,12 +124,17 @@ static void dump_test_log(const struct prog_test_def *test, bool failed)
>         fflush(stdout); /* exports env.log_buf & env.log_cnt */
>
>         if (env.verbosity > VERBOSE_NONE || test->force_log || failed) {
> -               if (env.log_cnt) {
> -                       env.log_buf[env.log_cnt] = '\0';
> -                       fprintf(env.stdout, "%s", env.log_buf);
> -                       if (env.log_buf[env.log_cnt - 1] != '\n')
> -                               fprintf(env.stdout, "\n");
> -               }
> +               dump_subtest_status(false);
> +       } else {
> +               rewind(stdout);
> +               dump_subtest_status(true);
> +               fflush(stdout);
> +       }
> +       if (env.log_cnt) {
> +               env.log_buf[env.log_cnt] = '\0';
> +               fprintf(env.stdout, "%s", env.log_buf);
> +               if (env.log_buf[env.log_cnt - 1] != '\n')
> +                       fprintf(env.stdout, "\n");
>         }
>  }
>
> @@ -183,7 +200,12 @@ void test__end_subtest(void)
>
>         dump_test_log(test, sub_error_cnt);
>
> +       // Print two copies here, one as part of full logs, another one will
> +       // only be used if there is no need to show full logs.

C++ style comments

>         fprintf(stdout, "#%d/%d %s/%s:%s\n",
> +               test->test_num, test->subtest_num, test->test_name, test->subtest_name,
> +               sub_error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
> +       fprintf(env.subtest_status_fd, "#%d/%d %s/%s:%s\n",
>                test->test_num, test->subtest_num, test->test_name, test->subtest_name,
>                sub_error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
>
> @@ -1250,6 +1272,15 @@ static int worker_main(int sock)
>
>                         run_one_test(test_to_run);
>
> +                       // discard logs if we don't need them

C++ style comment

> +                       if (env.verbosity > VERBOSE_NONE || test->force_log || test->error_cnt) {
> +                               dump_subtest_status(false);
> +                       } else {
> +                               rewind(stdout);
> +                               dump_subtest_status(true);
> +                               fflush(stdout);
> +                       }
> +
>                         stdio_restore();
>
>                         memset(&msg_done, 0, sizeof(msg_done));
> @@ -1260,10 +1291,9 @@ static int worker_main(int sock)
>                         msg_done.test_done.sub_succ_cnt = test->sub_succ_cnt;
>                         msg_done.test_done.have_log = false;
>
> -                       if (env.verbosity > VERBOSE_NONE || test->force_log || test->error_cnt) {
> -                               if (env.log_cnt)
> -                                       msg_done.test_done.have_log = true;
> -                       }
> +                       if (env.log_cnt)
> +                               msg_done.test_done.have_log = true;
> +
>                         if (send_message(sock, &msg_done) < 0) {
>                                 perror("Fail to send message done");
>                                 goto out;
> @@ -1357,6 +1387,12 @@ int main(int argc, char **argv)
>
>         env.stdout = stdout;
>         env.stderr = stderr;
> +       env.subtest_status_fd = open_memstream(

extremely misleading name, it's not an FD at all

> +               &env.subtest_status_buf, &env.subtest_status_cnt);
> +       if (!env.subtest_status_fd) {
> +               perror("Failed to setup env.subtest_status_fd");
> +               exit(EXIT_ERR_SETUP_INFRA);
> +       }
>
>         env.has_testmod = true;
>         if (!env.list_test_names && load_bpf_testmod()) {
> diff --git a/tools/testing/selftests/bpf/test_progs.h b/tools/testing/selftests/bpf/test_progs.h
> index 93c1ff705533..a564215a63b1 100644
> --- a/tools/testing/selftests/bpf/test_progs.h
> +++ b/tools/testing/selftests/bpf/test_progs.h
> @@ -89,6 +89,10 @@ struct test_env {
>         pid_t *worker_pids; /* array of worker pids */
>         int *worker_socks; /* array of worker socks */
>         int *worker_current_test; /* array of current running test for each worker */
> +
> +       FILE* subtest_status_fd; /* fd for printing status line for subtests */
> +       char *subtest_status_buf; /* buffer for subtests status */
> +       size_t subtest_status_cnt;
>  };
>
>  #define MAX_LOG_TRUNK_SIZE 8192
> --
> 2.30.2
>

Re: [PATCH bpf-next 3/4] selftests/bpf: fix attach_probe in parallel mode

[Andrii Nakryiko]

On Mon, Oct 25, 2021 at 3:33 PM Yucong Sun <fallentree@fb.com> wrote:
>
> From: Yucong Sun <sunyucong@gmail.com>
>
> This patch makes attach_probe uses its own method as attach point,
> avoiding conflict with other tests like bpf_cookie.
>
> Signed-off-by: Yucong Sun <sunyucong@gmail.com>
> ---
>  tools/testing/selftests/bpf/prog_tests/attach_probe.c | 9 +++++++--
>  1 file changed, 7 insertions(+), 2 deletions(-)
>
> diff --git a/tools/testing/selftests/bpf/prog_tests/attach_probe.c b/tools/testing/selftests/bpf/prog_tests/attach_probe.c
> index 6c511dcd1465..d0bd51eb23c8 100644
> --- a/tools/testing/selftests/bpf/prog_tests/attach_probe.c
> +++ b/tools/testing/selftests/bpf/prog_tests/attach_probe.c
> @@ -5,6 +5,11 @@
>  /* this is how USDT semaphore is actually defined, except volatile modifier */
>  volatile unsigned short uprobe_ref_ctr __attribute__((unused)) __attribute((section(".probes")));
>
> +/* attach point */
> +static void method(void) {

{ on separate line


let's also mark it as noinline just in case


> +       return ;

unnecessary return (also extra space before semicolon)

> +}
> +
>  void test_attach_probe(void)
>  {
>         DECLARE_LIBBPF_OPTS(bpf_uprobe_opts, uprobe_opts);
> @@ -33,7 +38,7 @@ void test_attach_probe(void)
>         if (CHECK(base_addr < 0, "get_base_addr",
>                   "failed to find base addr: %zd", base_addr))
>                 return;
> -       uprobe_offset = get_uprobe_offset(&get_base_addr, base_addr);
> +       uprobe_offset = get_uprobe_offset(&method, base_addr);
>
>         ref_ctr_offset = get_rel_offset((uintptr_t)&uprobe_ref_ctr);
>         if (!ASSERT_GE(ref_ctr_offset, 0, "ref_ctr_offset"))
> @@ -98,7 +103,7 @@ void test_attach_probe(void)
>                 goto cleanup;
>
>         /* trigger & validate uprobe & uretprobe */
> -       get_base_addr();
> +       method();
>
>         if (CHECK(skel->bss->uprobe_res != 3, "check_uprobe_res",
>                   "wrong uprobe res: %d\n", skel->bss->uprobe_res))
> --
> 2.30.2
>

Re: [PATCH bpf-next 2/4] selftests/bpf: print subtest status line

[sunyucong]

On Mon, Oct 25, 2021 at 9:09 PM Andrii Nakryiko
<andrii.nakryiko@gmail.com> wrote:
>
> On Mon, Oct 25, 2021 at 3:33 PM Yucong Sun <fallentree@fb.com> wrote:
> >
> > From: Yucong Sun <sunyucong@gmail.com>
> >
> > This patch restores behavior that prints one status line for each
> > subtest executed. It works in both serial mode and parallel mode,  and
> > all verbosity settings.
> >
> > The logic around IO hijacking could use some more simplification in the
> > future.
> >
>
> This feels like a big hack, not a proper solution. What if we extend
> MSG_TEST_DONE to signal also sub-test completion (along with subtest
> logs)? Would that work better and result in cleaner logic?

I think the current solution is actually cleaner.  Yes we could add
fields in task struct to record each subtest's name and status and
generate the status line separately, but it will only work in
situations where all tests pass.
When there is an error, we do want to mix the status line with the
actual stdout logs, which we won't be able to do afterwards.

Besides, we will still need to implement separate logic in 3 places
(serial mode,  parallel mode in worker process, and serial part of
parallel mode execution). Having two copies of stdout logs is actually
not that bad.

>
> > Signed-off-by: Yucong Sun <sunyucong@gmail.com>
> > ---
> >  tools/testing/selftests/bpf/test_progs.c | 56 +++++++++++++++++++-----
> >  tools/testing/selftests/bpf/test_progs.h |  4 ++
> >  2 files changed, 50 insertions(+), 10 deletions(-)
> >
> > diff --git a/tools/testing/selftests/bpf/test_progs.c b/tools/testing/selftests/bpf/test_progs.c
> > index 1f4a48566991..ff4598126f9d 100644
> > --- a/tools/testing/selftests/bpf/test_progs.c
> > +++ b/tools/testing/selftests/bpf/test_progs.c
> > @@ -100,6 +100,18 @@ static bool should_run(struct test_selector *sel, int num, const char *name)
> >         return num < sel->num_set_len && sel->num_set[num];
> >  }
> >
> > +static void dump_subtest_status(bool display) {
>
> please run checkpatch.pl
>
> > +       fflush(env.subtest_status_fd);
> > +       if (display) {
> > +               if (env.subtest_status_cnt) {
> > +                       env.subtest_status_buf[env.subtest_status_cnt] = '\0';
> > +                       fputs(env.subtest_status_buf, stdout);
> > +               }
> > +       }
> > +       rewind(env.subtest_status_fd);
> > +       fflush(env.subtest_status_fd);
> > +}
> > +
> >  static void dump_test_log(const struct prog_test_def *test, bool failed)
> >  {
> >         if (stdout == env.stdout)
> > @@ -112,12 +124,17 @@ static void dump_test_log(const struct prog_test_def *test, bool failed)
> >         fflush(stdout); /* exports env.log_buf & env.log_cnt */
> >
> >         if (env.verbosity > VERBOSE_NONE || test->force_log || failed) {
> > -               if (env.log_cnt) {
> > -                       env.log_buf[env.log_cnt] = '\0';
> > -                       fprintf(env.stdout, "%s", env.log_buf);
> > -                       if (env.log_buf[env.log_cnt - 1] != '\n')
> > -                               fprintf(env.stdout, "\n");
> > -               }
> > +               dump_subtest_status(false);
> > +       } else {
> > +               rewind(stdout);
> > +               dump_subtest_status(true);
> > +               fflush(stdout);
> > +       }
> > +       if (env.log_cnt) {
> > +               env.log_buf[env.log_cnt] = '\0';
> > +               fprintf(env.stdout, "%s", env.log_buf);
> > +               if (env.log_buf[env.log_cnt - 1] != '\n')
> > +                       fprintf(env.stdout, "\n");
> >         }
> >  }
> >
> > @@ -183,7 +200,12 @@ void test__end_subtest(void)
> >
> >         dump_test_log(test, sub_error_cnt);
> >
> > +       // Print two copies here, one as part of full logs, another one will
> > +       // only be used if there is no need to show full logs.
>
> C++ style comments
>
> >         fprintf(stdout, "#%d/%d %s/%s:%s\n",
> > +               test->test_num, test->subtest_num, test->test_name, test->subtest_name,
> > +               sub_error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
> > +       fprintf(env.subtest_status_fd, "#%d/%d %s/%s:%s\n",
> >                test->test_num, test->subtest_num, test->test_name, test->subtest_name,
> >                sub_error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
> >
> > @@ -1250,6 +1272,15 @@ static int worker_main(int sock)
> >
> >                         run_one_test(test_to_run);
> >
> > +                       // discard logs if we don't need them
>
> C++ style comment
>
> > +                       if (env.verbosity > VERBOSE_NONE || test->force_log || test->error_cnt) {
> > +                               dump_subtest_status(false);
> > +                       } else {
> > +                               rewind(stdout);
> > +                               dump_subtest_status(true);
> > +                               fflush(stdout);
> > +                       }
> > +
> >                         stdio_restore();
> >
> >                         memset(&msg_done, 0, sizeof(msg_done));
> > @@ -1260,10 +1291,9 @@ static int worker_main(int sock)
> >                         msg_done.test_done.sub_succ_cnt = test->sub_succ_cnt;
> >                         msg_done.test_done.have_log = false;
> >
> > -                       if (env.verbosity > VERBOSE_NONE || test->force_log || test->error_cnt) {
> > -                               if (env.log_cnt)
> > -                                       msg_done.test_done.have_log = true;
> > -                       }
> > +                       if (env.log_cnt)
> > +                               msg_done.test_done.have_log = true;
> > +
> >                         if (send_message(sock, &msg_done) < 0) {
> >                                 perror("Fail to send message done");
> >                                 goto out;
> > @@ -1357,6 +1387,12 @@ int main(int argc, char **argv)
> >
> >         env.stdout = stdout;
> >         env.stderr = stderr;
> > +       env.subtest_status_fd = open_memstream(
>
> extremely misleading name, it's not an FD at all

it is indeed a file descriptor, isn't it? What's a better name for it?

>
> > +               &env.subtest_status_buf, &env.subtest_status_cnt);
> > +       if (!env.subtest_status_fd) {
> > +               perror("Failed to setup env.subtest_status_fd");
> > +               exit(EXIT_ERR_SETUP_INFRA);
> > +       }
> >
> >         env.has_testmod = true;
> >         if (!env.list_test_names && load_bpf_testmod()) {
> > diff --git a/tools/testing/selftests/bpf/test_progs.h b/tools/testing/selftests/bpf/test_progs.h
> > index 93c1ff705533..a564215a63b1 100644
> > --- a/tools/testing/selftests/bpf/test_progs.h
> > +++ b/tools/testing/selftests/bpf/test_progs.h
> > @@ -89,6 +89,10 @@ struct test_env {
> >         pid_t *worker_pids; /* array of worker pids */
> >         int *worker_socks; /* array of worker socks */
> >         int *worker_current_test; /* array of current running test for each worker */
> > +
> > +       FILE* subtest_status_fd; /* fd for printing status line for subtests */
> > +       char *subtest_status_buf; /* buffer for subtests status */
> > +       size_t subtest_status_cnt;
> >  };
> >
> >  #define MAX_LOG_TRUNK_SIZE 8192
> > --
> > 2.30.2
> >

Re: [PATCH bpf-next 2/4] selftests/bpf: print subtest status line

[Andrii Nakryiko]

On Tue, Oct 26, 2021 at 10:24 AM sunyucong@gmail.com
<sunyucong@gmail.com> wrote:
>
> On Mon, Oct 25, 2021 at 9:09 PM Andrii Nakryiko
> <andrii.nakryiko@gmail.com> wrote:
> >
> > On Mon, Oct 25, 2021 at 3:33 PM Yucong Sun <fallentree@fb.com> wrote:
> > >
> > > From: Yucong Sun <sunyucong@gmail.com>
> > >
> > > This patch restores behavior that prints one status line for each
> > > subtest executed. It works in both serial mode and parallel mode,  and
> > > all verbosity settings.
> > >
> > > The logic around IO hijacking could use some more simplification in the
> > > future.
> > >
> >
> > This feels like a big hack, not a proper solution. What if we extend
> > MSG_TEST_DONE to signal also sub-test completion (along with subtest
> > logs)? Would that work better and result in cleaner logic?
>
> I think the current solution is actually cleaner.  Yes we could add

I disagree. Subtest is a first-class citizen, even if it's harder to
parallelize due to more dynamic nature. Having protocol that reflects
the fact that test can consist of subtests is the right way to go, I
think.

> fields in task struct to record each subtest's name and status and
> generate the status line separately, but it will only work in
> situations where all tests pass.
> When there is an error, we do want to mix the status line with the
> actual stdout logs, which we won't be able to do afterwards.

I don't understand why success of failure is different. Worker
shouldn't log status line into the logs and should send subtest logs
separately from subtest name and status. And then dispatcher thread
will print log (depending on success/failure and/or verbosity
settings) and pre-defined status line. Status line is a fixed-format
thing that's derived from subtest name and its success/failure result.
It's not part of "log" per se.

>
> Besides, we will still need to implement separate logic in 3 places
> (serial mode,  parallel mode in worker process, and serial part of
> parallel mode execution). Having two copies of stdout logs is actually
> not that bad.

Which is exactly why I was asking to reuse sequential loop, so that we
only have 2 loops. You felt it's not big deal. Maybe now is time to
rethink this?

Two copies of logs is certainly a design smell, so please give it some
thought and try to fix the protocol to accommodate subtests as a
concept.

>
> >
> > > Signed-off-by: Yucong Sun <sunyucong@gmail.com>
> > > ---
> > >  tools/testing/selftests/bpf/test_progs.c | 56 +++++++++++++++++++-----
> > >  tools/testing/selftests/bpf/test_progs.h |  4 ++
> > >  2 files changed, 50 insertions(+), 10 deletions(-)
> > >

[...]

> > > @@ -1357,6 +1387,12 @@ int main(int argc, char **argv)
> > >
> > >         env.stdout = stdout;
> > >         env.stderr = stderr;
> > > +       env.subtest_status_fd = open_memstream(
> >
> > extremely misleading name, it's not an FD at all
>
> it is indeed a file descriptor, isn't it? What's a better name for it?

FD is an integer. This one is FILE *, so it may be "file", but
certainly not an fd.

>
> >
> > > +               &env.subtest_status_buf, &env.subtest_status_cnt);
> > > +       if (!env.subtest_status_fd) {
> > > +               perror("Failed to setup env.subtest_status_fd");
> > > +               exit(EXIT_ERR_SETUP_INFRA);
> > > +       }
> > >
> > >         env.has_testmod = true;
> > >         if (!env.list_test_names && load_bpf_testmod()) {
> > > diff --git a/tools/testing/selftests/bpf/test_progs.h b/tools/testing/selftests/bpf/test_progs.h
> > > index 93c1ff705533..a564215a63b1 100644
> > > --- a/tools/testing/selftests/bpf/test_progs.h
> > > +++ b/tools/testing/selftests/bpf/test_progs.h
> > > @@ -89,6 +89,10 @@ struct test_env {
> > >         pid_t *worker_pids; /* array of worker pids */
> > >         int *worker_socks; /* array of worker socks */
> > >         int *worker_current_test; /* array of current running test for each worker */
> > > +
> > > +       FILE* subtest_status_fd; /* fd for printing status line for subtests */
> > > +       char *subtest_status_buf; /* buffer for subtests status */
> > > +       size_t subtest_status_cnt;
> > >  };
> > >
> > >  #define MAX_LOG_TRUNK_SIZE 8192
> > > --
> > > 2.30.2
> > >

Re: [PATCH bpf-next 0/4] selftests/bpf: parallel mode improvement

[Andrii Nakryiko]

On Mon, Oct 25, 2021 at 3:33 PM Yucong Sun <fallentree@fb.com> wrote:
>
> Several patches to improve parallel execution mode, including printing
> subtest status line, updating vmtest.sh and fixed two previously dropped
> patch according to feedback.
>

I've dropped the second patch and applied all the rest. I can run
`sudo ./test_progs -j` pretty reliably with no failures now and get
30-35 second saving on average. Thanks.

Let's keep discussing the subtest support separately.

>
> Yucong Sun (4):
>   selfetests/bpf: Update vmtest.sh defaults
>   selftests/bpf: print subtest status line
>   selftests/bpf: fix attach_probe in parallel mode
>   selftests/bpf: adding a namespace reset for tc_redirect
>
>  .../selftests/bpf/prog_tests/attach_probe.c   |  9 ++-
>  .../selftests/bpf/prog_tests/tc_redirect.c    | 14 +++++
>  tools/testing/selftests/bpf/test_progs.c      | 56 +++++++++++++++----
>  tools/testing/selftests/bpf/test_progs.h      |  4 ++
>  tools/testing/selftests/bpf/vmtest.sh         |  6 +-
>  5 files changed, 74 insertions(+), 15 deletions(-)
>
> --
> 2.30.2
>