All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH bpf-next] selftests/bpf: consolidate common code in run_one_test function
@ 2022-04-14  5:05 Mykola Lysenko
  2022-04-14 22:49 ` Andrii Nakryiko
  0 siblings, 1 reply; 3+ messages in thread
From: Mykola Lysenko @ 2022-04-14  5:05 UTC (permalink / raw)
  To: bpf, ast, andrii, daniel; +Cc: kernel-team, Mykola Lysenko

This is a pre-req to add separate logging for each subtest.

Move all the mutable test data to the test_result struct.
Move per-test init/de-init into the run_one_test function.
Consolidate data aggregation and final log output in
calculate_and_print_summary function.
As a side effect, this patch fixes double counting of errors
for subtests and possible duplicate output of subtest log
on failures.

Also, add prog_tests_framework.c test to verify some of the
counting logic.

As part of verification, confirmed that number of reported
tests is the same before and after the change for both parallel
and sequential test execution.

Signed-off-by: Mykola Lysenko <mykolal@fb.com>
---
 .../bpf/prog_tests/prog_tests_framework.c     |  55 ++++
 tools/testing/selftests/bpf/test_progs.c      | 301 +++++++-----------
 tools/testing/selftests/bpf/test_progs.h      |  32 +-
 3 files changed, 195 insertions(+), 193 deletions(-)
 create mode 100644 tools/testing/selftests/bpf/prog_tests/prog_tests_framework.c

diff --git a/tools/testing/selftests/bpf/prog_tests/prog_tests_framework.c b/tools/testing/selftests/bpf/prog_tests/prog_tests_framework.c
new file mode 100644
index 000000000000..7a5be06653f7
--- /dev/null
+++ b/tools/testing/selftests/bpf/prog_tests/prog_tests_framework.c
@@ -0,0 +1,55 @@
+// SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause)
+
+#include "test_progs.h"
+#include "testing_helpers.h"
+
+static void clear_test_result(struct test_result *result)
+{
+	result->error_cnt = 0;
+	result->sub_succ_cnt = 0;
+	result->skip_cnt = 0;
+}
+
+void test_prog_tests_framework(void)
+{
+	struct test_result *result = env.test_result;
+
+	// in all the ASSERT calls below we need to return on the first
+	// error due to the fact that we are cleaning the test state after
+	// each dummy subtest
+
+	// test we properly count skipped tests with subtests
+	if (test__start_subtest("test_good_subtest"))
+		test__end_subtest();
+	if (!ASSERT_EQ(result->skip_cnt, 0, "skip_cnt_check"))
+		return;
+	if (!ASSERT_EQ(result->error_cnt, 0, "error_cnt_check"))
+		return;
+	if (!ASSERT_EQ(result->subtest_num, 1, "subtest_num_check"))
+		return;
+	clear_test_result(result);
+
+	if (test__start_subtest("test_skip_subtest")) {
+		test__skip();
+		test__end_subtest();
+	}
+	if (test__start_subtest("test_skip_subtest")) {
+		test__skip();
+		test__end_subtest();
+	}
+	if (!ASSERT_EQ(result->skip_cnt, 2, "skip_cnt_check"))
+		return;
+	if (!ASSERT_EQ(result->subtest_num, 3, "subtest_num_check"))
+		return;
+	clear_test_result(result);
+
+	if (test__start_subtest("test_fail_subtest")) {
+		test__fail();
+		test__end_subtest();
+	}
+	if (!ASSERT_EQ(result->error_cnt, 1, "error_cnt_check"))
+		return;
+	if (!ASSERT_EQ(result->subtest_num, 4, "subtest_num_check"))
+		return;
+	clear_test_result(result);
+}
diff --git a/tools/testing/selftests/bpf/test_progs.c b/tools/testing/selftests/bpf/test_progs.c
index dcad9871f556..b3881d4fd99d 100644
--- a/tools/testing/selftests/bpf/test_progs.c
+++ b/tools/testing/selftests/bpf/test_progs.c
@@ -52,18 +52,8 @@ struct prog_test_def {
 	void (*run_test)(void);
 	void (*run_serial_test)(void);
 	bool force_log;
-	int error_cnt;
-	int skip_cnt;
-	int sub_succ_cnt;
 	bool should_run;
-	bool tested;
 	bool need_cgroup_cleanup;
-
-	char *subtest_name;
-	int subtest_num;
-
-	/* store counts before subtest started */
-	int old_error_cnt;
 };
 
 /* Override C runtime library's usleep() implementation to ensure nanosleep()
@@ -162,14 +152,6 @@ static void dump_test_log(const struct prog_test_def *test, bool failed)
 	}
 }
 
-static void skip_account(void)
-{
-	if (env.test->skip_cnt) {
-		env.skip_cnt++;
-		env.test->skip_cnt = 0;
-	}
-}
-
 static void stdio_restore(void);
 
 /* A bunch of tests set custom affinity per-thread and/or per-process. Reset
@@ -219,55 +201,59 @@ static void restore_netns(void)
 void test__end_subtest(void)
 {
 	struct prog_test_def *test = env.test;
-	int sub_error_cnt = test->error_cnt - test->old_error_cnt;
+	struct test_result *result = env.test_result;
 
-	dump_test_log(test, sub_error_cnt);
+	int sub_error_cnt = result->error_cnt - result->old_error_cnt;
 
 	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"));
+	       test->test_num, result->subtest_num, test->test_name, result->subtest_name,
+	       sub_error_cnt ? "FAIL" : (result->subtest_skip_cnt ? "SKIP" : "OK"));
 
-	if (sub_error_cnt)
-		test->error_cnt++;
-	else if (test->skip_cnt == 0)
-		test->sub_succ_cnt++;
-	skip_account();
+	if (!sub_error_cnt) {
+		if (result->subtest_skip_cnt == 0) {
+			result->sub_succ_cnt++;
+		} else {
+			result->subtest_skip_cnt = 0;
+			result->skip_cnt++;
+		}
+	}
 
-	free(test->subtest_name);
-	test->subtest_name = NULL;
+	free(result->subtest_name);
+	result->subtest_name = NULL;
 }
 
 bool test__start_subtest(const char *subtest_name)
 {
 	struct prog_test_def *test = env.test;
+	struct test_result *result = env.test_result;
 
-	if (test->subtest_name)
+	if (result->subtest_name)
 		test__end_subtest();
 
-	test->subtest_num++;
+	result->subtest_num++;
 
 	if (!subtest_name || !subtest_name[0]) {
 		fprintf(env.stderr,
 			"Subtest #%d didn't provide sub-test name!\n",
-			test->subtest_num);
+			result->subtest_num);
 		return false;
 	}
 
 	if (!should_run_subtest(&env.test_selector,
 				&env.subtest_selector,
-				test->subtest_num,
+				result->subtest_num,
 				test->test_name,
 				subtest_name))
 		return false;
 
-	test->subtest_name = strdup(subtest_name);
-	if (!test->subtest_name) {
+	result->subtest_name = strdup(subtest_name);
+	if (!result->subtest_name) {
 		fprintf(env.stderr,
 			"Subtest #%d: failed to copy subtest name!\n",
-			test->subtest_num);
+			result->subtest_num);
 		return false;
 	}
-	env.test->old_error_cnt = env.test->error_cnt;
+	result->old_error_cnt = result->error_cnt;
 
 	return true;
 }
@@ -279,12 +265,15 @@ void test__force_log(void)
 
 void test__skip(void)
 {
-	env.test->skip_cnt++;
+	if (env.test_result->subtest_name)
+		env.test_result->subtest_skip_cnt++;
+	else
+		env.test_result->skip_cnt++;
 }
 
 void test__fail(void)
 {
-	env.test->error_cnt++;
+	env.test_result->error_cnt++;
 }
 
 int test__join_cgroup(const char *path)
@@ -517,8 +506,11 @@ static struct prog_test_def prog_test_defs[] = {
 #include <prog_tests/tests.h>
 #undef DEFINE_TEST
 };
+
 static const int prog_test_cnt = ARRAY_SIZE(prog_test_defs);
 
+static struct test_result test_results[ARRAY_SIZE(prog_test_defs)];
+
 const char *argp_program_version = "test_progs 0.1";
 const char *argp_program_bug_address = "<bpf@vger.kernel.org>";
 static const char argp_program_doc[] = "BPF selftests test runner";
@@ -838,18 +830,6 @@ static void sigint_handler(int signum)
 
 static int current_test_idx;
 static pthread_mutex_t current_test_lock;
-static pthread_mutex_t stdout_output_lock;
-
-struct test_result {
-	int error_cnt;
-	int skip_cnt;
-	int sub_succ_cnt;
-
-	size_t log_cnt;
-	char *log_buf;
-};
-
-static struct test_result test_results[ARRAY_SIZE(prog_test_defs)];
 
 static inline const char *str_msg(const struct msg *msg, char *buf)
 {
@@ -904,8 +884,12 @@ static int recv_message(int sock, struct msg *msg)
 static void run_one_test(int test_num)
 {
 	struct prog_test_def *test = &prog_test_defs[test_num];
+	struct test_result *result = &test_results[test_num];
+
+	stdio_hijack();
 
 	env.test = test;
+	env.test_result = result;
 
 	if (test->run_test)
 		test->run_test();
@@ -913,17 +897,26 @@ static void run_one_test(int test_num)
 		test->run_serial_test();
 
 	/* ensure last sub-test is finalized properly */
-	if (test->subtest_name)
+	if (result->subtest_name)
 		test__end_subtest();
 
-	test->tested = true;
-
-	dump_test_log(test, test->error_cnt);
+	result->tested = true;
 
 	reset_affinity();
 	restore_netns();
 	if (test->need_cgroup_cleanup)
 		cleanup_cgroup_environment();
+
+	stdio_restore();
+
+	if (env.log_buf) {
+		result->log_buf = strdup(env.log_buf);
+		result->log_cnt = env.log_cnt;
+
+		free(env.log_buf);
+		env.log_buf = NULL;
+		env.log_cnt = 0;
+	}
 }
 
 struct dispatch_data {
@@ -989,9 +982,8 @@ static void *dispatch_thread(void *ctx)
 			if (test_to_run != msg_test_done.test_done.test_num)
 				goto error;
 
-			test->tested = true;
 			result = &test_results[test_to_run];
-
+			result->tested = true;
 			result->error_cnt = msg_test_done.test_done.error_cnt;
 			result->skip_cnt = msg_test_done.test_done.skip_cnt;
 			result->sub_succ_cnt = msg_test_done.test_done.sub_succ_cnt;
@@ -1017,24 +1009,6 @@ static void *dispatch_thread(void *ctx)
 				fclose(log_fp);
 				log_fp = NULL;
 			}
-			/* output log */
-			{
-				pthread_mutex_lock(&stdout_output_lock);
-
-				if (result->log_cnt) {
-					result->log_buf[result->log_cnt] = '\0';
-					fprintf(stdout, "%s", result->log_buf);
-					if (result->log_buf[result->log_cnt - 1] != '\n')
-						fprintf(stdout, "\n");
-				}
-
-				fprintf(stdout, "#%d %s:%s\n",
-					test->test_num, test->test_name,
-					result->error_cnt ? "FAIL" : (result->skip_cnt ? "SKIP" : "OK"));
-
-				pthread_mutex_unlock(&stdout_output_lock);
-			}
-
 		} /* wait for test done */
 	} /* while (true) */
 error:
@@ -1057,38 +1031,72 @@ static void *dispatch_thread(void *ctx)
 	return NULL;
 }
 
-static void print_all_error_logs(void)
+static void calculate_and_print_summary(struct test_env *env)
 {
 	int i;
+	int succ_cnt = 0, fail_cnt = 0, sub_succ_cnt = 0, skip_cnt = 0;
+
+	for (i = 0; i < prog_test_cnt; i++) {
+		struct prog_test_def *test = &prog_test_defs[i];
+		struct test_result *result = &test_results[i];
+
+		if (!result->tested)
+			continue;
+
+		sub_succ_cnt += result->sub_succ_cnt;
+		skip_cnt += result->skip_cnt;
+
+		if (result->error_cnt)
+			fail_cnt++;
+		else
+			succ_cnt++;
+
+		printf("#%d %s:%s\n",
+		       test->test_num, test->test_name,
+		       result->error_cnt ? "FAIL" : (result->skip_cnt ? "SKIP" : "OK"));
+
+		if (env->verbosity > VERBOSE_NONE || test->force_log || result->error_cnt) {
+			if (result->log_cnt) {
+				result->log_buf[result->log_cnt] = '\0';
+				printf("%s", result->log_buf);
+				if (result->log_buf[result->log_cnt - 1] != '\n')
+					printf("\n");
+			}
+		}
+	}
 
-	if (env.fail_cnt)
-		fprintf(stdout, "\nAll error logs:\n");
+	if (fail_cnt)
+		printf("\nAll error logs:\n");
 
 	/* print error logs again */
 	for (i = 0; i < prog_test_cnt; i++) {
-		struct prog_test_def *test;
-		struct test_result *result;
-
-		test = &prog_test_defs[i];
-		result = &test_results[i];
+		struct prog_test_def *test = &prog_test_defs[i];
+		struct test_result *result = &test_results[i];
 
-		if (!test->tested || !result->error_cnt)
+		if (!result->tested || !result->error_cnt)
 			continue;
 
-		fprintf(stdout, "\n#%d %s:%s\n",
-			test->test_num, test->test_name,
-			result->error_cnt ? "FAIL" : (result->skip_cnt ? "SKIP" : "OK"));
+		printf("\n#%d %s:%s\n",
+		       test->test_num, test->test_name, "FAIL");
 
 		if (result->log_cnt) {
 			result->log_buf[result->log_cnt] = '\0';
-			fprintf(stdout, "%s", result->log_buf);
+			printf("%s", result->log_buf);
 			if (result->log_buf[result->log_cnt - 1] != '\n')
-				fprintf(stdout, "\n");
+				printf("\n");
 		}
 	}
+
+	printf("Summary: %d/%d PASSED, %d SKIPPED, %d FAILED\n",
+	       succ_cnt, sub_succ_cnt, skip_cnt, fail_cnt);
+
+	env->succ_cnt = succ_cnt;
+	env->sub_succ_cnt = sub_succ_cnt;
+	env->fail_cnt = fail_cnt;
+	env->skip_cnt = skip_cnt;
 }
 
-static int server_main(void)
+static void server_main(void)
 {
 	pthread_t *dispatcher_threads;
 	struct dispatch_data *data;
@@ -1144,60 +1152,18 @@ static int server_main(void)
 
 	for (int i = 0; i < prog_test_cnt; i++) {
 		struct prog_test_def *test = &prog_test_defs[i];
-		struct test_result *result = &test_results[i];
 
 		if (!test->should_run || !test->run_serial_test)
 			continue;
 
-		stdio_hijack();
-
 		run_one_test(i);
-
-		stdio_restore();
-		if (env.log_buf) {
-			result->log_cnt = env.log_cnt;
-			result->log_buf = strdup(env.log_buf);
-
-			free(env.log_buf);
-			env.log_buf = NULL;
-			env.log_cnt = 0;
-		}
-		restore_netns();
-
-		fprintf(stdout, "#%d %s:%s\n",
-			test->test_num, test->test_name,
-			test->error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
-
-		result->error_cnt = test->error_cnt;
-		result->skip_cnt = test->skip_cnt;
-		result->sub_succ_cnt = test->sub_succ_cnt;
 	}
 
 	/* generate summary */
 	fflush(stderr);
 	fflush(stdout);
 
-	for (i = 0; i < prog_test_cnt; i++) {
-		struct prog_test_def *current_test;
-		struct test_result *result;
-
-		current_test = &prog_test_defs[i];
-		result = &test_results[i];
-
-		if (!current_test->tested)
-			continue;
-
-		env.succ_cnt += result->error_cnt ? 0 : 1;
-		env.skip_cnt += result->skip_cnt;
-		if (result->error_cnt)
-			env.fail_cnt++;
-		env.sub_succ_cnt += result->sub_succ_cnt;
-	}
-
-	print_all_error_logs();
-
-	fprintf(stdout, "Summary: %d/%d PASSED, %d SKIPPED, %d FAILED\n",
-		env.succ_cnt, env.sub_succ_cnt, env.skip_cnt, env.fail_cnt);
+	calculate_and_print_summary(&env);
 
 	/* reap all workers */
 	for (i = 0; i < env.workers; i++) {
@@ -1207,8 +1173,6 @@ static int server_main(void)
 		if (pid != env.worker_pids[i])
 			perror("Unable to reap worker");
 	}
-
-	return 0;
 }
 
 static int worker_main(int sock)
@@ -1229,35 +1193,29 @@ static int worker_main(int sock)
 					env.worker_id);
 			goto out;
 		case MSG_DO_TEST: {
-			int test_to_run;
-			struct prog_test_def *test;
+			int test_to_run = msg.do_test.test_num;
+			struct prog_test_def *test = &prog_test_defs[test_to_run];
+			struct test_result *result = &test_results[test_to_run];
 			struct msg msg_done;
 
-			test_to_run = msg.do_test.test_num;
-			test = &prog_test_defs[test_to_run];
-
 			if (env.debug)
 				fprintf(stderr, "[%d]: #%d:%s running.\n",
 					env.worker_id,
 					test_to_run + 1,
 					test->test_name);
 
-			stdio_hijack();
-
 			run_one_test(test_to_run);
 
-			stdio_restore();
-
 			memset(&msg_done, 0, sizeof(msg_done));
 			msg_done.type = MSG_TEST_DONE;
 			msg_done.test_done.test_num = test_to_run;
-			msg_done.test_done.error_cnt = test->error_cnt;
-			msg_done.test_done.skip_cnt = test->skip_cnt;
-			msg_done.test_done.sub_succ_cnt = test->sub_succ_cnt;
+			msg_done.test_done.error_cnt = result->error_cnt;
+			msg_done.test_done.skip_cnt = result->skip_cnt;
+			msg_done.test_done.sub_succ_cnt = result->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)
+			if (env.verbosity > VERBOSE_NONE || test->force_log || result->error_cnt) {
+				if (result->log_cnt)
 					msg_done.test_done.have_log = true;
 			}
 			if (send_message(sock, &msg_done) < 0) {
@@ -1270,8 +1228,8 @@ static int worker_main(int sock)
 				char *src;
 				size_t slen;
 
-				src = env.log_buf;
-				slen = env.log_cnt;
+				src = result->log_buf;
+				slen = result->log_cnt;
 				while (slen) {
 					struct msg msg_log;
 					char *dest;
@@ -1291,10 +1249,10 @@ static int worker_main(int sock)
 					assert(send_message(sock, &msg_log) >= 0);
 				}
 			}
-			if (env.log_buf) {
-				free(env.log_buf);
-				env.log_buf = NULL;
-				env.log_cnt = 0;
+			if (result->log_buf) {
+				free(result->log_buf);
+				result->log_buf = NULL;
+				result->log_cnt = 0;
 			}
 			if (env.debug)
 				fprintf(stderr, "[%d]: #%d:%s done.\n",
@@ -1425,7 +1383,6 @@ int main(int argc, char **argv)
 
 	for (i = 0; i < prog_test_cnt; i++) {
 		struct prog_test_def *test = &prog_test_defs[i];
-		struct test_result *result;
 
 		if (!test->should_run)
 			continue;
@@ -1441,34 +1398,7 @@ int main(int argc, char **argv)
 			continue;
 		}
 
-		stdio_hijack();
-
 		run_one_test(i);
-
-		stdio_restore();
-
-		fprintf(env.stdout, "#%d %s:%s\n",
-			test->test_num, test->test_name,
-			test->error_cnt ? "FAIL" : (test->skip_cnt ? "SKIP" : "OK"));
-
-		result = &test_results[i];
-		result->error_cnt = test->error_cnt;
-		if (env.log_buf) {
-			result->log_buf = strdup(env.log_buf);
-			result->log_cnt = env.log_cnt;
-
-			free(env.log_buf);
-			env.log_buf = NULL;
-			env.log_cnt = 0;
-		}
-
-		if (test->error_cnt)
-			env.fail_cnt++;
-		else
-			env.succ_cnt++;
-
-		skip_account();
-		env.sub_succ_cnt += test->sub_succ_cnt;
 	}
 
 	if (env.get_test_cnt) {
@@ -1479,10 +1409,7 @@ int main(int argc, char **argv)
 	if (env.list_test_names)
 		goto out;
 
-	print_all_error_logs();
-
-	fprintf(stdout, "Summary: %d/%d PASSED, %d SKIPPED, %d FAILED\n",
-		env.succ_cnt, env.sub_succ_cnt, env.skip_cnt, env.fail_cnt);
+	calculate_and_print_summary(&env);
 
 	close(env.saved_netns_fd);
 out:
diff --git a/tools/testing/selftests/bpf/test_progs.h b/tools/testing/selftests/bpf/test_progs.h
index 6a8d68bb459e..0521d6348e83 100644
--- a/tools/testing/selftests/bpf/test_progs.h
+++ b/tools/testing/selftests/bpf/test_progs.h
@@ -64,6 +64,24 @@ struct test_selector {
 	int num_set_len;
 };
 
+struct test_result {
+	bool tested;
+
+	int error_cnt;
+	int skip_cnt;
+	int subtest_skip_cnt;
+	int sub_succ_cnt;
+
+	char *subtest_name;
+	int subtest_num;
+
+	/* store counts before subtest started */
+	int old_error_cnt;
+
+	size_t log_cnt;
+	char *log_buf;
+};
+
 struct test_env {
 	struct test_selector test_selector;
 	struct test_selector subtest_selector;
@@ -76,7 +94,8 @@ struct test_env {
 	bool get_test_cnt;
 	bool list_test_names;
 
-	struct prog_test_def *test; /* current running tests */
+	struct prog_test_def *test; /* current running test */
+	struct test_result *test_result; /* current running test result */
 
 	FILE *stdout;
 	FILE *stderr;
@@ -126,11 +145,12 @@ struct msg {
 
 extern struct test_env env;
 
-extern void test__force_log();
-extern bool test__start_subtest(const char *name);
-extern void test__skip(void);
-extern void test__fail(void);
-extern int test__join_cgroup(const char *path);
+void test__force_log(void);
+bool test__start_subtest(const char *name);
+void test__end_subtest(void);
+void test__skip(void);
+void test__fail(void);
+int test__join_cgroup(const char *path);
 
 #define PRINT_FAIL(format...)                                                  \
 	({                                                                     \
-- 
2.30.2


^ permalink raw reply related	[flat|nested] 3+ messages in thread

* Re: [PATCH bpf-next] selftests/bpf: consolidate common code in run_one_test function
  2022-04-14  5:05 [PATCH bpf-next] selftests/bpf: consolidate common code in run_one_test function Mykola Lysenko
@ 2022-04-14 22:49 ` Andrii Nakryiko
  2022-04-14 23:40   ` Mykola Lysenko
  0 siblings, 1 reply; 3+ messages in thread
From: Andrii Nakryiko @ 2022-04-14 22:49 UTC (permalink / raw)
  To: Mykola Lysenko
  Cc: bpf, Alexei Starovoitov, Andrii Nakryiko, Daniel Borkmann, Kernel Team

On Wed, Apr 13, 2022 at 10:05 PM Mykola Lysenko <mykolal@fb.com> wrote:
>
> This is a pre-req to add separate logging for each subtest.
>
> Move all the mutable test data to the test_result struct.
> Move per-test init/de-init into the run_one_test function.
> Consolidate data aggregation and final log output in
> calculate_and_print_summary function.
> As a side effect, this patch fixes double counting of errors
> for subtests and possible duplicate output of subtest log
> on failures.
>
> Also, add prog_tests_framework.c test to verify some of the
> counting logic.
>
> As part of verification, confirmed that number of reported
> tests is the same before and after the change for both parallel
> and sequential test execution.
>
> Signed-off-by: Mykola Lysenko <mykolal@fb.com>
> ---

The consolidation of the per-test logic in one place is great, thanks
for tackling this! But I tried this locally and understood what you
were mentioning as completely buffered output. It really sucks and is
a big step back, I think :(

Running sudo ./test_progs -j I see no output for a long while and only
then get entire output at the end:

#239 xdp_noinline:OK
#240 xdp_perf:OK
#241 xdpwall:OK

All error logs:

#58 fexit_sleep:FAIL
test_fexit_sleep:PASS:fexit_skel_load 0 nsec
test_fexit_sleep:PASS:fexit_attach 0 nsec
test_fexit_sleep:PASS:clone 0 nsec
test_fexit_sleep:PASS:fexit_cnt 0 nsec
test_fexit_sleep:PASS:waitpid 0 nsec
test_fexit_sleep:PASS:exitstatus 0 nsec
test_fexit_sleep:FAIL:fexit_cnt 2
Summary: 240/1156 PASSED, 34 SKIPPED, 1 FAILED


First, just not seeing the progress made me wonder for a good minute
or more whether something is just stuck and deadlock. Which is anxiety
inducing and I'd rather avoid this :)

Second, as you can see, fexit_sleep actually failed (it does sometimes
in parallel mode). But I saw this only at the very end, while normally
I'd notice it as soon as it completes. In this case I know fexit_sleep
can fail and I'd ignore, but if there was some subtest that suddenly
breaks, I don't wait for all the tests to finish, I ctrl-C and go
investigate. Now I can't do that.

How much of a problem is it to preserve old behavior of streaming
results of tests as they come, but consolidate duplicate logic in one
place?

>  .../bpf/prog_tests/prog_tests_framework.c     |  55 ++++
>  tools/testing/selftests/bpf/test_progs.c      | 301 +++++++-----------
>  tools/testing/selftests/bpf/test_progs.h      |  32 +-
>  3 files changed, 195 insertions(+), 193 deletions(-)
>  create mode 100644 tools/testing/selftests/bpf/prog_tests/prog_tests_framework.c
>
> diff --git a/tools/testing/selftests/bpf/prog_tests/prog_tests_framework.c b/tools/testing/selftests/bpf/prog_tests/prog_tests_framework.c
> new file mode 100644
> index 000000000000..7a5be06653f7
> --- /dev/null
> +++ b/tools/testing/selftests/bpf/prog_tests/prog_tests_framework.c
> @@ -0,0 +1,55 @@
> +// SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause)
> +
> +#include "test_progs.h"
> +#include "testing_helpers.h"
> +
> +static void clear_test_result(struct test_result *result)
> +{
> +       result->error_cnt = 0;
> +       result->sub_succ_cnt = 0;
> +       result->skip_cnt = 0;
> +}
> +
> +void test_prog_tests_framework(void)
> +{
> +       struct test_result *result = env.test_result;
> +
> +       // in all the ASSERT calls below we need to return on the first
> +       // error due to the fact that we are cleaning the test state after
> +       // each dummy subtest
> +
> +       // test we properly count skipped tests with subtests

C++ comments, please use /* */


> +       if (test__start_subtest("test_good_subtest"))
> +               test__end_subtest();
> +       if (!ASSERT_EQ(result->skip_cnt, 0, "skip_cnt_check"))
> +               return;
> +       if (!ASSERT_EQ(result->error_cnt, 0, "error_cnt_check"))
> +               return;
> +       if (!ASSERT_EQ(result->subtest_num, 1, "subtest_num_check"))
> +               return;
> +       clear_test_result(result);
> +

[...]

^ permalink raw reply	[flat|nested] 3+ messages in thread

* Re: [PATCH bpf-next] selftests/bpf: consolidate common code in run_one_test function
  2022-04-14 22:49 ` Andrii Nakryiko
