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

From: Daniel Latypov
Date: Fri Oct 22 2021 - 18:29:40 EST

On Thu, Oct 21, 2021 at 11:16 PM David Gow <davidgow@xxxxxxxxxx> wrote:
>
> 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).

To be clear, I don't think we need to do anything about it at this moment.
Just noting that it might cause confusion (and if it causes enough
later on, then maybe we should revisit it).

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

Oops, muscle memory kicked in since I had just typed a Signed-off-by
recently....

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