LKML Archive on lore.kernel.org
help / color / mirror / Atom feed
* [PATCH v3 0/3] kunit: allow running test suites/cases individually
@ 2021-09-29 19:54 Daniel Latypov
  2021-09-29 19:54 ` [PATCH v3 1/4] kunit: add 'kunit.action' param to allow listing out tests Daniel Latypov
                   ` (3 more replies)
  0 siblings, 4 replies; 8+ messages in thread
From: Daniel Latypov @ 2021-09-29 19:54 UTC (permalink / raw)
  To: brendanhiggins, davidgow
  Cc: linux-kernel, kunit-dev, linux-kselftest, skhan, Daniel Latypov

Allow running each suite or each test case alone per kernel boot.
The motivation for this is to debug "test hermeticity" issues.
This new --run_isolated flag would be a good first step to try and
narrow down root causes.

Context: sometimes tests pass/fail depending on what ran before them.
Memory corruption errors in particular might only cause noticeable
issues later on. But you can also have the opposite, where "fixing" one
test causes another to start failing.

Usage:
$ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --run_isolated=suite
$ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --run_isolated=test
$ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --run_isolated=test example

The last one would provide output like
  ======== [PASSED] example ========
  [PASSED] example_simple_test
  ============================================================
  Testing complete. 1 tests run. 0 failed. 0 crashed. 0 skipped.
  Starting KUnit Kernel (2/3)...
  ============================================================
  ======== [SKIPPED] example ========
  [SKIPPED] example_skip_test # SKIP this test should be skipped
  ============================================================
  Testing complete. 1 tests run. 0 failed. 0 crashed. 1 skipped.
  Starting KUnit Kernel (3/3)...
  ============================================================
  ======== [SKIPPED] example ========
  [SKIPPED] example_mark_skipped_test # SKIP this test should be skipped
  ============================================================
  Testing complete. 1 tests run. 0 failed. 0 crashed. 1 skipped.

See the last patch's description for a bit more detail.

Meta:
The first patch is from another series with just a reworded commit
message, https://lore.kernel.org/linux-kselftest/20210805235145.2528054-2-dlatypov@google.com/

This patch series is based on Shuah's kunit branch:
https://git.kernel.org/pub/scm/linux/kernel/git/shuah/linux-kselftest.git/?h=kunit

Changes:
v1 -> v2: rebase onto Shuah's kunit branch, fix missing code in patch 1.
v2 -> v3: fix mypy errors, drop test plan from output, fix pre-existing
bug where kunit was not actually tracking test execution time (new patch 3).

Daniel Latypov (4):
  kunit: add 'kunit.action' param to allow listing out tests
  kunit: tool: factor exec + parse steps into a function
  kunit: tool: actually track how long it took to run tests
  kunit: tool: support running each suite/test separately

 lib/kunit/executor.c                   |  45 ++++++++-
 tools/testing/kunit/kunit.py           | 129 +++++++++++++++++--------
 tools/testing/kunit/kunit_tool_test.py |  40 ++++++++
 3 files changed, 169 insertions(+), 45 deletions(-)


base-commit: 3b29021ddd10cfb6b2565c623595bd3b02036f33
-- 
2.33.0.685.g46640cef36-goog


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

* [PATCH v3 1/4] kunit: add 'kunit.action' param to allow listing out tests
  2021-09-29 19:54 [PATCH v3 0/3] kunit: allow running test suites/cases individually Daniel Latypov
@ 2021-09-29 19:54 ` Daniel Latypov
  2021-09-29 19:54 ` [PATCH v3 2/4] kunit: tool: factor exec + parse steps into a function Daniel Latypov
                   ` (2 subsequent siblings)
  3 siblings, 0 replies; 8+ messages in thread
From: Daniel Latypov @ 2021-09-29 19:54 UTC (permalink / raw)
  To: brendanhiggins, davidgow
  Cc: linux-kernel, kunit-dev, linux-kselftest, skhan, Daniel Latypov

Context:
It's difficult to map a given .kunitconfig => set of enabled tests.
Letting kunit.py figure that out would be useful.

This patch:
* is intended to be an implementation detail used only by kunit.py
* adds a kunit.action module param with one valid non-null value, "list"
* for the "list" action, it simply prints out "<suite>.<test>"
* leaves the kunit.py changes to make use of this for another patch.

Note: kunit.filter_glob is respected for this and all future actions.

Hack: we print a TAP header (but no test plan) to allow kunit.py to
use the same code to pick up KUnit output that it does for normal tests.
Since this is intended to be an implementation detail, it seems fine for
now. Maybe in the future we output each test as SKIPPED or the like.

Go with a more generic "action" param, since it seems like we might
eventually have more modes besides just running or listing tests, e.g.
* perhaps a benchmark mode that reruns test cases and reports timing
* perhaps a deflake mode that reruns test cases that failed
* perhaps a mode where we randomize test order to try and catch
  hermeticity bugs like "test a only passes if run after test b"

Tested:
$ ./tools/testing/kunit/kunit.py run --kernel_arg=kunit.action=list --raw_output=kunit
...
TAP version 14
1..1
example.example_simple_test
example.example_skip_test
example.example_mark_skipped_test
reboot: System halted

Signed-off-by: Daniel Latypov <dlatypov@google.com>
Reviewed-by: David Gow <davidgow@google.com>
---
 lib/kunit/executor.c | 45 +++++++++++++++++++++++++++++++++++++++-----
 1 file changed, 40 insertions(+), 5 deletions(-)

diff --git a/lib/kunit/executor.c b/lib/kunit/executor.c
index bab3ab940acc..ce1f57a44ab9 100644
--- a/lib/kunit/executor.c
+++ b/lib/kunit/executor.c
@@ -15,9 +15,16 @@ extern struct kunit_suite * const * const __kunit_suites_end[];
 #if IS_BUILTIN(CONFIG_KUNIT)
 
 static char *filter_glob_param;
+static char *action_param;
+
 module_param_named(filter_glob, filter_glob_param, charp, 0);
 MODULE_PARM_DESC(filter_glob,
 		"Filter which KUnit test suites/tests run at boot-time, e.g. list* or list*.*del_test");
+module_param_named(action, action_param, charp, 0);
+MODULE_PARM_DESC(action,
+		 "Changes KUnit executor behavior, valid values are:\n"
+		 "<none>: run the tests like normal\n"
+		 "'list' to list test names instead of running them.\n");
 
 /* glob_match() needs NULL terminated strings, so we need a copy of filter_glob_param. */
 struct kunit_test_filter {
@@ -196,9 +203,35 @@ static void kunit_print_tap_header(struct suite_set *suite_set)
 	pr_info("1..%d\n", num_of_suites);
 }
 
-int kunit_run_all_tests(void)
+static void kunit_exec_run_tests(struct suite_set *suite_set)
 {
 	struct kunit_suite * const * const *suites;
+
+	kunit_print_tap_header(suite_set);
+
+	for (suites = suite_set->start; suites < suite_set->end; suites++)
+		__kunit_test_suites_init(*suites);
+}
+
+static void kunit_exec_list_tests(struct suite_set *suite_set)
+{
+	unsigned int i;
+	struct kunit_suite * const * const *suites;
+	struct kunit_case *test_case;
+
+	/* Hack: print a tap header so kunit.py can find the start of KUnit output. */
+	pr_info("TAP version 14\n");
+
+	for (suites = suite_set->start; suites < suite_set->end; suites++)
+		for (i = 0; (*suites)[i] != NULL; i++) {
+			kunit_suite_for_each_test_case((*suites)[i], test_case) {
+				pr_info("%s.%s\n", (*suites)[i]->name, test_case->name);
+			}
+		}
+}
+
+int kunit_run_all_tests(void)
+{
 	struct suite_set suite_set = {
 		.start = __kunit_suites_start,
 		.end = __kunit_suites_end,
@@ -207,10 +240,12 @@ int kunit_run_all_tests(void)
 	if (filter_glob_param)
 		suite_set = kunit_filter_suites(&suite_set, filter_glob_param);
 
-	kunit_print_tap_header(&suite_set);
-
-	for (suites = suite_set.start; suites < suite_set.end; suites++)
-		__kunit_test_suites_init(*suites);
+	if (!action_param)
+		kunit_exec_run_tests(&suite_set);
+	else if (strcmp(action_param, "list") == 0)
+		kunit_exec_list_tests(&suite_set);
+	else
+		pr_err("kunit executor: unknown action '%s'\n", action_param);
 
 	if (filter_glob_param) { /* a copy was made of each array */
 		kunit_free_suite_set(suite_set);
-- 
2.33.0.685.g46640cef36-goog


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

* [PATCH v3 2/4] kunit: tool: factor exec + parse steps into a function
  2021-09-29 19:54 [PATCH v3 0/3] kunit: allow running test suites/cases individually Daniel Latypov
  2021-09-29 19:54 ` [PATCH v3 1/4] kunit: add 'kunit.action' param to allow listing out tests Daniel Latypov