@ 2022-04-14 23:40   ` Mykola Lysenko
  0 siblings, 0 replies; 3+ messages in thread
From: Mykola Lysenko @ 2022-04-14 23:40 UTC (permalink / raw)
  To: Andrii Nakryiko
  Cc: Mykola Lysenko, bpf, Alexei Starovoitov, Andrii Nakryiko,
	Daniel Borkmann, Kernel Team



> On Apr 14, 2022, at 3:49 PM, Andrii Nakryiko <andrii.nakryiko@gmail.com> wrote:
> 
> On Wed, Apr 13, 2022 at 10:05 PM Mykola Lysenko <mykolal@fb.com> wrote:
>> 
>> This is a pre-req to add separate logging for each subtest.
>> 
>> Move all the mutable test data to the test_result struct.
>> Move per-test init/de-init into the run_one_test function.
>> Consolidate data aggregation and final log output in
>> calculate_and_print_summary function.
>> As a side effect, this patch fixes double counting of errors
>> for subtests and possible duplicate output of subtest log
>> on failures.
>> 
>> Also, add prog_tests_framework.c test to verify some of the
>> counting logic.
>> 
>> As part of verification, confirmed that number of reported
>> tests is the same before and after the change for both parallel
>> and sequential test execution.
>> 
>> Signed-off-by: Mykola Lysenko <mykolal@fb.com>
>> ---
> 
> The consolidation of the per-test logic in one place is great, thanks
> for tackling this! But I tried this locally and understood what you
> were mentioning as completely buffered output. It really sucks and is
> a big step back, I think :(

Thanks Andrii! Your points make sense, in the next revision I will keep
this behavior untouched.

> 
> Running sudo ./test_progs -j I see no output for a long while and only
> then get entire output at the end:
> 
> #239 xdp_noinline:OK
> #240 xdp_perf:OK
> #241 xdpwall:OK
> 
> All error logs:
> 
> #58 fexit_sleep:FAIL
> test_fexit_sleep:PASS:fexit_skel_load 0 nsec
> test_fexit_sleep:PASS:fexit_attach 0 nsec
> test_fexit_sleep:PASS:clone 0 nsec
> test_fexit_sleep:PASS:fexit_cnt 0 nsec
> test_fexit_sleep:PASS:waitpid 0 nsec
> test_fexit_sleep:PASS:exitstatus 0 nsec
> test_fexit_sleep:FAIL:fexit_cnt 2
> Summary: 240/1156 PASSED, 34 SKIPPED, 1 FAILED
> 
> 
> First, just not seeing the progress made me wonder for a good minute
> or more whether something is just stuck and deadlock. Which is anxiety
> inducing and I'd rather avoid this :)
> 
> Second, as you can see, fexit_sleep actually failed (it does sometimes
> in parallel mode). But I saw this only at the very end, while normally
> I'd notice it as soon as it completes. In this case I know fexit_sleep
> can fail and I'd ignore, but if there was some subtest that suddenly
> breaks, I don't wait for all the tests to finish, I ctrl-C and go
> investigate. Now I can't do that.
> 
> How much of a problem is it to preserve old behavior of streaming
> results of tests as they come, but consolidate duplicate logic in one
> place?
> 
>> .../bpf/prog_tests/prog_tests_framework.c | 55 ++++
>> tools/testing/selftests/bpf/test_progs.c | 301 +++++++-----------
>> tools/testing/selftests/bpf/test_progs.h | 32 +-
>> 3 files changed, 195 insertions(+), 193 deletions(-)
>> create mode 100644 tools/testing/selftests/bpf/prog_tests/prog_tests_framework.c
>> 
>> diff --git a/tools/testing/selftests/bpf/prog_tests/prog_tests_framework.c b/tools/testing/selftests/bpf/prog_tests/prog_tests_framework.c
>> new file mode 100644
>> index 000000000000..7a5be06653f7
>> --- /dev/null
>> +++ b/tools/testing/selftests/bpf/prog_tests/prog_tests_framework.c
>> @@ -0,0 +1,55 @@
>> +// SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause)
>> +
>> +#include "test_progs.h"
>> +#include "testing_helpers.h"
>> +
>> +static void clear_test_result(struct test_result *result)
>> +{
>> + result->error_cnt = 0;
>> + result->sub_succ_cnt = 0;
>> + result->skip_cnt = 0;
>> +}
>> +
>> +void test_prog_tests_framework(void)
>> +{
>> + struct test_result *result = env.test_result;
>> +
>> + // in all the ASSERT calls below we need to return on the first
>> + // error due to the fact that we are cleaning the test state after
>> + // each dummy subtest
>> +
>> + // test we properly count skipped tests with subtests
> 
> C++ comments, please use /* */

Will fix.

> 
> 
>> + if (test__start_subtest("test_good_subtest"))
>> + test__end_subtest();
>> + if (!ASSERT_EQ(result->skip_cnt, 0, "skip_cnt_check"))
>> + return;
>> + if (!ASSERT_EQ(result->error_cnt, 0, "error_cnt_check"))
>> + return;
>> + if (!ASSERT_EQ(result->subtest_num, 1, "subtest_num_check"))
>> + return;
>> + clear_test_result(result);
>> +
> 
> [...]


^ permalink raw reply	[flat|nested] 3+ messages in thread

end of thread, other threads:[~2022-04-14 23:41 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-04-14  5:05 [PATCH bpf-next] selftests/bpf: consolidate common code in run_one_test function Mykola Lysenko
2022-04-14 22:49 ` Andrii Nakryiko
2022-04-14 23:40   ` Mykola Lysenko

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.