[v2] kunit: Warn if tests are slow

  Kunit recently gained support to setup attributes, the first one being
the speed of a given test, then allowing to filter out slow tests.

A slow test is defined in the documentation as taking more than one
second. There's an another speed attribute called "super slow" but whose
definition is less clear.

Add support to the test runner to check the test execution time, and
report tests that should be marked as slow but aren't.

Signed-off-by: Maxime Ripard <mripard@kernel.org>

---

To: Brendan Higgins <brendan.higgins@linux.dev>
To: David Gow <davidgow@google.com>
Cc: Jani Nikula <jani.nikula@linux.intel.com>
Cc: Rae Moar <rmoar@google.com>
Cc: linux-kselftest@vger.kernel.org
Cc: kunit-dev@googlegroups.com
Cc: linux-kernel@vger.kernel.org

Changes from v1:
- Split the patch out of the series
- Change to trigger the warning only if the runtime is twice the
  threshold (Jani, Rae)
- Split the speed check into a separate function (Rae)
- Link: https://lore.kernel.org/all/20230911-kms-slow-tests-v1-0-d3800a69a1a1@kernel.org/
---
 lib/kunit/test.c | 27 +++++++++++++++++++++++++++
 1 file changed, 27 insertions(+)
  

On Wed, Sep 20, 2023 at 10:49:03AM +0200, Maxime Ripard wrote:
> Kunit recently gained support to setup attributes, the first one being
> the speed of a given test, then allowing to filter out slow tests.
> 
> A slow test is defined in the documentation as taking more than one
> second. There's an another speed attribute called "super slow" but whose
> definition is less clear.
> 
> Add support to the test runner to check the test execution time, and
> report tests that should be marked as slow but aren't.
> 
> Signed-off-by: Maxime Ripard <mripard@kernel.org>

Ping?

Thanks!
Maxime
  

On Wed, Sep 20, 2023 at 4:49 AM Maxime Ripard <mripard@kernel.org> wrote:
>
> Kunit recently gained support to setup attributes, the first one being
> the speed of a given test, then allowing to filter out slow tests.
>
> A slow test is defined in the documentation as taking more than one
> second. There's an another speed attribute called "super slow" but whose
> definition is less clear.
>
> Add support to the test runner to check the test execution time, and
> report tests that should be marked as slow but aren't.
>
> Signed-off-by: Maxime Ripard <mripard@kernel.org>
>

Hello!

Thanks for following up! Sorry for the delay in this response.

This looks great to me. I do have one comment below regarding the
KUNIT_SPEED_SLOW_THRESHOLD_S macro but other than that I would be
happy with this patch.

This patch does bring up the question of how to handle KUnit warnings
as mentioned before. But I am happy to approach that in a future
patch.

And I do still have concerns with this being annoying for those on
slower architectures but again that would depend on how we deal with
KUnit warnings.

Thanks!
-Rae