@ 2021-09-29 19:54 ` Daniel Latypov
  2021-09-29 19:54 ` [PATCH v3 3/4] kunit: tool: actually track how long it took to run tests Daniel Latypov
  2021-09-29 19:54 ` [PATCH v3 4/4] kunit: tool: support running each suite/test separately Daniel Latypov
  3 siblings, 0 replies; 8+ messages in thread
From: Daniel Latypov @ 2021-09-29 19:54 UTC (permalink / raw)
  To: brendanhiggins, davidgow
  Cc: linux-kernel, kunit-dev, linux-kselftest, skhan, Daniel Latypov

Currently this code is copy-pasted between the normal "run" subcommand
and the "exec" subcommand.

Given we don't have any interest in just executing the tests without
giving the user any indication what happened (i.e. parsing the output),
make a function that does both this things and can be reused.

This will be useful when we allow more complicated ways of running
tests, e.g. invoking the kernel multiple times instead of just once,
etc.

We remove input_data from the ParseRequest so the callers don't have to
pass in a dummy value for this field. Named tuples are also immutable,
so if they did pass in a dummy, exec_tests() would need to make a copy
to call parse_tests().

Removing it also makes KunitParseRequest match the other *Request types,
as they only contain user arguments/flags, not data.

Signed-off-by: Daniel Latypov <dlatypov@google.com>
Reviewed-by: David Gow <davidgow@google.com>
---
 tools/testing/kunit/kunit.py | 44 ++++++++++++++++--------------------
 1 file changed, 19 insertions(+), 25 deletions(-)

diff --git a/tools/testing/kunit/kunit.py b/tools/testing/kunit/kunit.py
index 66f67af97971..31eec9f6ecc3 100755
--- a/tools/testing/kunit/kunit.py
+++ b/tools/testing/kunit/kunit.py
@@ -34,7 +34,7 @@ KunitExecRequest = namedtuple('KunitExecRequest',
                               ['timeout', 'build_dir', 'alltests',
                                'filter_glob', 'kernel_args'])
 KunitParseRequest = namedtuple('KunitParseRequest',
-			       ['raw_output', 'input_data', 'build_dir', 'json'])
+			       ['raw_output', 'build_dir', 'json'])
 KunitRequest = namedtuple('KunitRequest', ['raw_output','timeout', 'jobs',
 					   'build_dir', 'alltests', 'filter_glob',
 					   'kernel_args', 'json', 'make_options'])
@@ -91,23 +91,25 @@ def build_tests(linux: kunit_kernel.LinuxSourceTree,
 			   'built kernel successfully',
 			   build_end - build_start)
 
-def exec_tests(linux: kunit_kernel.LinuxSourceTree,
-	       request: KunitExecRequest) -> KunitResult:
+def exec_tests(linux: kunit_kernel.LinuxSourceTree, request: KunitExecRequest,
+	       parse_request: KunitParseRequest) -> KunitResult:
 	kunit_parser.print_with_timestamp('Starting KUnit Kernel ...')
 	test_start = time.time()
-	result = linux.run_kernel(
+	run_result = linux.run_kernel(
 		args=request.kernel_args,
 		timeout=None if request.alltests else request.timeout,
-                filter_glob=request.filter_glob,
+		filter_glob=request.filter_glob,
 		build_dir=request.build_dir)
 
 	test_end = time.time()
+	exec_time = test_end - test_start
 
-	return KunitResult(KunitStatus.SUCCESS,
-			   result,
-			   test_end - test_start)
+	# Named tuples are immutable, so we rebuild them here manually
+	result = parse_tests(parse_request, run_result)
+
+	return KunitResult(status=result.status, result=result.result, elapsed_time=exec_time)
 
-def parse_tests(request: KunitParseRequest) -> KunitResult:
+def parse_tests(request: KunitParseRequest, input_data: Iterable[str]) -> KunitResult:
 	parse_start = time.time()
 
 	test_result = kunit_parser.TestResult(kunit_parser.TestStatus.SUCCESS,
@@ -115,7 +117,7 @@ def parse_tests(request: KunitParseRequest) -> KunitResult:
 					      'Tests not Parsed.')
 
 	if request.raw_output:
-		output: Iterable[str] = request.input_data
+		output: Iterable[str] = input_data
 		if request.raw_output == 'all':
 			pass
 		elif request.raw_output == 'kunit':
@@ -126,7 +128,7 @@ def parse_tests(request: KunitParseRequest) -> KunitResult:
 			print(line.rstrip())
 
 	else:
-		test_result = kunit_parser.parse_run_tests(request.input_data)
+		test_result = kunit_parser.parse_run_tests(input_data)
 	parse_end = time.time()
 
 	if request.json:
@@ -165,15 +167,11 @@ def run_tests(linux: kunit_kernel.LinuxSourceTree,
 	exec_request = KunitExecRequest(request.timeout, request.build_dir,
 				 request.alltests, request.filter_glob,
 				 request.kernel_args)
-	exec_result = exec_tests(linux, exec_request)
-	if exec_result.status != KunitStatus.SUCCESS:
-		return exec_result
-
 	parse_request = KunitParseRequest(request.raw_output,
-					  exec_result.result,
 					  request.build_dir,
 					  request.json)
-	parse_result = parse_tests(parse_request)
+
+	exec_result = exec_tests(linux, exec_request, parse_request)
 
 	run_end = time.time()
 
@@ -184,7 +182,7 @@ def run_tests(linux: kunit_kernel.LinuxSourceTree,
 				config_result.elapsed_time,
 				build_result.elapsed_time,
 				exec_result.elapsed_time))
-	return parse_result
+	return exec_result
 
 def add_common_opts(parser) -> None:
 	parser.add_argument('--build_dir',
@@ -381,15 +379,12 @@ def main(argv, linux=None):
 						cli_args.alltests,
 						cli_args.filter_glob,
 						cli_args.kernel_args)
-		exec_result = exec_tests(linux, exec_request)
 		parse_request = KunitParseRequest(cli_args.raw_output,
-						  exec_result.result,
 						  cli_args.build_dir,
 						  cli_args.json)
-		result = parse_tests(parse_request)
+		result = exec_tests(linux, exec_request, parse_request)
 		kunit_parser.print_with_timestamp((
-			'Elapsed time: %.3fs\n') % (
-				exec_result.elapsed_time))
+			'Elapsed time: %.3fs\n') % (result.elapsed_time))
 		if result.status != KunitStatus.SUCCESS:
 			sys.exit(1)
 	elif cli_args.subcommand == 'parse':
@@ -399,10 +394,9 @@ def main(argv, linux=None):
 			with open(cli_args.file, 'r') as f:
 				kunit_output = f.read().splitlines()
 		request = KunitParseRequest(cli_args.raw_output,
-					    kunit_output,
 					    None,
 					    cli_args.json)
-		result = parse_tests(request)
+		result = parse_tests(request, kunit_output)
 		if result.status != KunitStatus.SUCCESS:
 			sys.exit(1)
 	else:
-- 
2.33.0.685.g46640cef36-goog


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

* [PATCH v3 3/4] kunit: tool: actually track how long it took to run tests
  2021-09-29 19:54 [PATCH v3 0/3] kunit: allow running test suites/cases individually Daniel Latypov
  2021-09-29 19:54 ` [PATCH v3 1/4] kunit: add 'kunit.action' param to allow listing out tests Daniel Latypov
  2021-09-29 19:54 ` [PATCH v3 2/4] kunit: tool: factor exec + parse steps into a function Daniel Latypov
@ 2021-09-29 19:54 ` Daniel Latypov
  2021-09-30  2:29   ` David Gow
  2021-09-29 19:54 ` [PATCH v3 4/4] kunit: tool: support running each suite/test separately Daniel Latypov
  3 siblings, 1 reply; 8+ messages in thread
