2020-12-11 12:13:42

by David Gow

[permalink] [raw]
Subject: [PATCH] kunit: Print test statistics on failure

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
subtests, and at least one failure (new default)
- 2: Always print test statistics

For parameterised tests, the summary line looks as follows:
" # inode_test_xtimestamp_decoding: 0 / 16 test parameters failed"
For test suites, it looks like this:
"# ext4_inode_test: (0 / 1) tests failed (0 / 16 test parameters)"

kunit_tool is also updated to correctly ignore diagnostic lines, so that
these statistics do not prevent the result from parsing.

Signed-off-by: David Gow <[email protected]>
---

This is largely a follow-up to the discussion here:
https://lore.kernel.org/linux-kselftest/CABVgOSmy4n_LGwDS7yWfoLftcQzxv6S+iXx9Y=OPcgG2gu0z1w@mail.gmail.com/T/#t

Does this seem like a sensible addition?

Cheers,
-- David

lib/kunit/test.c | 71 +++++++++++++++++++++++++++++
tools/testing/kunit/kunit_parser.py | 2 +-
2 files changed, 72 insertions(+), 1 deletion(-)

diff --git a/lib/kunit/test.c b/lib/kunit/test.c
index ec9494e914ef..711e269366a7 100644
--- a/lib/kunit/test.c
+++ b/lib/kunit/test.c
@@ -9,6 +9,7 @@
#include <kunit/test.h>
#include <linux/kernel.h>
#include <linux/kref.h>
+#include <linux/moduleparam.h>
#include <linux/sched/debug.h>
#include <linux/sched.h>

@@ -16,6 +17,40 @@
#include "string-stream.h"
#include "try-catch-impl.h"