> ---
>
> To: Brendan Higgins <brendan.higgins@linux.dev>
> To: David Gow <davidgow@google.com>
> Cc: Jani Nikula <jani.nikula@linux.intel.com>
> Cc: Rae Moar <rmoar@google.com>
> Cc: linux-kselftest@vger.kernel.org
> Cc: kunit-dev@googlegroups.com
> Cc: linux-kernel@vger.kernel.org
>
> Changes from v1:
> - Split the patch out of the series
> - Change to trigger the warning only if the runtime is twice the
>   threshold (Jani, Rae)
> - Split the speed check into a separate function (Rae)
> - Link: https://lore.kernel.org/all/20230911-kms-slow-tests-v1-0-d3800a69a1a1@kernel.org/
> ---
>  lib/kunit/test.c | 27 +++++++++++++++++++++++++++
>  1 file changed, 27 insertions(+)
>
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index 49698a168437..a1d5dd2bf87d 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -372,6 +372,25 @@ void kunit_init_test(struct kunit *test, const char *name, char *log)
>  }
>  EXPORT_SYMBOL_GPL(kunit_init_test);
>
> +#define KUNIT_SPEED_SLOW_THRESHOLD_S   1
> +
> +static void kunit_run_case_check_speed(struct kunit *test,
> +                                      struct kunit_case *test_case,
> +                                      struct timespec64 duration)
> +{
> +       enum kunit_speed speed = test_case->attr.speed;
> +
> +       if (duration.tv_sec < (2 * KUNIT_SPEED_SLOW_THRESHOLD_S))

I think I would prefer that KUNIT_SPEED_SLOW_THRESHOLD_S is instead
set to 2 rather than using 2 as the multiplier. I realize the actual
threshold for the attributes is 1 sec but for the practical use of
this warning it is 2 sec.

Also I would still be open to this being 1 sec depending on others
opinions. David, what are your thoughts on this?

> +               return;
> +
> +       if (speed == KUNIT_SPEED_VERY_SLOW || speed == KUNIT_SPEED_SLOW)
> +               return;
> +
> +       kunit_warn(test,
> +                  "Test should be marked slow (runtime: %lld.%09lds)",
> +                  duration.tv_sec, duration.tv_nsec);
> +}
> +
>  /*
>   * Initializes and runs test case. Does not clean up or do post validations.
>   */
> @@ -379,6 +398,8 @@ static void kunit_run_case_internal(struct kunit *test,
>                                     struct kunit_suite *suite,
>                                     struct kunit_case *test_case)
>  {
> +       struct timespec64 start, end;
> +
>         if (suite->init) {
>                 int ret;
>
> @@ -390,7 +411,13 @@ static void kunit_run_case_internal(struct kunit *test,
>                 }
>         }
>
> +       ktime_get_ts64(&start);
> +
>         test_case->run_case(test);
> +
> +       ktime_get_ts64(&end);
> +
> +       kunit_run_case_check_speed(test, test_case, timespec64_sub(end, start));
>  }
>
>  static void kunit_case_internal_cleanup(struct kunit *test)
> --
> 2.41.0
>
  

Hi Rae,

On Tue, Oct 24, 2023 at 03:41:33PM -0400, Rae Moar wrote:
> On Wed, Sep 20, 2023 at 4:49 AM Maxime Ripard <mripard@kernel.org> wrote:
> >
> > Kunit recently gained support to setup attributes, the first one being
> > the speed of a given test, then allowing to filter out slow tests.
> >
> > A slow test is defined in the documentation as taking more than one
> > second. There's an another speed attribute called "super slow" but whose
> > definition is less clear.
> >
> > Add support to the test runner to check the test execution time, and
> > report tests that should be marked as slow but aren't.
> >
> > Signed-off-by: Maxime Ripard <mripard@kernel.org>
> >
> 
> Hello!
> 
> Thanks for following up! Sorry for the delay in this response.

np, I kind of forgot about it too to be fair :)

> This looks great to me. I do have one comment below regarding the
> KUNIT_SPEED_SLOW_THRESHOLD_S macro but other than that I would be
> happy with this patch.
> 
> This patch does bring up the question of how to handle KUnit warnings
> as mentioned before. But I am happy to approach that in a future
> patch.
>
> And I do still have concerns with this being annoying for those on
> slower architectures but again that would depend on how we deal with
> KUnit warnings.

Yeah, I agree there

