| Message ID | 20211025223345.2136168-3-fallentree@fb.com (mailing list archive) |
|---|---|
| State | Changes Requested |
| Delegated to: | BPF |
| Headers | show |
| Series | selftests/bpf: parallel mode improvement | expand |
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 >
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 > >
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 > > >
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