linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH v2] kunit: Print test statistics on failure
@ 2021-08-04  5:08 David Gow
  2021-08-04  7:42 ` Andy Shevchenko
                   ` (2 more replies)
  0 siblings, 3 replies; 5+ messages in thread
From: David Gow @ 2021-08-04  5:08 UTC (permalink / raw)
  To: Brendan Higgins, Shuah Khan, Andy Shevchenko
  Cc: David Gow, Daniel Latypov, Rae Moar, kunit-dev, linux-kselftest,
	linux-kernel

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@google.com>
---

This is the long-awaited v2 of the test statistics patch:
https://lore.kernel.org/linux-kselftest/20201211072319.533803-1-davidgow@google.com/

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@google.com/
- 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


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

* Re: [PATCH v2] kunit: Print test statistics on failure
  2021-08-04  5:08 [PATCH v2] kunit: Print test statistics on failure David Gow
@ 2021-08-04  7:42 ` Andy Shevchenko
  2021-08-04 18:39 ` Daniel Latypov
  2021-08-05 18:14 ` Brendan Higgins
  2 siblings, 0 replies; 5+ messages in thread
From: Andy Shevchenko @ 2021-08-04  7:42 UTC (permalink / raw)
  To: David Gow, Rasmus Villemoes
  Cc: Brendan Higgins, Shuah Khan, Daniel Latypov, Rae Moar,
	KUnit Development, open list:KERNEL SELFTEST FRAMEWORK,
	Linux Kernel Mailing List

+Cc: Rasmus

On Wed, Aug 4, 2021 at 8:08 AM David Gow <davidgow@google.com> 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@google.com>
> ---
>
> This is the long-awaited v2 of the test statistics patch:
> https://lore.kernel.org/linux-kselftest/20201211072319.533803-1-davidgow@google.com/
>
> 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@google.com/
> - 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

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

* Re: [PATCH v2] kunit: Print test statistics on failure
  2021-08-04  5:08 [PATCH v2] kunit: Print test statistics on failure David Gow
  2021-08-04  7:42 ` Andy Shevchenko
@ 2021-08-04 18:39 ` Daniel Latypov
  2021-08-05 18:14 ` Brendan Higgins
  2 siblings, 0 replies; 5+ messages in thread
From: Daniel Latypov @ 2021-08-04 18:39 UTC (permalink / raw)
  To: David Gow
  Cc: Brendan Higgins, Shuah Khan, Andy Shevchenko, Rae Moar,
	kunit-dev, linux-kselftest, linux-kernel

On Tue, Aug 3, 2021 at 10:08 PM David Gow <davidgow@google.com> 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"

To clarify, this doesn't show up in `kunit.py run` unless you pass --raw_output.
So this is more aimed at people running tests via modules.

In that case, it seems more acceptable to have a global knob
(kunit.stats_enabled) for turning this on, and also that the default
is changing.

>
> 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@google.com>
> ---
>
> This is the long-awaited v2 of the test statistics patch:
> https://lore.kernel.org/linux-kselftest/20201211072319.533803-1-davidgow@google.com/
>
> 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@google.com/
> - 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
>

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

* Re: [PATCH v2] kunit: Print test statistics on failure
  2021-08-04  5:08 [PATCH v2] kunit: Print test statistics on failure David Gow
  2021-08-04  7:42 ` Andy Shevchenko
  2021-08-04 18:39 ` Daniel Latypov
@ 2021-08-05 18:14 ` Brendan Higgins
  2021-08-13  5:41   ` David Gow
  2 siblings, 1 reply; 5+ messages in thread
From: Brendan Higgins @ 2021-08-05 18:14 UTC (permalink / raw)
  To: David Gow
  Cc: Shuah Khan, Andy Shevchenko, Daniel Latypov, Rae Moar, kunit-dev,
	linux-kselftest, linux-kernel