> > To: Brendan Higgins <brendan.higgins@linux.dev>
> > To: David Gow <davidgow@google.com>
> > Cc: Jani Nikula <jani.nikula@linux.intel.com>
> > Cc: Rae Moar <rmoar@google.com>
> > Cc: linux-kselftest@vger.kernel.org
> > Cc: kunit-dev@googlegroups.com
> > Cc: linux-kernel@vger.kernel.org
> >
> > Changes from v1:
> > - Split the patch out of the series
> > - Change to trigger the warning only if the runtime is twice the
> >   threshold (Jani, Rae)
> > - Split the speed check into a separate function (Rae)
> > - Link: https://lore.kernel.org/all/20230911-kms-slow-tests-v1-0-d3800a69a1a1@kernel.org/
> > ---
> >  lib/kunit/test.c | 27 +++++++++++++++++++++++++++
> >  1 file changed, 27 insertions(+)
> >
> > diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> > index 49698a168437..a1d5dd2bf87d 100644
> > --- a/lib/kunit/test.c
> > +++ b/lib/kunit/test.c
> > @@ -372,6 +372,25 @@ void kunit_init_test(struct kunit *test, const char *name, char *log)
> >  }
> >  EXPORT_SYMBOL_GPL(kunit_init_test);
> >
> > +#define KUNIT_SPEED_SLOW_THRESHOLD_S   1
> > +
> > +static void kunit_run_case_check_speed(struct kunit *test,
> > +                                      struct kunit_case *test_case,
> > +                                      struct timespec64 duration)
> > +{
> > +       enum kunit_speed speed = test_case->attr.speed;
> > +
> > +       if (duration.tv_sec < (2 * KUNIT_SPEED_SLOW_THRESHOLD_S))
> 
> I think I would prefer that KUNIT_SPEED_SLOW_THRESHOLD_S is instead
> set to 2 rather than using 2 as the multiplier. I realize the actual
> threshold for the attributes is 1 sec but for the practical use of
> this warning it is 2 sec.

Right. So I kind of disagree here. To me, the define should match the
definition we have for a slow test. We chose to report it only if it
exceeds it by a margin, but that's a separate thing from the actual
threshold.

I guess I could add a new version to make that distinction clearer.
Would that work for you?

Maxime
  

On Wed, 20 Sept 2023 at 16:49, Maxime Ripard <mripard@kernel.org> wrote:
>
> Kunit recently gained support to setup attributes, the first one being
> the speed of a given test, then allowing to filter out slow tests.
>
> A slow test is defined in the documentation as taking more than one
> second. There's an another speed attribute called "super slow" but whose
> definition is less clear.
>
> Add support to the test runner to check the test execution time, and
> report tests that should be marked as slow but aren't.
>
> Signed-off-by: Maxime Ripard <mripard@kernel.org>
>
> ---
>
> To: Brendan Higgins <brendan.higgins@linux.dev>
> To: David Gow <davidgow@google.com>
> Cc: Jani Nikula <jani.nikula@linux.intel.com>
> Cc: Rae Moar <rmoar@google.com>
> Cc: linux-kselftest@vger.kernel.org
> Cc: kunit-dev@googlegroups.com
> Cc: linux-kernel@vger.kernel.org
>
> Changes from v1:
> - Split the patch out of the series
> - Change to trigger the warning only if the runtime is twice the
>   threshold (Jani, Rae)
> - Split the speed check into a separate function (Rae)
> - Link: https://lore.kernel.org/all/20230911-kms-slow-tests-v1-0-d3800a69a1a1@kernel.org/
> ---

I quite like this, though agree somewhat with Rae's comments below.

I personally think the time thresholds are, by necessity, very
'fuzzy', due to the varying speeds of different hardware. Fortunately,
the actual runtime of tests seems pretty well stratified, so the exact
threshold doesn't really matter much.

I ran some tests here, and all of the tests currently not marked slow
take <1s on every machine I tried (including the ancient 66MHz 486),
except for the drm_mm_* ones (which takes ~6s on my laptop, and times
out after 15 minutes on the aforementioned 486). Both the 1s and 2s
timeouts successfully distinguish those cases.

Ideally, I think we'd have something like:
#define KUNIT_SPEED_SLOW_THRESHOLD_S 1 /* 1 sec threshold for 'slow' tests */
#define KUNIT_SPEED_WARNING_MULTIPLIER 2 /* Warn when a test takes >
twice the threshold. */
#define KUNIT_SPEED_SLOW_WARNING_THRESHOLD_S
(KUNIT_SPEED_WARNING_MULTIPLIER * KUNIT_SPEED_SLOW_THRESHOLD_S)

Which is perhaps excessively verbose, but is very clear as to what
we're doing. It also gives more scope to allow the ratio to be
configured for people with very slow / fast machines in the future.

Thoughts?

Otherwise, this looks good to me.

Reviewed-by: David Gow <davidgow@google.com>

Cheers,
-- David

>  lib/kunit/test.c | 27 +++++++++++++++++++++++++++
>  1 file changed, 27 insertions(+)
>
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index 49698a168437..a1d5dd2bf87d 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -372,6 +372,25 @@ void kunit_init_test(struct kunit *test, const char *name, char *log)
>  }
>  EXPORT_SYMBOL_GPL(kunit_init_test);
>
> +#define KUNIT_SPEED_SLOW_THRESHOLD_S   1
> +
> +static void kunit_run_case_check_speed(struct kunit *test,
> +                                      struct kunit_case *test_case,
> +                                      struct timespec64 duration)
> +{
> +       enum kunit_speed speed = test_case->attr.speed;
> +
> +       if (duration.tv_sec < (2 * KUNIT_SPEED_SLOW_THRESHOLD_S))
> +               return;
> +
> +       if (speed == KUNIT_SPEED_VERY_SLOW || speed == KUNIT_SPEED_SLOW)
> +               return;
> +
> +       kunit_warn(test,
> +                  "Test should be marked slow (runtime: %lld.%09lds)",
> +                  duration.tv_sec, duration.tv_nsec);
> +}
> +
>  /*
>   * Initializes and runs test case. Does not clean up or do post validations.
>   */
> @@ -379,6 +398,8 @@ static void kunit_run_case_internal(struct kunit *test,
>                                     struct kunit_suite *suite,
>                                     struct kunit_case *test_case)
>  {
> +       struct timespec64 start, end;
> +
>         if (suite->init) {
>                 int ret;
>
> @@ -390,7 +411,13 @@ static void kunit_run_case_internal(struct kunit *test,
>                 }
>         }
>
> +       ktime_get_ts64(&start);
> +
>         test_case->run_case(test);
> +
> +       ktime_get_ts64(&end);
> +
> +       kunit_run_case_check_speed(test, test_case, timespec64_sub(end, start));
>  }
>
>  static void kunit_case_internal_cleanup(struct kunit *test)
> --
> 2.41.0
>
  