From: Daniel Latypov @ 2021-09-29 19:54 UTC (permalink / raw)
  To: brendanhiggins, davidgow
  Cc: linux-kernel, kunit-dev, linux-kselftest, skhan, Daniel Latypov

This is a long standing bug in kunit tool.
Since these files were added, run_kernel() has always yielded lines.

That means, the call to run_kernel() returns before the kernel finishes
executing tests, potentially before a single line of output is even
produced.

So code like this
  time_start = time.time()
  result = linux.run_kernel(...)
  time_end = time.time()

would only measure the time taken for python to give back the generator
object.

From a caller's perspective, the only way to know the kernel has exited
is for us to consume all the output from the `result` generator object.
Alternatively, we could change run_kernel() to try and do its own book
keeping and return the total time, but that doesn't seem worth it.

This change makes us record `time_end` after we're doing parsing all the
output (which should mean we've consumed all of it, or errored out).
That means we're including in the parsing time as well, but that should
be quite small, and it's better than claiming it took 0s to run tests.

Let's use this as an example:
$ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit example

Before:
Elapsed time: 7.684s total, 0.001s configuring, 4.692s building, 0.000s running

After:
Elapsed time: 6.283s total, 0.001s configuring, 3.202s building, 3.079s running

Signed-off-by: Daniel Latypov <dlatypov@google.com>
---
 tools/testing/kunit/kunit.py | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

diff --git a/tools/testing/kunit/kunit.py b/tools/testing/kunit/kunit.py
index 31eec9f6ecc3..5e717594df5b 100755
--- a/tools/testing/kunit/kunit.py
+++ b/tools/testing/kunit/kunit.py
@@ -101,12 +101,14 @@ def exec_tests(linux: kunit_kernel.LinuxSourceTree, request: KunitExecRequest,
 		filter_glob=request.filter_glob,
 		build_dir=request.build_dir)
 
+	result = parse_tests(parse_request, run_result)
+
+	# run_kernel() doesn't block on the kernel exiting.
+	# That only happens after we get the last line of output from `run_result`.
+	# So exec_time here actually contains parsing + execution time, which is fine.
 	test_end = time.time()
 	exec_time = test_end - test_start
 
-	# Named tuples are immutable, so we rebuild them here manually
-	result = parse_tests(parse_request, run_result)
-
 	return KunitResult(status=result.status, result=result.result, elapsed_time=exec_time)
 
 def parse_tests(request: KunitParseRequest, input_data: Iterable[str]) -> KunitResult:
-- 
2.33.0.685.g46640cef36-goog


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

* [PATCH v3 4/4] kunit: tool: support running each suite/test separately
  2021-09-29 19:54 [PATCH v3 0/3] kunit: allow running test suites/cases individually Daniel Latypov
                   ` (2 preceding siblings ...)
  2021-09-29 19:54 ` [PATCH v3 3/4] kunit: tool: actually track how long it took to run tests Daniel Latypov
@ 2021-09-29 19:54 ` Daniel Latypov
  2021-09-30  2:27   ` David Gow
  3 siblings, 1 reply; 8+ messages in thread
From: Daniel Latypov @ 2021-09-29 19:54 UTC (permalink / raw)
  To: brendanhiggins, davidgow
  Cc: linux-kernel, kunit-dev, linux-kselftest, skhan, Daniel Latypov

The new --run_isolated flag makes the tool boot the kernel once per
suite or test, preventing leftover state from one suite to impact the
other. This can be useful as a starting point to debugging test
hermeticity issues.

Note: it takes a lot longer, so people should not use it normally.

Consider the following very simplified example:

  bool disable_something_for_test = false;
  void function_being_tested() {
    ...
    if (disable_something_for_test) return;
    ...
  }

  static void test_before(struct kunit *test)
  {
    disable_something_for_test = true;
    function_being_tested();
    /* oops, we forgot to reset it back to false */
  }

  static void test_after(struct kunit *test)
  {
    /* oops, now "fixing" test_before can cause test_after to fail! */
    function_being_tested();
  }

Presented like this, the issues are obvious, but it gets a lot more
complicated to track down as the amount of test setup and helper
functions increases.

Another use case is memory corruption. It might not be surfaced as a
failure/crash in the test case or suite that caused it. I've noticed in
kunit's own unit tests, the 3rd suite after might be the one to finally
crash after an out-of-bounds write, for example.

Example usage:

Per suite:
$ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --run_isolated=suite
...
Starting KUnit Kernel (1/7)...
============================================================
======== [PASSED] kunit_executor_test ========
....
Testing complete. 5 tests run. 0 failed. 0 crashed. 0 skipped.
Starting KUnit Kernel (2/7)...
============================================================
======== [PASSED] kunit-try-catch-test ========
...

Per test:
$ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --run_isolated=test
Starting KUnit Kernel (1/23)...
============================================================
======== [PASSED] kunit_executor_test ========
[PASSED] parse_filter_test
============================================================
Testing complete. 1 tests run. 0 failed. 0 crashed. 0 skipped.
Starting KUnit Kernel (2/23)...
============================================================
======== [PASSED] kunit_executor_test ========
[PASSED] filter_subsuite_test
...

It works with filters as well:
$ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --run_isolated=suite example
...
Starting KUnit Kernel (1/1)...
============================================================
======== [PASSED] example ========
...

It also handles test filters, '*.*skip*' runs these 3 tests:
  kunit_status.kunit_status_mark_skipped_test
  example.example_skip_test
  example.example_mark_skipped_test

Signed-off-by: Daniel Latypov <dlatypov@google.com>
Reviewed-by: David Gow <davidgow@google.com>
---
 tools/testing/kunit/kunit.py           | 95 ++++++++++++++++++++------
 tools/testing/kunit/kunit_tool_test.py | 40 +++++++++++
 2 files changed, 114 insertions(+), 21 deletions(-)

diff --git a/tools/testing/kunit/kunit.py b/tools/testing/kunit/kunit.py
index 5e717594df5b..b9d63f558765 100755
--- a/tools/testing/kunit/kunit.py
+++ b/tools/testing/kunit/kunit.py
@@ -16,7 +16,7 @@ assert sys.version_info >= (3, 7), "Python version is too old"
 
 from collections import namedtuple
 from enum import Enum, auto
-from typing import Iterable
+from typing import Iterable, List
 
 import kunit_config
 import kunit_json
@@ -31,13 +31,13 @@ KunitBuildRequest = namedtuple('KunitBuildRequest',
 			       ['jobs', 'build_dir', 'alltests',
 				'make_options'])
 KunitExecRequest = namedtuple('KunitExecRequest',
-                              ['timeout', 'build_dir', 'alltests',
-                               'filter_glob', 'kernel_args'])
+			      ['timeout', 'build_dir', 'alltests',
+			       'filter_glob', 'kernel_args', 'run_isolated'])
 KunitParseRequest = namedtuple('KunitParseRequest',
 			       ['raw_output', 'build_dir', 'json'])
 KunitRequest = namedtuple('KunitRequest', ['raw_output','timeout', 'jobs',
 					   'build_dir', 'alltests', 'filter_glob',
-					   'kernel_args', 'json', 'make_options'])
+					   'kernel_args', 'run_isolated', 'json', 'make_options'])
 
 KernelDirectoryPath = sys.argv[0].split('tools/testing/kunit/')[0]
 
