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

[David Gow]

On Fri, Oct 22, 2021 at 9:15 AM Daniel Latypov <dlatypov@xxxxxxxxxx> wrote:
>
> 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?
>

Whoops, yup. I didn't want to change anything without making this a
v2, but I'll definitely update it now.

> > 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.

Totally agree with this. A --depth option is definitely going to
become necessary here, and I think that printing FAILED subtests after
that limit is sensible default behaviour for it.

>
> 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.)
>

Yeah, this is definitely something for which there's no "perfect" way
of handling it. The fact that the number of '=' signs is based on the
length of the name means that even that might not look consistent.
I'm sure there are things we could experiment with to make this
clearer, e.g. indenting or swapping out the '=' for '-' on subtests
(though there's definitely a limit to how deep we could go with
something like that).

> >
> > [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>
>

(Was this supposed to be a Tested-by or Reviewed-by or something?)

> > ---
> >
> > 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
> >