Hi,

On Thu, Oct 26, 2023 at 03:06:39PM +0800, David Gow wrote:
> On Wed, 20 Sept 2023 at 16:49, Maxime Ripard <mripard@kernel.org> wrote:
> >
> > Kunit recently gained support to setup attributes, the first one being
> > the speed of a given test, then allowing to filter out slow tests.
> >
> > A slow test is defined in the documentation as taking more than one
> > second. There's an another speed attribute called "super slow" but whose
> > definition is less clear.
> >
> > Add support to the test runner to check the test execution time, and
> > report tests that should be marked as slow but aren't.
> >
> > Signed-off-by: Maxime Ripard <mripard@kernel.org>
> >
> > ---
> >
> > To: Brendan Higgins <brendan.higgins@linux.dev>
> > To: David Gow <davidgow@google.com>
> > Cc: Jani Nikula <jani.nikula@linux.intel.com>
> > Cc: Rae Moar <rmoar@google.com>
> > Cc: linux-kselftest@vger.kernel.org
> > Cc: kunit-dev@googlegroups.com
> > Cc: linux-kernel@vger.kernel.org
> >
> > Changes from v1:
> > - Split the patch out of the series
> > - Change to trigger the warning only if the runtime is twice the
> >   threshold (Jani, Rae)
> > - Split the speed check into a separate function (Rae)
> > - Link: https://lore.kernel.org/all/20230911-kms-slow-tests-v1-0-d3800a69a1a1@kernel.org/
> > ---
> 
> I quite like this, though agree somewhat with Rae's comments below.
> 
> I personally think the time thresholds are, by necessity, very
> 'fuzzy', due to the varying speeds of different hardware. Fortunately,
> the actual runtime of tests seems pretty well stratified, so the exact
> threshold doesn't really matter much.
> 
> I ran some tests here, and all of the tests currently not marked slow
> take <1s on every machine I tried (including the ancient 66MHz 486),
> except for the drm_mm_* ones (which takes ~6s on my laptop, and times
> out after 15 minutes on the aforementioned 486). Both the 1s and 2s
> timeouts successfully distinguish those cases.

I had a similar experience running the tests in qemu on a Pi4, which is
probably the slowest machine we can reasonably expect.

> Ideally, I think we'd have something like:
> #define KUNIT_SPEED_SLOW_THRESHOLD_S 1 /* 1 sec threshold for 'slow' tests */
> #define KUNIT_SPEED_WARNING_MULTIPLIER 2 /* Warn when a test takes >
> twice the threshold. */
> #define KUNIT_SPEED_SLOW_WARNING_THRESHOLD_S
> (KUNIT_SPEED_WARNING_MULTIPLIER * KUNIT_SPEED_SLOW_THRESHOLD_S)
> 
> Which is perhaps excessively verbose, but is very clear as to what
> we're doing. It also gives more scope to allow the ratio to be
> configured for people with very slow / fast machines in the future.
> 
> Thoughts?

That looks like a good compromise to me, I'll send another version :)

Thanks!
Maxime