@@ -91,23 +91,68 @@ def build_tests(linux: kunit_kernel.LinuxSourceTree,
 			   'built kernel successfully',
 			   build_end - build_start)
 
+def _list_tests(linux: kunit_kernel.LinuxSourceTree, request: KunitExecRequest) -> List[str]:
+	args = ['kunit.action=list']
+	if request.kernel_args:
+		args.extend(request.kernel_args)
+
+	output = linux.run_kernel(args=args,
+			   timeout=None if request.alltests else request.timeout,
+			   filter_glob=request.filter_glob,
+			   build_dir=request.build_dir)
+	lines = kunit_parser.extract_tap_lines(output)
+	# Hack! Drop the dummy TAP version header that the executor prints out.
+	lines.pop()
+	return list(lines)
+
+def _suites_from_test_list(tests: List[str]) -> List[str]:
+	"""Extracts all the suites from an ordered list of tests."""
+	suites = []  # type: List[str]
+	for t in tests:
+		parts = t.split('.', maxsplit=2)
+		if len(parts) != 2:
+			raise ValueError(f'internal KUnit error, test name should be of the form "<suite>.<test>", got "{t}"')
+		suite, case = parts
+		if not suites or suites[-1] != suite:
+			suites.append(suite)
+	return suites
+
+
+
 def exec_tests(linux: kunit_kernel.LinuxSourceTree, request: KunitExecRequest,
 	       parse_request: KunitParseRequest) -> KunitResult:
-	kunit_parser.print_with_timestamp('Starting KUnit Kernel ...')
-	test_start = time.time()
-	run_result = linux.run_kernel(
-		args=request.kernel_args,
-		timeout=None if request.alltests else request.timeout,
-		filter_glob=request.filter_glob,
-		build_dir=request.build_dir)
-
-	result = parse_tests(parse_request, run_result)
-
-	# run_kernel() doesn't block on the kernel exiting.
-	# That only happens after we get the last line of output from `run_result`.
-	# So exec_time here actually contains parsing + execution time, which is fine.
-	test_end = time.time()
-	exec_time = test_end - test_start
+	filter_globs = [request.filter_glob]
+	if request.run_isolated:
+		tests = _list_tests(linux, request)
+		if request.run_isolated == 'test':
+			filter_globs = tests
+		if request.run_isolated == 'suite':
+			filter_globs = _suites_from_test_list(tests)
+			# Apply the test-part of the user's glob, if present.
+			if '.' in request.filter_glob:
+				test_glob = request.filter_glob.split('.', maxsplit=2)[1]
+				filter_globs = [g + '.'+ test_glob for g in filter_globs]
+
+	overall_status = kunit_parser.TestStatus.SUCCESS
+	exec_time = 0.0
+	for i, filter_glob in enumerate(filter_globs):
+		kunit_parser.print_with_timestamp('Starting KUnit Kernel ({}/{})...'.format(i+1, len(filter_globs)))
+
+		test_start = time.time()
+		run_result = linux.run_kernel(
+			args=request.kernel_args,
+			timeout=None if request.alltests else request.timeout,
+			filter_glob=filter_glob,
+			build_dir=request.build_dir)
+
+		result = parse_tests(parse_request, run_result)
+		# run_kernel() doesn't block on the kernel exiting.
+		# That only happens after we get the last line of output from `run_result`.
+		# So exec_time here actually contains parsing + execution time, which is fine.
+		test_end = time.time()
+		exec_time += test_end - test_start
+
+		overall_status = kunit_parser.max_status(overall_status, result.status)
 
 	return KunitResult(status=result.status, result=result.result, elapsed_time=exec_time)
 
@@ -168,7 +213,7 @@ def run_tests(linux: kunit_kernel.LinuxSourceTree,
 
 	exec_request = KunitExecRequest(request.timeout, request.build_dir,
 				 request.alltests, request.filter_glob,
-				 request.kernel_args)
+				 request.kernel_args, request.run_isolated)
 	parse_request = KunitParseRequest(request.raw_output,
 					  request.build_dir,
 					  request.json)
@@ -252,6 +297,12 @@ def add_exec_opts(parser) -> None:
 	parser.add_argument('--kernel_args',
 			    help='Kernel command-line parameters. Maybe be repeated',
 			     action='append')
+	parser.add_argument('--run_isolated', help='If set, boot the kernel for each '
+			    'individual suite/test. This is can be useful for debugging '
+			    'a non-hermetic test, one that might pass/fail based on '
+			    'what ran before it.',
+			    type=str,
+			    choices=['suite', 'test']),
 
 def add_parse_opts(parser) -> None:
 	parser.add_argument('--raw_output', help='If set don\'t format output from kernel. '
@@ -325,6 +376,7 @@ def main(argv, linux=None):
 				       cli_args.alltests,
 				       cli_args.filter_glob,
 				       cli_args.kernel_args,
+				       cli_args.run_isolated,
 				       cli_args.json,
 				       cli_args.make_options)
 		result = run_tests(linux, request)
@@ -380,7 +432,8 @@ def main(argv, linux=None):
 						cli_args.build_dir,
 						cli_args.alltests,
 						cli_args.filter_glob,
-						cli_args.kernel_args)
+						cli_args.kernel_args,
+						cli_args.run_isolated)
 		parse_request = KunitParseRequest(cli_args.raw_output,
 						  cli_args.build_dir,
 						  cli_args.json)
diff --git a/tools/testing/kunit/kunit_tool_test.py b/tools/testing/kunit/kunit_tool_test.py
index 619c4554cbff..1ff35c08d2c8 100755
--- a/tools/testing/kunit/kunit_tool_test.py
+++ b/tools/testing/kunit/kunit_tool_test.py
@@ -477,6 +477,46 @@ class KUnitMainTest(unittest.TestCase):
 		      args=['a=1','b=2'], build_dir='.kunit', filter_glob='', timeout=300)
 		self.print_mock.assert_any_call(StrContains('Testing complete.'))
 