On Tue, Aug 3, 2021 at 10:08 PM David Gow <davidgow@google.com> 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@google.com>

This looks great, David!

My only suggestion, can you maybe provide a sample of the TAP output
with your change running on the thread? I think it looks great, but I
imagine that it has the potential of being more interesting to people
other than you, Daniel, and myself rather than the actual code change.
(To be clear, I think the summary and the code both look good, IMO.)

Reviewed-by: Brendan Higgins <brendanhiggins@google.com>

Cheers!

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

* Re: [PATCH v2] kunit: Print test statistics on failure
  2021-08-05 18:14 ` Brendan Higgins
@ 2021-08-13  5:41   ` David Gow
  0 siblings, 0 replies; 5+ messages in thread
From: David Gow @ 2021-08-13  5:41 UTC (permalink / raw)
  To: Brendan Higgins
  Cc: Shuah Khan, Andy Shevchenko, Daniel Latypov, Rae Moar,
	KUnit Development, open list:KERNEL SELFTEST FRAMEWORK,
	Linux Kernel Mailing List

On Fri, Aug 6, 2021 at 2:15 AM 'Brendan Higgins' via KUnit Development
<kunit-dev@googlegroups.com> wrote:
>
> On Tue, Aug 3, 2021 at 10:08 PM David Gow <davidgow@google.com> 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@google.com>
>
> This looks great, David!
>
> My only suggestion, can you maybe provide a sample of the TAP output
> with your change running on the thread? I think it looks great, but I
> imagine that it has the potential of being more interesting to people
> other than you, Daniel, and myself rather than the actual code change.
> (To be clear, I think the summary and the code both look good, IMO.)

Sure. The lines in the commit description I think cover the actual
change pretty well:

"    # inode_test_xtimestamp_decoding: pass:16 fail:0 skip:0 total:16"

"# ext4_inode_test: pass:1 fail:0 skip:0 total:1"
"# Totals: pass:16 fail:0 skip:0 total:16"

Nevertheless, here's the complete output of the 'example' and
'rational' suites, which should give a more complete overview. (This
is with the default configuration of only printing out lines where the
number of subtests is >1)

TAP version 14
1..2
   # Subtest: example
   1..3
   # example_simple_test: initializing
   ok 1 - example_simple_test
   # example_skip_test: initializing
   # example_skip_test: You should not see a line below.
   ok 2 - example_skip_test # SKIP this test should be skipped
   # example_mark_skipped_test: initializing
   # example_mark_skipped_test: You should see a line below.
   # example_mark_skipped_test: You should see this line.
   ok 3 - example_mark_skipped_test # SKIP this test should be skipped
# example: pass:1 fail:0 skip:2 total:3
# Totals: pass:1 fail:0 skip:2 total:3
ok 1 - example
   # Subtest: rational
   1..1
   # rational_test: ok 1 - Exceeds bounds, semi-convergent term > 1/2 last term
   # rational_test: ok 2 - Exceeds bounds, semi-convergent term < 1/2 last term
   # rational_test: ok 3 - Closest to zero
   # rational_test: ok 4 - Closest to smallest non-zero
   # rational_test: ok 5 - Use convergent
   # rational_test: ok 6 - Exact answer
   # rational_test: ok 7 - Semiconvergent, numerator limit
   # rational_test: ok 8 - Semiconvergent, denominator limit
   # rational_test: pass:8 fail:0 skip:0 total:8
   ok 1 - rational_test
# Totals: pass:8 fail:0 skip:0 total:8
ok 2 - rational

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

end of thread, other threads:[~2021-08-13  5:41 UTC | newest]

Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-08-04  5:08 [PATCH v2] kunit: Print test statistics on failure David Gow
2021-08-04  7:42 ` Andy Shevchenko
2021-08-04 18:39 ` Daniel Latypov
2021-08-05 18:14 ` Brendan Higgins
2021-08-13  5:41   ` David Gow

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