Re: [PATCH v2] kunit: Print test statistics on failure

From: Andy Shevchenko
Date: Wed Aug 04 2021 - 03:43:33 EST

+Cc: Rasmus

On Wed, Aug 4, 2021 at 8:08 AM David Gow <davidgow@xxxxxxxxxx> wrote:
>
> When a number of tests fail, it can be useful to get higher-level
> statistics of how many tests are failing (or how many parameters are
> failing in parameterised tests), and in what cases or suites. This is
> already done by some non-KUnit tests, so add support for automatically
> generating these for KUnit tests.
>
> This change adds a 'kunit.stats_enabled' switch which has three values:
> - 0: No stats are printed (current behaviour)
> - 1: Stats are printed only for tests/suites with more than one
> subtest (new default)
> - 2: Always print test statistics
>
> For parameterised tests, the summary line looks as follows:
> " # inode_test_xtimestamp_decoding: pass:16 fail:0 skip:0 total:16"
> For test suites, there are two lines looking like this:
> "# ext4_inode_test: pass:1 fail:0 skip:0 total:1"
> "# Totals: pass:16 fail:0 skip:0 total:16"
>
> The first line gives the number of direct subtests, the second "Totals"
> line is the accumulated sum of all tests and test parameters.
>
> This format is based on the one used by kselftest[1].
>
> [1]: https://elixir.bootlin.com/linux/latest/source/tools/testing/selftests/kselftest.h#L109
>
> Signed-off-by: David Gow <davidgow@xxxxxxxxxx>
> ---
>
> This is the long-awaited v2 of the test statistics patch:
> https://lore.kernel.org/linux-kselftest/20201211072319.533803-1-davidgow@xxxxxxxxxx/
>
> It updates the patch to apply on current mainline kernels, takes skipped
> tests into account, changes the output format to better match what
> kselftest uses, and addresses some of the comments from v1.
>
> Please let me know what you think, in particular:
> - Is this sufficient to assuage any worries about porting tests to
> KUnit?
> - Are we printing too many stats by default: for a lot of existing tests
> many of them are useless. I'm particuarly curious about the separate
> "Totals" line, versus the per-suite line -- is that useful? Should it
> only be printed when the totals differ?
> - Is the output format sufficiently legible for people and/or tools
> which may want to parse it?
>
> Cheers,
> -- David
>
> Changelog:
>
> Changes since v1:
> https://lore.kernel.org/linux-kselftest/20201211072319.533803-1-davidgow@xxxxxxxxxx/
> - Rework to use a new struct kunit_result_stats, with helper functions
> for adding results, accumulating them over nested structures, etc.
> - Support skipped tests, report them separately from failures and
> passes.
> - New output format to better match kselftest:
> - "pass:n fail:n skip:n total:n"
> - Changes to stats_enabled parameter:
> - Now a module parameter, with description
> - Default "1" option now prints even when no tests fail.
> - Improved parser fix which doesn't break crashed test detection.
>
> ---
> lib/kunit/test.c | 109 ++++++++++++++++++++++++++++
> tools/testing/kunit/kunit_parser.py | 2 +-
> 2 files changed, 110 insertions(+), 1 deletion(-)
>
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index d79ecb86ea57..f246b847024e 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -10,6 +10,7 @@
> #include <kunit/test-bug.h>
> #include <linux/kernel.h>
> #include <linux/kref.h>
> +#include <linux/moduleparam.h>
> #include <linux/sched/debug.h>
> #include <linux/sched.h>
>
> @@ -51,6 +52,51 @@ void __kunit_fail_current_test(const char *file, int line, const char *fmt, ...)
> EXPORT_SYMBOL_GPL(__kunit_fail_current_test);
> #endif
>
> +/*
> + * KUnit statistic mode:
> + * 0 - disabled
> + * 1 - only when there is more than one subtest
> + * 2 - enabled
> + */
> +static int kunit_stats_enabled = 1;
> +module_param_named(stats_enabled, kunit_stats_enabled, int, 0644);
> +MODULE_PARM_DESC(stats_enabled,
> + "Print test stats: never (0), only for multiple subtests (1), or always (2)");
> +
> +struct kunit_result_stats {
> + unsigned long passed;
> + unsigned long skipped;
> + unsigned long failed;
> + unsigned long total;
> +};
> +
> +static bool kunit_should_print_stats(struct kunit_result_stats stats)
> +{
> + if (kunit_stats_enabled == 0)
> + return false;
> +
> + if (kunit_stats_enabled == 2)
> + return true;
> +
> + return (stats.total > 1);
> +}
> +
> +static void kunit_print_test_stats(struct kunit *test,
> + struct kunit_result_stats stats)
> +{
> + if (!kunit_should_print_stats(stats))
> + return;
> +
> + kunit_log(KERN_INFO, test,
> + KUNIT_SUBTEST_INDENT
> + "# %s: pass:%lu fail:%lu skip:%lu total:%lu",
> + test->name,
> + stats.passed,
> + stats.failed,
> + stats.skipped,
> + stats.total);
> +}
> +
> /*
> * Append formatted message to log, size of which is limited to
> * KUNIT_LOG_SIZE bytes (including null terminating byte).
> @@ -393,15 +439,69 @@ static void kunit_run_case_catch_errors(struct kunit_suite *suite,
> test_case->status = KUNIT_SUCCESS;
> }
>
> +static void kunit_print_suite_stats(struct kunit_suite *suite,
> + struct kunit_result_stats suite_stats,
> + struct kunit_result_stats param_stats)
> +{
> + if (kunit_should_print_stats(suite_stats)) {
> + kunit_log(KERN_INFO, suite,
> + "# %s: pass:%lu fail:%lu skip:%lu total:%lu",
> + suite->name,
> + suite_stats.passed,
> + suite_stats.failed,
> + suite_stats.skipped,
> + suite_stats.total);
> + }
> +
> + if (kunit_should_print_stats(param_stats)) {
> + kunit_log(KERN_INFO, suite,
> + "# Totals: pass:%lu fail:%lu skip:%lu total:%lu",
> + param_stats.passed,
> + param_stats.failed,
> + param_stats.skipped,
> + param_stats.total);
> + }
> +}
> +
> +static void kunit_update_stats(struct kunit_result_stats *stats,
> + enum kunit_status status)
> +{
> + switch (status) {
> + case KUNIT_SUCCESS:
> + stats->passed++;
> + break;
> + case KUNIT_SKIPPED:
> + stats->skipped++;
> + break;
> + case KUNIT_FAILURE:
> + stats->failed++;
> + break;
> + }
> +
> + stats->total++;
> +}
> +
> +static void kunit_accumulate_stats(struct kunit_result_stats *total,
> + struct kunit_result_stats add)
> +{
> + total->passed += add.passed;
> + total->skipped += add.skipped;
> + total->failed += add.failed;
> + total->total += add.total;
> +}
> +
> int kunit_run_tests(struct kunit_suite *suite)
> {
> char param_desc[KUNIT_PARAM_DESC_SIZE];
> struct kunit_case *test_case;
> + struct kunit_result_stats suite_stats = { 0 };
> + struct kunit_result_stats total_stats = { 0 };
>
> kunit_print_subtest_start(suite);
>
> kunit_suite_for_each_test_case(suite, test_case) {
> struct kunit test = { .param_value = NULL, .param_index = 0 };
> + struct kunit_result_stats param_stats = { 0 };
> test_case->status = KUNIT_SKIPPED;
>
> if (test_case->generate_params) {
> @@ -431,14 +531,23 @@ int kunit_run_tests(struct kunit_suite *suite)
> test.param_value = test_case->generate_params(test.param_value, param_desc);
> test.param_index++;
> }
> +
> + kunit_update_stats(&param_stats, test.status);
> +
> } while (test.param_value);
>
> + kunit_print_test_stats(&test, param_stats);
> +
> kunit_print_ok_not_ok(&test, true, test_case->status,
> kunit_test_case_num(suite, test_case),
> test_case->name,
> test.status_comment);
> +
> + kunit_update_stats(&suite_stats, test_case->status);
> + kunit_accumulate_stats(&total_stats, param_stats);
> }
>
> + kunit_print_suite_stats(suite, suite_stats, total_stats);
> kunit_print_subtest_end(suite);
>
> return 0;
> diff --git a/tools/testing/kunit/kunit_parser.py b/tools/testing/kunit/kunit_parser.py
> index b88db3f51dc5..c699f778da06 100644
> --- a/tools/testing/kunit/kunit_parser.py
> +++ b/tools/testing/kunit/kunit_parser.py
> @@ -137,7 +137,7 @@ def print_log(log) -> None:
> for m in log:
> print_with_timestamp(m)
>
> -TAP_ENTRIES = re.compile(r'^(TAP|[\s]*ok|[\s]*not ok|[\s]*[0-9]+\.\.[0-9]+|[\s]*#).*$')
> +TAP_ENTRIES = re.compile(r'^(TAP|[\s]*ok|[\s]*not ok|[\s]*[0-9]+\.\.[0-9]+|[\s]*# (Subtest:|.*: kunit test case crashed!)).*$')
>
> def consume_non_diagnostic(lines: LineStream) -> None:
> while lines and not TAP_ENTRIES.match(lines.peek()):
> --
> 2.32.0.554.ge1b32706d8-goog
>


--
With Best Regards,
Andy Shevchenko