+	def test_list_tests(self):
+		want = ['suite.test1', 'suite.test2', 'suite2.test1']
+		self.linux_source_mock.run_kernel.return_value = ['TAP version 14'] + want
+
+		got = kunit._list_tests(self.linux_source_mock,
+				     kunit.KunitExecRequest(300, '.kunit', False, 'suite*', None, 'suite'))
+
+		self.assertEqual(got, want)
+		# Should respect the user's filter glob when listing tests.
+		self.linux_source_mock.run_kernel.assert_called_once_with(
+			args=['kunit.action=list'], build_dir='.kunit', filter_glob='suite*', timeout=300)
+
+
+	@mock.patch.object(kunit, '_list_tests')
+	def test_run_isolated_by_suite(self, mock_tests):
+		mock_tests.return_value = ['suite.test1', 'suite.test2', 'suite2.test1']
+		kunit.main(['exec', '--run_isolated=suite', 'suite*.test*'], self.linux_source_mock)
+
+		# Should respect the user's filter glob when listing tests.
+		mock_tests.assert_called_once_with(mock.ANY,
+				     kunit.KunitExecRequest(300, '.kunit', False, 'suite*.test*', None, 'suite'))
+		self.linux_source_mock.run_kernel.assert_has_calls([
+			mock.call(args=None, build_dir='.kunit', filter_glob='suite.test*', timeout=300),
+			mock.call(args=None, build_dir='.kunit', filter_glob='suite2.test*', timeout=300),
+		])
+
+	@mock.patch.object(kunit, '_list_tests')
+	def test_run_isolated_by_test(self, mock_tests):
+		mock_tests.return_value = ['suite.test1', 'suite.test2', 'suite2.test1']
+		kunit.main(['exec', '--run_isolated=test', 'suite*'], self.linux_source_mock)
+
+		# Should respect the user's filter glob when listing tests.
+		mock_tests.assert_called_once_with(mock.ANY,
+				     kunit.KunitExecRequest(300, '.kunit', False, 'suite*', None, 'test'))
+		self.linux_source_mock.run_kernel.assert_has_calls([
+			mock.call(args=None, build_dir='.kunit', filter_glob='suite.test1', timeout=300),
+			mock.call(args=None, build_dir='.kunit', filter_glob='suite.test2', timeout=300),
+			mock.call(args=None, build_dir='.kunit', filter_glob='suite2.test1', timeout=300),
+		])
+
 
 if __name__ == '__main__':
 	unittest.main()
-- 
2.33.0.685.g46640cef36-goog


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

