Re: [PATCH 2/2] kunit: Report test parameter results as (K)TAP subtests

From: Daniel Latypov
Date: Thu Oct 21 2021 - 21:15:54 EST

On Wed, Oct 20, 2021 at 11:28 PM David Gow <davidgow@xxxxxxxxxx> wrote:
>
> Currently, the results for individial parameters in a parameterised test
> are simply output as (K)TAP diagnostic lines. However, the plan was
> always[1] to make these (K)TAP subtests when kunit_tool supported them.
>
> With [2], these are now supported. (v5 will print out an error about the
> missing plan line, but this can safely be ignored, and will hopefully be

Should this commit description be updated?

> changed). As a result, individual test parameter results are parsed,
> displayed in the formatted results, and counted for test statistics.

This works for me.

One concern I have for the future is if showing all the parameters by
default might become too verbose?
Should there eventually be a verbosity/test-level flag that controls
how deep we go?
We could elect to only print FAILED subtests after we hit the depth limit.

Testing this out with:
$ ./tools/testing/kunit/kunit.py --kunitconfig=fs/fat

Before:
[17:55:48] Starting KUnit Kernel (1/1)...
[17:55:48] ============================================================
[17:55:51] ================== fat_test (3 subtests) ===================
[17:55:51] [PASSED] fat_checksum_test
[17:55:51] [PASSED] fat_time_fat2unix_test
[17:55:51] [PASSED] fat_time_unix2fat_test
[17:55:51] ==================== [PASSED] fat_test =====================
[17:55:51] ============================================================
[17:55:51] Testing complete. Passed: 3, Failed: 0, Crashed: 0,
Skipped: 0, Errors: 0
[17:55:51] Elapsed time: 7.784s total, 0.001s configuring, 4.790s
building, 2.877s running

[17:56:22] Starting KUnit Kernel (1/1)...
[17:56:22] ============================================================
[17:56:25] ================== fat_test (3 subtests) ===================
[17:56:25] [PASSED] fat_checksum_test
[17:56:25] ================== fat_time_fat2unix_test ==================
[17:56:25] [PASSED] Earliest possible UTC (1980-01-01 00:00:00)
[17:56:25] [PASSED] Latest possible UTC (2107-12-31 23:59:58)
[17:56:25] [PASSED] Earliest possible (UTC-11) (== 1979-12-31 13:00:00 UTC)
[17:56:25] [PASSED] Latest possible (UTC+11) (== 2108-01-01 10:59:58 UTC)
[17:56:25] [PASSED] Leap Day / Year (1996-02-29 00:00:00)
[17:56:25] [PASSED] Year 2000 is leap year (2000-02-29 00:00:00)
[17:56:25] [PASSED] Year 2100 not leap year (2100-03-01 00:00:00)
[17:56:25] [PASSED] Leap year + timezone UTC+1 (== 2004-02-29 00:30:00 UTC)
[17:56:25] [PASSED] Leap year + timezone UTC-1 (== 2004-02-29 23:30:00 UTC)
[17:56:25] [PASSED] VFAT odd-second resolution (1999-12-31 23:59:59)
[17:56:25] [PASSED] VFAT 10ms resolution (1980-01-01 00:00:00:0010)
[17:56:25] ============= [PASSED] fat_time_fat2unix_test ==============
[17:56:25] ================== fat_time_unix2fat_test ==================
[17:56:25] [PASSED] Earliest possible UTC (1980-01-01 00:00:00)
[17:56:25] [PASSED] Latest possible UTC (2107-12-31 23:59:58)
[17:56:25] [PASSED] Earliest possible (UTC-11) (== 1979-12-31 13:00:00 UTC)
[17:56:25] [PASSED] Latest possible (UTC+11) (== 2108-01-01 10:59:58 UTC)
[17:56:25] [PASSED] Leap Day / Year (1996-02-29 00:00:00)
[17:56:25] [PASSED] Year 2000 is leap year (2000-02-29 00:00:00)
[17:56:25] [PASSED] Year 2100 not leap year (2100-03-01 00:00:00)
[17:56:25] [PASSED] Leap year + timezone UTC+1 (== 2004-02-29 00:30:00 UTC)
[17:56:25] [PASSED] Leap year + timezone UTC-1 (== 2004-02-29 23:30:00 UTC)
[17:56:25] [PASSED] VFAT odd-second resolution (1999-12-31 23:59:59)
[17:56:25] [PASSED] VFAT 10ms resolution (1980-01-01 00:00:00:0010)
[17:56:25] ============= [PASSED] fat_time_unix2fat_test ==============
[17:56:25] ==================== [PASSED] fat_test =====================
[17:56:25] ============================================================
[17:56:25] Testing complete. Passed: 23, Failed: 0, Crashed: 0,
Skipped: 0, Errors: 0
[17:56:25] Elapsed time: 7.733s total, 0.001s configuring, 4.740s
building, 2.915s running

Looks similar when run with --kunitconfig=fs/ext4.

This "inverted" nesting of PASSED looks a bit "wrong" at first.

[17:56:25] [PASSED] VFAT 10ms resolution (1980-01-01 00:00:00:0010)
[17:56:25] ============= [PASSED] fat_time_unix2fat_test ==============
[17:56:25] ==================== [PASSED] fat_test =====================

But I know it's so that we can show results as incrementally as
possible, so I'm fine with it.
(I imagine our users won't necessarily make that connection, however.)

>
> [1]: https://lore.kernel.org/linux-kselftest/CABVgOSnJAgWvTTABaF082LuYjAoAWzrBsyu9sT7x4GGMVsOD6Q@xxxxxxxxxxxxxx/
> [2]: https://lore.kernel.org/linux-kselftest/20211006001447.20919-1-dlatypov@xxxxxxxxxx/
>
> Signed-off-by: David Gow <davidgow@xxxxxxxxxx>

Signed-off-by: Daniel Latypov <dlatypov@xxxxxxxxxx>

> ---
>
> Note that this was previously posted as:
> https://lore.kernel.org/all/20211006071112.2206942-1-davidgow@xxxxxxxxxx/
>
> No changes have been made, save for a trivial rebase on the current
> kselftest/kunit branch.
>
> lib/kunit/test.c | 7 ++++---
> 1 file changed, 4 insertions(+), 3 deletions(-)
>
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index 3bd741e50a2d..85265f9a66a1 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -508,6 +508,8 @@ int kunit_run_tests(struct kunit_suite *suite)
> /* Get initial param. */
> param_desc[0] = '\0';
> test.param_value = test_case->generate_params(NULL, param_desc);
> + kunit_log(KERN_INFO, &test, KUNIT_SUBTEST_INDENT KUNIT_SUBTEST_INDENT
> + "# Subtest: %s", test_case->name);
> }
>
> do {
> @@ -520,9 +522,8 @@ int kunit_run_tests(struct kunit_suite *suite)
> }
>
> kunit_log(KERN_INFO, &test,
> - KUNIT_SUBTEST_INDENT
> - "# %s: %s %d - %s",
> - test_case->name,
> + KUNIT_SUBTEST_INDENT KUNIT_SUBTEST_INDENT
> + "%s %d - %s",
> kunit_status_to_ok_not_ok(test.status),
> test.param_index + 1, param_desc);
>
> --
> 2.33.0.1079.g6e70778dc9-goog
>