diff mbox series

kunit: Print test statistics on failure

Message ID 20201211072319.533803-1-davidgow@google.com
State New
Headers show
Series kunit: Print test statistics on failure | expand

Commit Message

David Gow Dec. 11, 2020, 7:23 a.m. UTC 
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 <davidgow@google.com>
---

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


base-commit: 5f6b99d0287de2c2d0b5e7abcb0092d553ad804a

Comments

kernel test robot Dec. 11, 2020, 8:22 p.m. UTC | #1 
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 <lkp@intel.com>

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/kbuild-all@lists.01.org
Brendan Higgins Feb. 5, 2021, 11:27 p.m. UTC | #2 
On Thu, Dec 10, 2020 at 11:23 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

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


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

>
diff mbox series

Patch

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]):