* Re: [PATCH v3 4/4] kunit: tool: support running each suite/test separately
  2021-09-29 19:54 ` [PATCH v3 4/4] kunit: tool: support running each suite/test separately Daniel Latypov
@ 2021-09-30  2:27   ` David Gow
  2021-09-30 16:30     ` Daniel Latypov
  0 siblings, 1 reply; 8+ messages in thread
From: David Gow @ 2021-09-30  2:27 UTC (permalink / raw)
  To: Daniel Latypov
  Cc: Brendan Higgins, Linux Kernel Mailing List, KUnit Development,
	open list:KERNEL SELFTEST FRAMEWORK, Shuah Khan

On Thu, Sep 30, 2021 at 3:54 AM Daniel Latypov <dlatypov@google.com> wrote:
>
> The new --run_isolated flag makes the tool boot the kernel once per
> suite or test, preventing leftover state from one suite to impact the
> other. This can be useful as a starting point to debugging test
> hermeticity issues.
>
> Note: it takes a lot longer, so people should not use it normally.
>
> Consider the following very simplified example:
>
>   bool disable_something_for_test = false;
>   void function_being_tested() {
>     ...
>     if (disable_something_for_test) return;
>     ...
>   }
>
>   static void test_before(struct kunit *test)
>   {
>     disable_something_for_test = true;
>     function_being_tested();
>     /* oops, we forgot to reset it back to false */
>   }
>
>   static void test_after(struct kunit *test)
>   {
>     /* oops, now "fixing" test_before can cause test_after to fail! */
>     function_being_tested();
>   }
>
> Presented like this, the issues are obvious, but it gets a lot more
> complicated to track down as the amount of test setup and helper
> functions increases.
>
> Another use case is memory corruption. It might not be surfaced as a
> failure/crash in the test case or suite that caused it. I've noticed in
> kunit's own unit tests, the 3rd suite after might be the one to finally
> crash after an out-of-bounds write, for example.
>
> Example usage:
>
> Per suite:
> $ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --run_isolated=suite
> ...
> Starting KUnit Kernel (1/7)...
> ============================================================
> ======== [PASSED] kunit_executor_test ========
> ....
> Testing complete. 5 tests run. 0 failed. 0 crashed. 0 skipped.
> Starting KUnit Kernel (2/7)...
> ============================================================
> ======== [PASSED] kunit-try-catch-test ========
> ...
>
> Per test:
> $ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --run_isolated=test
> Starting KUnit Kernel (1/23)...
> ============================================================
> ======== [PASSED] kunit_executor_test ========
> [PASSED] parse_filter_test
> ============================================================
> Testing complete. 1 tests run. 0 failed. 0 crashed. 0 skipped.
> Starting KUnit Kernel (2/23)...
> ============================================================
> ======== [PASSED] kunit_executor_test ========
> [PASSED] filter_subsuite_test
> ...
>
> It works with filters as well:
> $ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --run_isolated=suite example
> ...
> Starting KUnit Kernel (1/1)...
> ============================================================
> ======== [PASSED] example ========
> ...
>
> It also handles test filters, '*.*skip*' runs these 3 tests:
>   kunit_status.kunit_status_mark_skipped_test
>   example.example_skip_test
>   example.example_mark_skipped_test
>
> Signed-off-by: Daniel Latypov <dlatypov@google.com>
> Reviewed-by: David Gow <davidgow@google.com>
> ---

Thanks. This is good. A part of me still would've preferred the TAP
header to have been altered, but it probably makes more sense to leave
that until after Rae's parser rework patch anyway, which has better
support for multiple possible TAP headers anyway.

I did find an issue when running this under qemu/i386: a timing
problem with interleaved lines. We could do something drastic, like
having a marker at the start of every line to identify which ones are
tests, but that does seem like overkill for a (hopefully) rare
problem. Just ignoring obviously invalid lines should do it. Futher
details below.

-- David

>  tools/testing/kunit/kunit.py           | 95 ++++++++++++++++++++------
>  tools/testing/kunit/kunit_tool_test.py | 40 +++++++++++
>  2 files changed, 114 insertions(+), 21 deletions(-)
>
> diff --git a/tools/testing/kunit/kunit.py b/tools/testing/kunit/kunit.py
> index 5e717594df5b..b9d63f558765 100755
> --- a/tools/testing/kunit/kunit.py
> +++ b/tools/testing/kunit/kunit.py
> @@ -16,7 +16,7 @@ assert sys.version_info >= (3, 7), "Python version is too old"
>
>  from collections import namedtuple
>  from enum import Enum, auto
> -from typing import Iterable
> +from typing import Iterable, List
>
>  import kunit_config
>  import kunit_json
> @@ -31,13 +31,13 @@ KunitBuildRequest = namedtuple('KunitBuildRequest',
>                                ['jobs', 'build_dir', 'alltests',
>                                 'make_options'])
>  KunitExecRequest = namedtuple('KunitExecRequest',
> -                              ['timeout', 'build_dir', 'alltests',
> -                               'filter_glob', 'kernel_args'])
> +                             ['timeout', 'build_dir', 'alltests',
> +                              'filter_glob', 'kernel_args', 'run_isolated'])
>  KunitParseRequest = namedtuple('KunitParseRequest',
>                                ['raw_output', 'build_dir', 'json'])
>  KunitRequest = namedtuple('KunitRequest', ['raw_output','timeout', 'jobs',
>                                            'build_dir', 'alltests', 'filter_glob',
> -                                          'kernel_args', 'json', 'make_options'])
> +                                          'kernel_args', 'run_isolated', 'json', 'make_options'])
>
>  KernelDirectoryPath = sys.argv[0].split('tools/testing/kunit/')[0]
>
> @@ -91,23 +91,68 @@ def build_tests(linux: kunit_kernel.LinuxSourceTree,
>                            'built kernel successfully',
>                            build_end - build_start)
>
> +def _list_tests(linux: kunit_kernel.LinuxSourceTree, request: KunitExecRequest) -> List[str]:
> +       args = ['kunit.action=list']
> +       if request.kernel_args:
> +               args.extend(request.kernel_args)
> +
> +       output = linux.run_kernel(args=args,
> +                          timeout=None if request.alltests else request.timeout,
> +                          filter_glob=request.filter_glob,
> +                          build_dir=request.build_dir)
> +       lines = kunit_parser.extract_tap_lines(output)
> +       # Hack! Drop the dummy TAP version header that the executor prints out.
> +       lines.pop()
> +       return list(lines)
> +
> +def _suites_from_test_list(tests: List[str]) -> List[str]:
> +       """Extracts all the suites from an ordered list of tests."""
> +       suites = []  # type: List[str]
> +       for t in tests:
> +               parts = t.split('.', maxsplit=2)
> +               if len(parts) != 2:
> +                       raise ValueError(f'internal KUnit error, test name should be of the form "<suite>.<test>", got "{t}"')

It turns out that this can trigger on some machines/architectures if
there are other lines of kernel output which either get interspersed
in the test list, or -- more likely -- between the test list and the
"Restarting System" line.

On i386, under qemu, I'm seeing this output:
$ qemu-system-x86_64 -nodefaults -m 1024 -kernel
.kunit/arch/x86/boot/bzImage -append 'kunit.action=list mem=1G
console=tty kunit_shutdown=halt console=ttyS0 kunit_shutdown=reboot'
-no-reboot -nographic -serial stdio
...
property-entry.pe_test_reference
random: fast init done
input: ImExPS/2 Generic Explorer Mouse as
/devices/platform/i8042/serio1/input/input2
reboot: Restarting system
reboot: machine restart

Which translates into the following kunit_tool error:
$ ./tools/testing/kunit/kunit.py run --run_isolated=suite --arch=i386
...
 File "./tools/testing/kunit/kunit.py", line 114, in _suites_from_test_list
   raise ValueError(f'internal KUnit error, test name should be of the
form "<suite>.<test>", got "{t}"')
ValueError: internal KUnit error, test name should be of the form
"<suite>.<test>", got "random: fast init done"


Could we maybe ignore entries of the incorrect form?


> +               suite, case = parts
> +               if not suites or suites[-1] != suite:
> +                       suites.append(suite)
> +       return suites
> +
> +
> +
>  def exec_tests(linux: kunit_kernel.LinuxSourceTree, request: KunitExecRequest,
>                parse_request: KunitParseRequest) -> KunitResult:
> -       kunit_parser.print_with_timestamp('Starting KUnit Kernel ...')
> -       test_start = time.time()
> -       run_result = linux.run_kernel(
> -               args=request.kernel_args,
> -               timeout=None if request.alltests else request.timeout,
> -               filter_glob=request.filter_glob,
> -               build_dir=request.build_dir)
> -
> -       result = parse_tests(parse_request, run_result)
> -
> -       # run_kernel() doesn't block on the kernel exiting.
> -       # That only happens after we get the last line of output from `run_result`.
> -       # So exec_time here actually contains parsing + execution time, which is fine.
> -       test_end = time.time()
> -       exec_time = test_end - test_start
> +       filter_globs = [request.filter_glob]
> +       if request.run_isolated:
> +               tests = _list_tests(linux, request)
> +               if request.run_isolated == 'test':
> +                       filter_globs = tests
> +               if request.run_isolated == 'suite':
> +                       filter_globs = _suites_from_test_list(tests)
> +                       # Apply the test-part of the user's glob, if present.
> +                       if '.' in request.filter_glob:
> +                               test_glob = request.filter_glob.split('.', maxsplit=2)[1]
> +                               filter_globs = [g + '.'+ test_glob for g in filter_globs]
> +
> +       overall_status = kunit_parser.TestStatus.SUCCESS
> +       exec_time = 0.0
> +       for i, filter_glob in enumerate(filter_globs):
> +               kunit_parser.print_with_timestamp('Starting KUnit Kernel ({}/{})...'.format(i+1, len(filter_globs)))
> +
> +               test_start = time.time()
> +               run_result = linux.run_kernel(
> +                       args=request.kernel_args,
> +                       timeout=None if request.alltests else request.timeout,
> +                       filter_glob=filter_glob,
> +                       build_dir=request.build_dir)
> +
> +               result = parse_tests(parse_request, run_result)
> +               # run_kernel() doesn't block on the kernel exiting.
> +               # That only happens after we get the last line of output from `run_result`.
> +               # So exec_time here actually contains parsing + execution time, which is fine.
> +               test_end = time.time()
> +               exec_time += test_end - test_start
> +
> +               overall_status = kunit_parser.max_status(overall_status, result.status)
>
>         return KunitResult(status=result.status, result=result.result, elapsed_time=exec_time)
>
> @@ -168,7 +213,7 @@ def run_tests(linux: kunit_kernel.LinuxSourceTree,
>
>         exec_request = KunitExecRequest(request.timeout, request.build_dir,
>                                  request.alltests, request.filter_glob,
> -                                request.kernel_args)
> +                                request.kernel_args, request.run_isolated)
>         parse_request = KunitParseRequest(request.raw_output,
>                                           request.build_dir,
>                                           request.json)
> @@ -252,6 +297,12 @@ def add_exec_opts(parser) -> None:
>         parser.add_argument('--kernel_args',
>                             help='Kernel command-line parameters. Maybe be repeated',
>                              action='append')
> +       parser.add_argument('--run_isolated', help='If set, boot the kernel for each '
> +                           'individual suite/test. This is can be useful for debugging '
> +                           'a non-hermetic test, one that might pass/fail based on '
> +                           'what ran before it.',
> +                           type=str,
> +                           choices=['suite', 'test']),
>
>  def add_parse_opts(parser) -> None:
>         parser.add_argument('--raw_output', help='If set don\'t format output from kernel. '
> @@ -325,6 +376,7 @@ def main(argv, linux=None):
>                                        cli_args.alltests,
>                                        cli_args.filter_glob,
>                                        cli_args.kernel_args,
> +                                      cli_args.run_isolated,
>                                        cli_args.json,
>                                        cli_args.make_options)
>                 result = run_tests(linux, request)
> @@ -380,7 +432,8 @@ def main(argv, linux=None):
>                                                 cli_args.build_dir,
>                                                 cli_args.alltests,
>                                                 cli_args.filter_glob,
> -                                               cli_args.kernel_args)
> +                                               cli_args.kernel_args,
> +                                               cli_args.run_isolated)
>                 parse_request = KunitParseRequest(cli_args.raw_output,
>                                                   cli_args.build_dir,
>                                                   cli_args.json)
> diff --git a/tools/testing/kunit/kunit_tool_test.py b/tools/testing/kunit/kunit_tool_test.py
> index 619c4554cbff..1ff35c08d2c8 100755
> --- a/tools/testing/kunit/kunit_tool_test.py
> +++ b/tools/testing/kunit/kunit_tool_test.py
> @@ -477,6 +477,46 @@ class KUnitMainTest(unittest.TestCase):
>                       args=['a=1','b=2'], build_dir='.kunit', filter_glob='', timeout=300)
>                 self.print_mock.assert_any_call(StrContains('Testing complete.'))
>
> +       def test_list_tests(self):
> +               want = ['suite.test1', 'suite.test2', 'suite2.test1']
> +               self.linux_source_mock.run_kernel.return_value = ['TAP version 14'] + want
> +
> +               got = kunit._list_tests(self.linux_source_mock,
> +                                    kunit.KunitExecRequest(300, '.kunit', False, 'suite*', None, 'suite'))
> +
> +               self.assertEqual(got, want)
> +               # Should respect the user's filter glob when listing tests.
> +               self.linux_source_mock.run_kernel.assert_called_once_with(
> +                       args=['kunit.action=list'], build_dir='.kunit', filter_glob='suite*', timeout=300)
> +
> +
> +       @mock.patch.object(kunit, '_list_tests')
> +       def test_run_isolated_by_suite(self, mock_tests):
> +               mock_tests.return_value = ['suite.test1', 'suite.test2', 'suite2.test1']
> +               kunit.main(['exec', '--run_isolated=suite', 'suite*.test*'], self.linux_source_mock)
> +
> +               # Should respect the user's filter glob when listing tests.
> +               mock_tests.assert_called_once_with(mock.ANY,
> +                                    kunit.KunitExecRequest(300, '.kunit', False, 'suite*.test*', None, 'suite'))
> +               self.linux_source_mock.run_kernel.assert_has_calls([
> +                       mock.call(args=None, build_dir='.kunit', filter_glob='suite.test*', timeout=300),
> +                       mock.call(args=None, build_dir='.kunit', filter_glob='suite2.test*', timeout=300),
> +               ])
> +
> +       @mock.patch.object(kunit, '_list_tests')
> +       def test_run_isolated_by_test(self, mock_tests):
> +               mock_tests.return_value = ['suite.test1', 'suite.test2', 'suite2.test1']
> +               kunit.main(['exec', '--run_isolated=test', 'suite*'], self.linux_source_mock)
> +
> +               # Should respect the user's filter glob when listing tests.
> +               mock_tests.assert_called_once_with(mock.ANY,
> +                                    kunit.KunitExecRequest(300, '.kunit', False, 'suite*', None, 'test'))
> +               self.linux_source_mock.run_kernel.assert_has_calls([
> +                       mock.call(args=None, build_dir='.kunit', filter_glob='suite.test1', timeout=300),
> +                       mock.call(args=None, build_dir='.kunit', filter_glob='suite.test2', timeout=300),
> +                       mock.call(args=None, build_dir='.kunit', filter_glob='suite2.test1', timeout=300),
> +               ])
> +
>
>  if __name__ == '__main__':
>         unittest.main()
> --
> 2.33.0.685.g46640cef36-goog
>

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

* Re: [PATCH v3 3/4] kunit: tool: actually track how long it took to run tests
  2021-09-29 19:54 ` [PATCH v3 3/4] kunit: tool: actually track how long it took to run tests Daniel Latypov