+/*
+ * KUnit statistic mode:
+ * 0 - disabled
+ * 1 - only when there is at least one failure, and more than one subtest
+ * 2 - enabled
+ */
+static int kunit_stats_enabled = 1;
+core_param(kunit_stats_enabled, kunit_stats_enabled, int, 0644);
+
+static bool kunit_should_print_stats(int num_failures, int num_subtests)
+{
+ if (kunit_stats_enabled == 0)
+ return false;
+
+ if (kunit_stats_enabled == 2)
+ return true;
+
+ return (num_failures > 0 && num_subtests > 1);
+}
+
+static void kunit_print_test_stats(struct kunit *test,
+ size_t num_failures, size_t num_subtests)
+{
+ if (!kunit_should_print_stats(num_failures, num_subtests))
+ return;
+
+ kunit_log(KERN_INFO, test,
+ KUNIT_SUBTEST_INDENT
+ "# %s: %lu / %lu test parameters failed",
+ test->name,
+ num_failures,
+ num_subtests);
+}
+
/*
* Append formatted message to log, size of which is limited to
* KUNIT_LOG_SIZE bytes (including null terminating byte).
@@ -346,15 +381,37 @@ static void kunit_run_case_catch_errors(struct kunit_suite *suite,
test_case->success = test->success;
}

+static void kunit_print_suite_stats(struct kunit_suite *suite,
+ size_t num_failures,
+ size_t total_param_failures,
+ size_t total_params)
+{
+ size_t num_cases = kunit_suite_num_test_cases(suite);
+
+ if (!kunit_should_print_stats(num_failures, num_cases))
+ return;
+
+ kunit_log(KERN_INFO, suite,
+ "# %s: (%lu / %lu) tests failed (%lu / %lu test parameters)",
+ suite->name,
+ num_failures,
+ num_cases,
+ total_param_failures,
+ total_params);
+}
+
int kunit_run_tests(struct kunit_suite *suite)
{
char param_desc[KUNIT_PARAM_DESC_SIZE];
struct kunit_case *test_case;
+ size_t num_suite_failures = 0;
+ size_t total_param_failures = 0, total_params = 0;

kunit_print_subtest_start(suite);

kunit_suite_for_each_test_case(suite, test_case) {
struct kunit test = { .param_value = NULL, .param_index = 0 };
+ size_t num_params = 0, num_failures = 0;
bool test_success = true;

if (test_case->generate_params) {
@@ -385,13 +442,27 @@ int kunit_run_tests(struct kunit_suite *suite)
test.param_value = test_case->generate_params(test.param_value, param_desc);
test.param_index++;
}
+
+ if (!test.success)
+ num_failures++;
+ num_params++;
+
} while (test.param_value);

+ kunit_print_test_stats(&test, num_failures, num_params);
+
kunit_print_ok_not_ok(&test, true, test_success,
kunit_test_case_num(suite, test_case),
test_case->name);
+
+ if (!test_success)
+ num_suite_failures++;
+ total_params += num_params;
+ total_param_failures += num_failures;
}

+ kunit_print_suite_stats(suite, num_suite_failures,
+ total_param_failures, total_params);
kunit_print_subtest_end(suite);

return 0;
diff --git a/tools/testing/kunit/kunit_parser.py b/tools/testing/kunit/kunit_parser.py
index 6614ec4d0898..88ee2b2668ad 100644
--- a/tools/testing/kunit/kunit_parser.py
+++ b/tools/testing/kunit/kunit_parser.py
@@ -95,7 +95,7 @@ def print_log(log):
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:).*$')

def consume_non_diagnositic(lines: List[str]) -> None:
while lines and not TAP_ENTRIES.match(lines[0]):

base-commit: 5f6b99d0287de2c2d0b5e7abcb0092d553ad804a
--
2.29.2.576.ga3fc446d84-goog


2020-12-13 01:30:46

by kernel test robot

[permalink] [raw]
Subject: Re: [PATCH] kunit: Print test statistics on failure

Hi David,

I love your patch! Perhaps something to improve:

[auto build test WARNING on 5f6b99d0287de2c2d0b5e7abcb0092d553ad804a]

url: https://github.com/0day-ci/linux/commits/David-Gow/kunit-Print-test-statistics-on-failure/20201211-153009
base: 5f6b99d0287de2c2d0b5e7abcb0092d553ad804a
config: arc-randconfig-r006-20201210 (attached as .config)
compiler: arceb-elf-gcc (GCC) 9.3.0
reproduce (this is a W=1 build):
wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
chmod +x ~/bin/make.cross
# https://github.com/0day-ci/linux/commit/2bdf1b55a1b3673a1a02f71457fc52b497fc7223
git remote add linux-review https://github.com/0day-ci/linux
git fetch --no-tags linux-review David-Gow/kunit-Print-test-statistics-on-failure/20201211-153009
git checkout 2bdf1b55a1b3673a1a02f71457fc52b497fc7223
# save the attached .config to linux build tree
COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-9.3.0 make.cross ARCH=arc

If you fix the issue, kindly add following tag as appropriate
Reported-by: kernel test robot <[email protected]>

All warnings (new ones prefixed by >>):

In file included from lib/kunit/test.c:9:
lib/kunit/test.c: In function 'kunit_print_test_stats':
>> include/linux/kern_levels.h:5:18: warning: format '%lu' expects argument of type 'long unsigned int', but argument 3 has type 'size_t' {aka 'unsigned int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
include/kunit/test.h:621:10: note: in definition of macro 'kunit_log'
621 | printk(lvl fmt, ##__VA_ARGS__); \
| ^~~
include/linux/kern_levels.h:14:19: note: in expansion of macro 'KERN_SOH'
14 | #define KERN_INFO KERN_SOH "6" /* informational */
| ^~~~~~~~
lib/kunit/test.c:46:12: note: in expansion of macro 'KERN_INFO'
46 | kunit_log(KERN_INFO, test,
| ^~~~~~~~~
lib/kunit/test.c:48:14: note: format string is defined here
48 | "# %s: %lu / %lu test parameters failed",
| ~~^
| |
| long unsigned int
| %u
In file included from lib/kunit/test.c:9:
include/linux/kern_levels.h:5:18: warning: format '%lu' expects argument of type 'long unsigned int', but argument 4 has type 'size_t' {aka 'unsigned int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
include/kunit/test.h:621:10: note: in definition of macro 'kunit_log'
621 | printk(lvl fmt, ##__VA_ARGS__); \
| ^~~
include/linux/kern_levels.h:14:19: note: in expansion of macro 'KERN_SOH'
14 | #define KERN_INFO KERN_SOH "6" /* informational */
| ^~~~~~~~
lib/kunit/test.c:46:12: note: in expansion of macro 'KERN_INFO'
46 | kunit_log(KERN_INFO, test,
| ^~~~~~~~~
lib/kunit/test.c:48:20: note: format string is defined here
48 | "# %s: %lu / %lu test parameters failed",
| ~~^
| |
| long unsigned int
| %u
lib/kunit/test.c: In function 'kunit_log_append':
lib/kunit/test.c:72:2: warning: function 'kunit_log_append' might be a candidate for 'gnu_printf' format attribute [-Wsuggest-attribute=format]
72 | vsnprintf(line, sizeof(line), fmt, args);
| ^~~~~~~~~
In file included from lib/kunit/test.c:9:
lib/kunit/test.c: In function 'kunit_print_suite_stats':
>> include/linux/kern_levels.h:5:18: warning: format '%lu' expects argument of type 'long unsigned int', but argument 3 has type 'size_t' {aka 'unsigned int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
include/kunit/test.h:621:10: note: in definition of macro 'kunit_log'
621 | printk(lvl fmt, ##__VA_ARGS__); \
| ^~~
include/linux/kern_levels.h:14:19: note: in expansion of macro 'KERN_SOH'
14 | #define KERN_INFO KERN_SOH "6" /* informational */
| ^~~~~~~~
lib/kunit/test.c:394:12: note: in expansion of macro 'KERN_INFO'
394 | kunit_log(KERN_INFO, suite,
| ^~~~~~~~~
lib/kunit/test.c:395:15: note: format string is defined here
395 | "# %s: (%lu / %lu) tests failed (%lu / %lu test parameters)",
| ~~^
| |
| long unsigned int
| %u
In file included from lib/kunit/test.c:9:
include/linux/kern_levels.h:5:18: warning: format '%lu' expects argument of type 'long unsigned int', but argument 4 has type 'size_t' {aka 'unsigned int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
include/kunit/test.h:621:10: note: in definition of macro 'kunit_log'
621 | printk(lvl fmt, ##__VA_ARGS__); \
| ^~~
include/linux/kern_levels.h:14:19: note: in expansion of macro 'KERN_SOH'
14 | #define KERN_INFO KERN_SOH "6" /* informational */
| ^~~~~~~~
lib/kunit/test.c:394:12: note: in expansion of macro 'KERN_INFO'
394 | kunit_log(KERN_INFO, suite,
| ^~~~~~~~~
lib/kunit/test.c:395:21: note: format string is defined here
395 | "# %s: (%lu / %lu) tests failed (%lu / %lu test parameters)",
| ~~^
| |
| long unsigned int
| %u
In file included from lib/kunit/test.c:9:
include/linux/kern_levels.h:5:18: warning: format '%lu' expects argument of type 'long unsigned int', but argument 5 has type 'size_t' {aka 'unsigned int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
include/kunit/test.h:621:10: note: in definition of macro 'kunit_log'
621 | printk(lvl fmt, ##__VA_ARGS__); \
| ^~~
include/linux/kern_levels.h:14:19: note: in expansion of macro 'KERN_SOH'
14 | #define KERN_INFO KERN_SOH "6" /* informational */
| ^~~~~~~~
lib/kunit/test.c:394:12: note: in expansion of macro 'KERN_INFO'
394 | kunit_log(KERN_INFO, suite,
| ^~~~~~~~~
lib/kunit/test.c:395:40: note: format string is defined here
395 | "# %s: (%lu / %lu) tests failed (%lu / %lu test parameters)",
| ~~^
| |
| long unsigned int
| %u
In file included from lib/kunit/test.c:9:
include/linux/kern_levels.h:5:18: warning: format '%lu' expects argument of type 'long unsigned int', but argument 6 has type 'size_t' {aka 'unsigned int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
include/kunit/test.h:621:10: note: in definition of macro 'kunit_log'
621 | printk(lvl fmt, ##__VA_ARGS__); \
| ^~~
include/linux/kern_levels.h:14:19: note: in expansion of macro 'KERN_SOH'
14 | #define KERN_INFO KERN_SOH "6" /* informational */
| ^~~~~~~~
lib/kunit/test.c:394:12: note: in expansion of macro 'KERN_INFO'
394 | kunit_log(KERN_INFO, suite,
| ^~~~~~~~~
lib/kunit/test.c:395:46: note: format string is defined here
395 | "# %s: (%lu / %lu) tests failed (%lu / %lu test parameters)",
| ~~^
| |
| long unsigned int
| %u

vim +5 include/linux/kern_levels.h

314ba3520e513a Joe Perches 2012-07-30 4
04d2c8c83d0e3a Joe Perches 2012-07-30 @5 #define KERN_SOH "\001" /* ASCII Start Of Header */
04d2c8c83d0e3a Joe Perches 2012-07-30 6 #define KERN_SOH_ASCII '\001'
04d2c8c83d0e3a Joe Perches 2012-07-30 7

---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/[email protected]


Attachments:
(No filename) (8.41 kB)
.config.gz (31.35 kB)
Download all attachments

2020-12-13 02:45:25

by kernel test robot

[permalink] [raw]
Subject: Re: [PATCH] kunit: Print test statistics on failure

Hi David,

I love your patch! Yet something to improve:

[auto build test ERROR on 5f6b99d0287de2c2d0b5e7abcb0092d553ad804a]

url: https://github.com/0day-ci/linux/commits/David-Gow/kunit-Print-test-statistics-on-failure/20201211-153009
base: 5f6b99d0287de2c2d0b5e7abcb0092d553ad804a
config: c6x-randconfig-r004-20201210 (attached as .config)
compiler: c6x-elf-gcc (GCC) 9.3.0
reproduce (this is a W=1 build):
wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
chmod +x ~/bin/make.cross
# https://github.com/0day-ci/linux/commit/2bdf1b55a1b3673a1a02f71457fc52b497fc7223
git remote add linux-review https://github.com/0day-ci/linux
git fetch --no-tags linux-review David-Gow/kunit-Print-test-statistics-on-failure/20201211-153009
git checkout 2bdf1b55a1b3673a1a02f71457fc52b497fc7223
# save the attached .config to linux build tree
COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-9.3.0 make.cross ARCH=c6x

If you fix the issue, kindly add following tag as appropriate
Reported-by: kernel test robot <[email protected]>

All errors (new ones prefixed by >>):

>> lib/kunit/test.c:27:53: error: expected ')' before 'int'
27 | core_param(kunit_stats_enabled, kunit_stats_enabled, int, 0644);
| ^~~~
| )
In file included from lib/kunit/test.c:9:
lib/kunit/test.c: In function 'kunit_print_test_stats':
include/linux/kern_levels.h:5:18: warning: format '%lu' expects argument of type 'long unsigned int', but argument 3 has type 'size_t' {aka 'unsigned int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
include/kunit/test.h:621:10: note: in definition of macro 'kunit_log'
621 | printk(lvl fmt, ##__VA_ARGS__); \
| ^~~
include/linux/kern_levels.h:14:19: note: in expansion of macro 'KERN_SOH'
14 | #define KERN_INFO KERN_SOH "6" /* informational */
| ^~~~~~~~
lib/kunit/test.c:46:12: note: in expansion of macro 'KERN_INFO'
46 | kunit_log(KERN_INFO, test,
| ^~~~~~~~~
lib/kunit/test.c:48:14: note: format string is defined here
48 | "# %s: %lu / %lu test parameters failed",
| ~~^
| |
| long unsigned int
| %u
In file included from lib/kunit/test.c:9:
include/linux/kern_levels.h:5:18: warning: format '%lu' expects argument of type 'long unsigned int', but argument 4 has type 'size_t' {aka 'unsigned int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
include/kunit/test.h:621:10: note: in definition of macro 'kunit_log'
621 | printk(lvl fmt, ##__VA_ARGS__); \
| ^~~
include/linux/kern_levels.h:14:19: note: in expansion of macro 'KERN_SOH'
14 | #define KERN_INFO KERN_SOH "6" /* informational */
| ^~~~~~~~
lib/kunit/test.c:46:12: note: in expansion of macro 'KERN_INFO'
46 | kunit_log(KERN_INFO, test,
| ^~~~~~~~~
lib/kunit/test.c:48:20: note: format string is defined here
48 | "# %s: %lu / %lu test parameters failed",
| ~~^
| |
| long unsigned int
| %u
lib/kunit/test.c: In function 'kunit_log_append':
lib/kunit/test.c:72:2: warning: function 'kunit_log_append' might be a candidate for 'gnu_printf' format attribute [-Wsuggest-attribute=format]
72 | vsnprintf(line, sizeof(line), fmt, args);
| ^~~~~~~~~
In file included from lib/kunit/test.c:9:
lib/kunit/test.c: In function 'kunit_print_suite_stats':
include/linux/kern_levels.h:5:18: warning: format '%lu' expects argument of type 'long unsigned int', but argument 3 has type 'size_t' {aka 'unsigned int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
include/kunit/test.h:621:10: note: in definition of macro 'kunit_log'
621 | printk(lvl fmt, ##__VA_ARGS__); \
| ^~~
include/linux/kern_levels.h:14:19: note: in expansion of macro 'KERN_SOH'
14 | #define KERN_INFO KERN_SOH "6" /* informational */
| ^~~~~~~~
lib/kunit/test.c:394:12: note: in expansion of macro 'KERN_INFO'
394 | kunit_log(KERN_INFO, suite,
| ^~~~~~~~~
lib/kunit/test.c:395:15: note: format string is defined here
395 | "# %s: (%lu / %lu) tests failed (%lu / %lu test parameters)",
| ~~^
| |
| long unsigned int
| %u
In file included from lib/kunit/test.c:9:
include/linux/kern_levels.h:5:18: warning: format '%lu' expects argument of type 'long unsigned int', but argument 4 has type 'size_t' {aka 'unsigned int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
include/kunit/test.h:621:10: note: in definition of macro 'kunit_log'
621 | printk(lvl fmt, ##__VA_ARGS__); \
| ^~~
include/linux/kern_levels.h:14:19: note: in expansion of macro 'KERN_SOH'
14 | #define KERN_INFO KERN_SOH "6" /* informational */
| ^~~~~~~~
lib/kunit/test.c:394:12: note: in expansion of macro 'KERN_INFO'
394 | kunit_log(KERN_INFO, suite,
| ^~~~~~~~~
lib/kunit/test.c:395:21: note: format string is defined here
395 | "# %s: (%lu / %lu) tests failed (%lu / %lu test parameters)",
| ~~^
| |
| long unsigned int
| %u
In file included from lib/kunit/test.c:9:
include/linux/kern_levels.h:5:18: warning: format '%lu' expects argument of type 'long unsigned int', but argument 5 has type 'size_t' {aka 'unsigned int'} [-Wformat=]
5 | #define KERN_SOH "\001" /* ASCII Start Of Header */
| ^~~~~~
include/kunit/test.h:621:10: note: in definition of macro 'kunit_log'
621 | printk(lvl fmt, ##__VA_ARGS__); \
| ^~~
include/linux/kern_levels.h:14:19: note: in expansion of macro 'KERN_SOH'
14 | #define KERN_INFO KERN_SOH "6" /* informational */
| ^~~~~~~~
lib/kunit/test.c:394:12: note: in expansion of macro 'KERN_INFO'
394 | kunit_log(KERN_INFO, suite,
| ^~~~~~~~~
lib/kunit/test.c:395:40: note: format string is defined here
395 | "# %s: (%lu / %lu) tests failed (%lu / %lu test parameters)",

vim +27 lib/kunit/test.c

19
20 /*
21 * KUnit statistic mode:
22 * 0 - disabled
23 * 1 - only when there is at least one failure, and more than one subtest
24 * 2 - enabled
25 */
26 static int kunit_stats_enabled = 1;
> 27 core_param(kunit_stats_enabled, kunit_stats_enabled, int, 0644);
28

---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/[email protected]


Attachments:
(No filename) (7.34 kB)
.config.gz (26.28 kB)
Download all attachments

2020-12-13 06:14:15

by Daniel Latypov

[permalink] [raw]
Subject: Re: [PATCH] kunit: Print test statistics on failure

On Thu, Dec 10, 2020 at 11:23 PM David Gow <[email protected]> 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
> subtests, and at least one failure (new default)
> - 2: Always print test statistics

I personally prefer having less options here, if possible.

a) I wonder if 0 can be dropped in favor of just using the default (1).
I don't know that showing test counts on failures (ideally a rare
occurrence) in the diagnostics would be enough of an annoyance that
people would want to turn it off.

b) And/or perhaps strike a compromise between 1/2.
We print the test stats whenever there are >1 subtests, regardless of
# of failures.

If we take both suggestions, then we just have one way, which is
appealing to me personally, but I don't know that people would like
that.

>
> For parameterised tests, the summary line looks as follows:
> " # inode_test_xtimestamp_decoding: 0 / 16 test parameters failed"
> For test suites, it looks like this:
> "# ext4_inode_test: (0 / 1) tests failed (0 / 16 test parameters)"
>
> kunit_tool is also updated to correctly ignore diagnostic lines, so that
> these statistics do not prevent the result from parsing.
>
> Signed-off-by: David Gow <[email protected]>
> ---
>
> This is largely a follow-up to the discussion here:
> https://lore.kernel.org/linux-kselftest/CABVgOSmy4n_LGwDS7yWfoLftcQzxv6S+iXx9Y=OPcgG2gu0z1w@mail.gmail.com/T/#t
>
> Does this seem like a sensible addition?
>
> Cheers,
> -- David
>
> lib/kunit/test.c | 71 +++++++++++++++++++++++++++++
> tools/testing/kunit/kunit_parser.py | 2 +-
> 2 files changed, 72 insertions(+), 1 deletion(-)
>
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index ec9494e914ef..711e269366a7 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -9,6 +9,7 @@
> #include <kunit/test.h>
> #include <linux/kernel.h>
> #include <linux/kref.h>
> +#include <linux/moduleparam.h>
> #include <linux/sched/debug.h>
> #include <linux/sched.h>
>
> @@ -16,6 +17,40 @@
> #include "string-stream.h"
> #include "try-catch-impl.h"
>
> +/*
> + * KUnit statistic mode:
> + * 0 - disabled
> + * 1 - only when there is at least one failure, and more than one subtest
> + * 2 - enabled
> + */
> +static int kunit_stats_enabled = 1;
> +core_param(kunit_stats_enabled, kunit_stats_enabled, int, 0644);
> +
> +static bool kunit_should_print_stats(int num_failures, int num_subtests)
> +{
> + if (kunit_stats_enabled == 0)
> + return false;
> +
> + if (kunit_stats_enabled == 2)
> + return true;
> +
> + return (num_failures > 0 && num_subtests > 1);
> +}
> +
> +static void kunit_print_test_stats(struct kunit *test,
> + size_t num_failures, size_t num_subtests)
> +{
> + if (!kunit_should_print_stats(num_failures, num_subtests))
> + return;
> +
> + kunit_log(KERN_INFO, test,
> + KUNIT_SUBTEST_INDENT
> + "# %s: %lu / %lu test parameters failed",
> + test->name,
> + num_failures,
> + num_subtests);
> +}
> +
> /*
> * Append formatted message to log, size of which is limited to
> * KUNIT_LOG_SIZE bytes (including null terminating byte).
> @@ -346,15 +381,37 @@ static void kunit_run_case_catch_errors(struct kunit_suite *suite,
> test_case->success = test->success;
> }
>
> +static void kunit_print_suite_stats(struct kunit_suite *suite,
> + size_t num_failures,
> + size_t total_param_failures,
> + size_t total_params)
> +{
> + size_t num_cases = kunit_suite_num_test_cases(suite);
> +
> + if (!kunit_should_print_stats(num_failures, num_cases))
> + return;
> +
> + kunit_log(KERN_INFO, suite,
> + "# %s: (%lu / %lu) tests failed (%lu / %lu test parameters)",
> + suite->name,
> + num_failures,
> + num_cases,
> + total_param_failures,
> + total_params);
> +}
> +
> int kunit_run_tests(struct kunit_suite *suite)
> {
> char param_desc[KUNIT_PARAM_DESC_SIZE];
> struct kunit_case *test_case;
> + size_t num_suite_failures = 0;
> + size_t total_param_failures = 0, total_params = 0;
>
> kunit_print_subtest_start(suite);
>
> kunit_suite_for_each_test_case(suite, test_case) {
> struct kunit test = { .param_value = NULL, .param_index = 0 };
> + size_t num_params = 0, num_failures = 0;
> bool test_success = true;
>
> if (test_case->generate_params) {
> @@ -385,13 +442,27 @@ int kunit_run_tests(struct kunit_suite *suite)
> test.param_value = test_case->generate_params(test.param_value, param_desc);
> test.param_index++;
> }
> +
> + if (!test.success)
> + num_failures++;

Completely tangential: I'm glad we're counting failures now.
As noted in previous discussions, we'd want to eventually do this anyways.
It would be good if this func (and eventually `insmod`) could return a
non-zero retcode on test failure so users don't have to necessarily
parse KTAP output.

> + num_params++;
> +
> } while (test.param_value);
>
> + kunit_print_test_stats(&test, num_failures, num_params);
> +
> kunit_print_ok_not_ok(&test, true, test_success,
> kunit_test_case_num(suite, test_case),
> test_case->name);
> +
> + if (!test_success)
> + num_suite_failures++;
> + total_params += num_params;
> + total_param_failures += num_failures;
> }
>
> + kunit_print_suite_stats(suite, num_suite_failures,
> + total_param_failures, total_params);
> kunit_print_subtest_end(suite);
>
> return 0;
> diff --git a/tools/testing/kunit/kunit_parser.py b/tools/testing/kunit/kunit_parser.py
> index 6614ec4d0898..88ee2b2668ad 100644
> --- a/tools/testing/kunit/kunit_parser.py
> +++ b/tools/testing/kunit/kunit_parser.py
> @@ -95,7 +95,7 @@ def print_log(log):
> 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:).*$')
>
> def consume_non_diagnositic(lines: List[str]) -> None:
> while lines and not TAP_ENTRIES.match(lines[0]):
>
> base-commit: 5f6b99d0287de2c2d0b5e7abcb0092d553ad804a
> --
> 2.29.2.576.ga3fc446d84-goog
>

2021-02-06 03:02:30

by Brendan Higgins

[permalink] [raw]
Subject: Re: [PATCH] kunit: Print test statistics on failure

On Thu, Dec 10, 2020 at 11:23 PM David Gow <[email protected]> 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
> subtests, and at least one failure (new default)
> - 2: Always print test statistics
>
> For parameterised tests, the summary line looks as follows:
> " # inode_test_xtimestamp_decoding: 0 / 16 test parameters failed"
> For test suites, it looks like this:
> "# ext4_inode_test: (0 / 1) tests failed (0 / 16 test parameters)"
>
> kunit_tool is also updated to correctly ignore diagnostic lines, so that
> these statistics do not prevent the result from parsing.
>
> Signed-off-by: David Gow <[email protected]>

Sorry, forgot about this. A couple of comments below:

> ---
>
> This is largely a follow-up to the discussion here:
> https://lore.kernel.org/linux-kselftest/CABVgOSmy4n_LGwDS7yWfoLftcQzxv6S+iXx9Y=OPcgG2gu0z1w@mail.gmail.com/T/#t
>
> Does this seem like a sensible addition?

I am fine with it as long as other people want it.

> Cheers,
> -- David
>
> lib/kunit/test.c | 71 +++++++++++++++++++++++++++++
> tools/testing/kunit/kunit_parser.py | 2 +-
> 2 files changed, 72 insertions(+), 1 deletion(-)
>
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index ec9494e914ef..711e269366a7 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -9,6 +9,7 @@
> #include <kunit/test.h>
> #include <linux/kernel.h>
> #include <linux/kref.h>
> +#include <linux/moduleparam.h>
> #include <linux/sched/debug.h>
> #include <linux/sched.h>
>
> @@ -16,6 +17,40 @@
> #include "string-stream.h"
> #include "try-catch-impl.h"
>
> +/*
> + * KUnit statistic mode:
> + * 0 - disabled
> + * 1 - only when there is at least one failure, and more than one subtest
> + * 2 - enabled
> + */
> +static int kunit_stats_enabled = 1;
> +core_param(kunit_stats_enabled, kunit_stats_enabled, int, 0644);

I think this should be a module param.

Also, remember to document the param with: MODULE_PARM_DESC()

> +static bool kunit_should_print_stats(int num_failures, int num_subtests)
> +{
> + if (kunit_stats_enabled == 0)
> + return false;
> +
> + if (kunit_stats_enabled == 2)
> + return true;
> +
> + return (num_failures > 0 && num_subtests > 1);
> +}
> +
> +static void kunit_print_test_stats(struct kunit *test,
> + size_t num_failures, size_t num_subtests)
> +{
> + if (!kunit_should_print_stats(num_failures, num_subtests))
> + return;
> +
> + kunit_log(KERN_INFO, test,
> + KUNIT_SUBTEST_INDENT
> + "# %s: %lu / %lu test parameters failed",
> + test->name,
> + num_failures,
> + num_subtests);
> +}
> +
> /*
> * Append formatted message to log, size of which is limited to
> * KUNIT_LOG_SIZE bytes (including null terminating byte).
> @@ -346,15 +381,37 @@ static void kunit_run_case_catch_errors(struct kunit_suite *suite,
> test_case->success = test->success;
> }
>
> +static void kunit_print_suite_stats(struct kunit_suite *suite,
> + size_t num_failures,
> + size_t total_param_failures,
> + size_t total_params)
> +{
> + size_t num_cases = kunit_suite_num_test_cases(suite);
> +
> + if (!kunit_should_print_stats(num_failures, num_cases))
> + return;
> +
> + kunit_log(KERN_INFO, suite,
> + "# %s: (%lu / %lu) tests failed (%lu / %lu test parameters)",
> + suite->name,
> + num_failures,
> + num_cases,
> + total_param_failures,
> + total_params);
> +}
> +
> int kunit_run_tests(struct kunit_suite *suite)
> {
> char param_desc[KUNIT_PARAM_DESC_SIZE];
> struct kunit_case *test_case;
> + size_t num_suite_failures = 0;
> + size_t total_param_failures = 0, total_params = 0;
>
> kunit_print_subtest_start(suite);
>
> kunit_suite_for_each_test_case(suite, test_case) {
> struct kunit test = { .param_value = NULL, .param_index = 0 };
> + size_t num_params = 0, num_failures = 0;
> bool test_success = true;
>
> if (test_case->generate_params) {
> @@ -385,13 +442,27 @@ int kunit_run_tests(struct kunit_suite *suite)
> test.param_value = test_case->generate_params(test.param_value, param_desc);
> test.param_index++;
> }
> +
> + if (!test.success)
> + num_failures++;
> + num_params++;
> +
> } while (test.param_value);
>
> + kunit_print_test_stats(&test, num_failures, num_params);
> +
> kunit_print_ok_not_ok(&test, true, test_success,
> kunit_test_case_num(suite, test_case),
> test_case->name);
> +
> + if (!test_success)
> + num_suite_failures++;
> + total_params += num_params;
> + total_param_failures += num_failures;
> }
>
> + kunit_print_suite_stats(suite, num_suite_failures,
> + total_param_failures, total_params);
> kunit_print_subtest_end(suite);
>
> return 0;
> diff --git a/tools/testing/kunit/kunit_parser.py b/tools/testing/kunit/kunit_parser.py
> index 6614ec4d0898..88ee2b2668ad 100644
> --- a/tools/testing/kunit/kunit_parser.py
> +++ b/tools/testing/kunit/kunit_parser.py
> @@ -95,7 +95,7 @@ def print_log(log):
> 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:).*$')
>
> def consume_non_diagnositic(lines: List[str]) -> None:
> while lines and not TAP_ENTRIES.match(lines[0]):
>
> base-commit: 5f6b99d0287de2c2d0b5e7abcb0092d553ad804a
> --
> 2.29.2.576.ga3fc446d84-goog
>