@ 2021-09-30  2:29   ` David Gow
  0 siblings, 0 replies; 8+ messages in thread
From: David Gow @ 2021-09-30  2:29 UTC (permalink / raw)
  To: Daniel Latypov
  Cc: Brendan Higgins, Linux Kernel Mailing List, KUnit Development,
	open list:KERNEL SELFTEST FRAMEWORK, Shuah Khan

On Thu, Sep 30, 2021 at 3:54 AM Daniel Latypov <dlatypov@google.com> wrote:
>
> This is a long standing bug in kunit tool.
> Since these files were added, run_kernel() has always yielded lines.
>
> That means, the call to run_kernel() returns before the kernel finishes
> executing tests, potentially before a single line of output is even
> produced.
>
> So code like this
>   time_start = time.time()
>   result = linux.run_kernel(...)
>   time_end = time.time()
>
> would only measure the time taken for python to give back the generator
> object.
>
> From a caller's perspective, the only way to know the kernel has exited
> is for us to consume all the output from the `result` generator object.
> Alternatively, we could change run_kernel() to try and do its own book
> keeping and return the total time, but that doesn't seem worth it.
>
> This change makes us record `time_end` after we're doing parsing all the
> output (which should mean we've consumed all of it, or errored out).
> That means we're including in the parsing time as well, but that should
> be quite small, and it's better than claiming it took 0s to run tests.
>
> Let's use this as an example:
> $ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit example
>
> Before:
> Elapsed time: 7.684s total, 0.001s configuring, 4.692s building, 0.000s running
>
> After:
> Elapsed time: 6.283s total, 0.001s configuring, 3.202s building, 3.079s running
>
> Signed-off-by: Daniel Latypov <dlatypov@google.com>
> ---

Thanks for looking into and fixing this: clearly I should've noticed
it before. :-)

Including the parsing time as well doesn't worry me: as you note, it
should be negligible.

Reviewed-by: David Gow <davidgow@google.com>

-- David

>  tools/testing/kunit/kunit.py | 8 +++++---
>  1 file changed, 5 insertions(+), 3 deletions(-)
>
> diff --git a/tools/testing/kunit/kunit.py b/tools/testing/kunit/kunit.py
> index 31eec9f6ecc3..5e717594df5b 100755
> --- a/tools/testing/kunit/kunit.py
> +++ b/tools/testing/kunit/kunit.py
> @@ -101,12 +101,14 @@ def exec_tests(linux: kunit_kernel.LinuxSourceTree, request: KunitExecRequest,
>                 filter_glob=request.filter_glob,
>                 build_dir=request.build_dir)
>
> +       result = parse_tests(parse_request, run_result)
> +
> +       # run_kernel() doesn't block on the kernel exiting.
> +       # That only happens after we get the last line of output from `run_result`.
> +       # So exec_time here actually contains parsing + execution time, which is fine.
>         test_end = time.time()
>         exec_time = test_end - test_start
>
> -       # Named tuples are immutable, so we rebuild them here manually
> -       result = parse_tests(parse_request, run_result)
> -
>         return KunitResult(status=result.status, result=result.result, elapsed_time=exec_time)
>
>  def parse_tests(request: KunitParseRequest, input_data: Iterable[str]) -> KunitResult:
> --
> 2.33.0.685.g46640cef36-goog
>

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

* Re: [PATCH v3 4/4] kunit: tool: support running each suite/test separately
  2021-09-30  2:27   ` David Gow
@ 2021-09-30 16:30     ` Daniel Latypov
  0 siblings, 0 replies; 8+ messages in thread
From: Daniel Latypov @ 2021-09-30 16:30 UTC (permalink / raw)
  To: David Gow
  Cc: Brendan Higgins, Linux Kernel Mailing List, KUnit Development,
	open list:KERNEL SELFTEST FRAMEWORK, Shuah Khan

On Wed, Sep 29, 2021 at 7:27 PM David Gow <davidgow@google.com> wrote:
>
> On Thu, Sep 30, 2021 at 3:54 AM Daniel Latypov <dlatypov@google.com> wrote:
> >
> > The new --run_isolated flag makes the tool boot the kernel once per
> > suite or test, preventing leftover state from one suite to impact the
> > other. This can be useful as a starting point to debugging test
> > hermeticity issues.
> >
> > Note: it takes a lot longer, so people should not use it normally.
> >
> > Consider the following very simplified example:
> >
> >   bool disable_something_for_test = false;
> >   void function_being_tested() {
> >     ...
> >     if (disable_something_for_test) return;
> >     ...
> >   }
> >
> >   static void test_before(struct kunit *test)
> >   {
> >     disable_something_for_test = true;
> >     function_being_tested();
> >     /* oops, we forgot to reset it back to false */
> >   }
> >
> >   static void test_after(struct kunit *test)
> >   {
> >     /* oops, now "fixing" test_before can cause test_after to fail! */
> >     function_being_tested();
> >   }
> >
> > Presented like this, the issues are obvious, but it gets a lot more
> > complicated to track down as the amount of test setup and helper
> > functions increases.
> >
> > Another use case is memory corruption. It might not be surfaced as a
> > failure/crash in the test case or suite that caused it. I've noticed in
> > kunit's own unit tests, the 3rd suite after might be the one to finally
> > crash after an out-of-bounds write, for example.
> >
> > Example usage:
> >
> > Per suite:
> > $ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --run_isolated=suite
> > ...
> > Starting KUnit Kernel (1/7)...
> > ============================================================
> > ======== [PASSED] kunit_executor_test ========
> > ....
> > Testing complete. 5 tests run. 0 failed. 0 crashed. 0 skipped.
> > Starting KUnit Kernel (2/7)...
> > ============================================================
> > ======== [PASSED] kunit-try-catch-test ========
> > ...
> >
> > Per test:
> > $ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --run_isolated=test
> > Starting KUnit Kernel (1/23)...
> > ============================================================
> > ======== [PASSED] kunit_executor_test ========
> > [PASSED] parse_filter_test
> > ============================================================
> > Testing complete. 1 tests run. 0 failed. 0 crashed. 0 skipped.
> > Starting KUnit Kernel (2/23)...
> > ============================================================
> > ======== [PASSED] kunit_executor_test ========
> > [PASSED] filter_subsuite_test
> > ...
> >
> > It works with filters as well:
> > $ ./tools/testing/kunit/kunit.py run --kunitconfig=lib/kunit --run_isolated=suite example
> > ...
> > Starting KUnit Kernel (1/1)...
> > ============================================================
> > ======== [PASSED] example ========
> > ...
> >
> > It also handles test filters, '*.*skip*' runs these 3 tests:
> >   kunit_status.kunit_status_mark_skipped_test
> >   example.example_skip_test
> >   example.example_mark_skipped_test
> >
> > Signed-off-by: Daniel Latypov <dlatypov@google.com>
> > Reviewed-by: David Gow <davidgow@google.com>
> > ---
>
> Thanks. This is good. A part of me still would've preferred the TAP
> header to have been altered, but it probably makes more sense to leave
> that until after Rae's parser rework patch anyway, which has better
> support for multiple possible TAP headers anyway.
>
> I did find an issue when running this under qemu/i386: a timing
> problem with interleaved lines. We could do something drastic, like
> having a marker at the start of every line to identify which ones are
> tests, but that does seem like overkill for a (hopefully) rare
> problem. Just ignoring obviously invalid lines should do it. Futher
> details below.
>
> -- David
>
> >  tools/testing/kunit/kunit.py           | 95 ++++++++++++++++++++------
> >  tools/testing/kunit/kunit_tool_test.py | 40 +++++++++++
> >  2 files changed, 114 insertions(+), 21 deletions(-)
> >
> > diff --git a/tools/testing/kunit/kunit.py b/tools/testing/kunit/kunit.py
> > index 5e717594df5b..b9d63f558765 100755
> > --- a/tools/testing/kunit/kunit.py
> > +++ b/tools/testing/kunit/kunit.py
> > @@ -16,7 +16,7 @@ assert sys.version_info >= (3, 7), "Python version is too old"
> >
> >  from collections import namedtuple
> >  from enum import Enum, auto
> > -from typing import Iterable
> > +from typing import Iterable, List
> >
> >  import kunit_config
> >  import kunit_json
> > @@ -31,13 +31,13 @@ KunitBuildRequest = namedtuple('KunitBuildRequest',
> >                                ['jobs', 'build_dir', 'alltests',
> >                                 'make_options'])
> >  KunitExecRequest = namedtuple('KunitExecRequest',
> > -                              ['timeout', 'build_dir', 'alltests',
> > -                               'filter_glob', 'kernel_args'])
> > +                             ['timeout', 'build_dir', 'alltests',
> > +                              'filter_glob', 'kernel_args', 'run_isolated'])
> >  KunitParseRequest = namedtuple('KunitParseRequest',
> >                                ['raw_output', 'build_dir', 'json'])
> >  KunitRequest = namedtuple('KunitRequest', ['raw_output','timeout', 'jobs',
> >                                            'build_dir', 'alltests', 'filter_glob',
> > -                                          'kernel_args', 'json', 'make_options'])
> > +                                          'kernel_args', 'run_isolated', 'json', 'make_options'])
> >
> >  KernelDirectoryPath = sys.argv[0].split('tools/testing/kunit/')[0]
> >
> > @@ -91,23 +91,68 @@ def build_tests(linux: kunit_kernel.LinuxSourceTree,
> >                            'built kernel successfully',
> >                            build_end - build_start)
> >
> > +def _list_tests(linux: kunit_kernel.LinuxSourceTree, request: KunitExecRequest) -> List[str]:
> > +       args = ['kunit.action=list']
> > +       if request.kernel_args:
> > +               args.extend(request.kernel_args)
> > +
> > +       output = linux.run_kernel(args=args,
> > +                          timeout=None if request.alltests else request.timeout,
> > +                          filter_glob=request.filter_glob,
> > +                          build_dir=request.build_dir)
> > +       lines = kunit_parser.extract_tap_lines(output)
> > +       # Hack! Drop the dummy TAP version header that the executor prints out.
> > +       lines.pop()
> > +       return list(lines)
> > +
> > +def _suites_from_test_list(tests: List[str]) -> List[str]:
> > +       """Extracts all the suites from an ordered list of tests."""
> > +       suites = []  # type: List[str]
> > +       for t in tests:
> > +               parts = t.split('.', maxsplit=2)
> > +               if len(parts) != 2:
> > +                       raise ValueError(f'internal KUnit error, test name should be of the form "<suite>.<test>", got "{t}"')
>
> It turns out that this can trigger on some machines/architectures if
> there are other lines of kernel output which either get interspersed
> in the test list, or -- more likely -- between the test list and the
> "Restarting System" line.
>
> On i386, under qemu, I'm seeing this output:
> $ qemu-system-x86_64 -nodefaults -m 1024 -kernel
> .kunit/arch/x86/boot/bzImage -append 'kunit.action=list mem=1G
> console=tty kunit_shutdown=halt console=ttyS0 kunit_shutdown=reboot'
> -no-reboot -nographic -serial stdio
> ...
> property-entry.pe_test_reference
> random: fast init done
> input: ImExPS/2 Generic Explorer Mouse as
> /devices/platform/i8042/serio1/input/input2
> reboot: Restarting system
> reboot: machine restart
>
> Which translates into the following kunit_tool error:
> $ ./tools/testing/kunit/kunit.py run --run_isolated=suite --arch=i386
> ...
>  File "./tools/testing/kunit/kunit.py", line 114, in _suites_from_test_list
>    raise ValueError(f'internal KUnit error, test name should be of the
> form "<suite>.<test>", got "{t}"')
> ValueError: internal KUnit error, test name should be of the form
> "<suite>.<test>", got "random: fast init done"
>
>
> Could we maybe ignore entries of the incorrect form?

I'm thinking we change _list_tests() above like
-       return list(lines)
+
+       # Filter out any extraneous non-test output that might have
gotten mixed in.
+       return [l for l in lines if re.match('^\w+\.\w+$', l)]

The problem with \w is that it doesn't match -.
So I'm thinking we maybe go with something very lax like
  '^[^\s.]+\.[^\s.]+$'

Since we don't have any requirements on the naming convention, I don't
know if we can be stricter.
Like, KUNIT_CASE() sorta enforces that test cases follow C identifier
naming rules, but users could always work around it fairly easily by
instantiating the struct directly.

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

end of thread, other threads:[~2021-09-30 16:31 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-09-29 19:54 [PATCH v3 0/3] kunit: allow running test suites/cases individually Daniel Latypov
2021-09-29 19:54 ` [PATCH v3 1/4] kunit: add 'kunit.action' param to allow listing out tests Daniel Latypov
2021-09-29 19:54 ` [PATCH v3 2/4] kunit: tool: factor exec + parse steps into a function Daniel Latypov
2021-09-29 19:54 ` [PATCH v3 3/4] kunit: tool: actually track how long it took to run tests Daniel Latypov
2021-09-30  2:29   ` David Gow
2021-09-29 19:54 ` [PATCH v3 4/4] kunit: tool: support running each suite/test separately Daniel Latypov
2021-09-30  2:27   ` David Gow
2021-09-30 16:30     ` Daniel Latypov

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).