diff mbox series

[1/2] kunit: Warn if tests are slow

Message ID 20230911-kms-slow-tests-v1-1-d3800a69a1a1@kernel.org (mailing list archive)
State New
Delegated to: Brendan Higgins
Headers show
Series drm/tests: Flag slow kunit tests as such | expand

Commit Message

Maxime Ripard Sept. 11, 2023, 9:51 a.m. UTC
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>
---
 lib/kunit/test.c | 16 ++++++++++++++++
 1 file changed, 16 insertions(+)

Comments

Jani Nikula Sept. 11, 2023, 10:07 a.m. UTC | #1
On Mon, 11 Sep 2023, 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>
> ---
>  lib/kunit/test.c | 16 ++++++++++++++++
>  1 file changed, 16 insertions(+)
>
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index 49698a168437..a3b924501f3d 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -379,6 +379,9 @@ static void kunit_run_case_internal(struct kunit *test,
>  				    struct kunit_suite *suite,
>  				    struct kunit_case *test_case)
>  {
> +	struct timespec64 start, end;
> +	struct timespec64 duration;
> +
>  	if (suite->init) {
>  		int ret;
>  
> @@ -390,7 +393,20 @@ static void kunit_run_case_internal(struct kunit *test,
>  		}
>  	}
>  
> +	ktime_get_ts64(&start);
> +
>  	test_case->run_case(test);
> +
> +	ktime_get_ts64(&end);
> +
> +	duration = timespec64_sub(end, start);
> +
> +	if (duration.tv_sec >= 1 &&
> +	    (test_case->attr.speed == KUNIT_SPEED_UNSET ||
> +	     test_case->attr.speed >= KUNIT_SPEED_NORMAL))
> +		kunit_warn(test,
> +			   "Test should be marked slow (runtime: %lld.%09lds)",
> +			   duration.tv_sec, duration.tv_nsec);

Two thoughts:

Should there be some tolerance here? Otherwise we're flagging this on
the slowest machines, and we'll be defining tests slow based on
that. Like, warn if it takes more than 2 seconds.

What if someone makes a test faster, but forgets to update the
attribute? Should we also flag slow tests that are in fact fast?


BR,
Jani.


>  }
>  
>  static void kunit_case_internal_cleanup(struct kunit *test)
Maxime Ripard Sept. 11, 2023, 11:25 a.m. UTC | #2
Hi Jani,

On Mon, Sep 11, 2023 at 01:07:35PM +0300, Jani Nikula wrote:
> On Mon, 11 Sep 2023, 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>
> > ---
> >  lib/kunit/test.c | 16 ++++++++++++++++
> >  1 file changed, 16 insertions(+)
> >
> > diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> > index 49698a168437..a3b924501f3d 100644
> > --- a/lib/kunit/test.c
> > +++ b/lib/kunit/test.c
> > @@ -379,6 +379,9 @@ static void kunit_run_case_internal(struct kunit *test,
> >  				    struct kunit_suite *suite,
> >  				    struct kunit_case *test_case)
> >  {
> > +	struct timespec64 start, end;
> > +	struct timespec64 duration;
> > +
> >  	if (suite->init) {
> >  		int ret;
> >  
> > @@ -390,7 +393,20 @@ static void kunit_run_case_internal(struct kunit *test,
> >  		}
> >  	}
> >  
> > +	ktime_get_ts64(&start);
> > +
> >  	test_case->run_case(test);
> > +
> > +	ktime_get_ts64(&end);
> > +
> > +	duration = timespec64_sub(end, start);
> > +
> > +	if (duration.tv_sec >= 1 &&
> > +	    (test_case->attr.speed == KUNIT_SPEED_UNSET ||
> > +	     test_case->attr.speed >= KUNIT_SPEED_NORMAL))
> > +		kunit_warn(test,
> > +			   "Test should be marked slow (runtime: %lld.%09lds)",
> > +			   duration.tv_sec, duration.tv_nsec);
> 
> Two thoughts:
> 
> Should there be some tolerance here? Otherwise we're flagging this on
> the slowest machines, and we'll be defining tests slow based on
> that. Like, warn if it takes more than 2 seconds.

I'm not sure what the expectation from David and Brendan are here. I'll
follow what they suggest, but with a couple of hundreds tests like we
have in DRM at the moment, the difference in run time can be up to 5
minutes :/

> What if someone makes a test faster, but forgets to update the
> attribute? Should we also flag slow tests that are in fact fast?

I'm not sure we can do that actually, because it certainly depends on
the hardware running the tests. So I would definitely expect most of the
slow tests to be running faster on some hardware.

Like, running kunit natively on my workstation clears all the DRM tests
in 6s, while it takes about 60s using qemu to test it on arm64, so they
would be considered slow on arm64 but not by default.

Maxime
Rae Moar Sept. 19, 2023, 7:48 p.m. UTC | #3
On Mon, Sep 11, 2023 at 5:51 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>

Hi!

I like this idea especially if it was helpful in identifying slow
tests already! I have a few thoughts on this. I share Jani's concern
for warning all tests on slow machines. I can think of a few options.

First, we could increase the threshold to about 2s even though that
would eliminate warnings on potentially slow tests. However, this
would point out the slowest tests.

Second, we could change this to warn users only when they choose by
making this a configurable option or making this a script to output a
list of all unmarked slow tests.

Third, we could leave this as is. As the KUnit warnings do not show up
in the kunit.py output and do not cause the test to fail in any way
they are relatively harmless if they are unwanted by the user.

Not quite sure which I prefer? The second option might be the cleanest
for the user and the time threshold could even be customizable. Let me
know what you think.

> ---
>  lib/kunit/test.c | 16 ++++++++++++++++
>  1 file changed, 16 insertions(+)
>
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index 49698a168437..a3b924501f3d 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -379,6 +379,9 @@ static void kunit_run_case_internal(struct kunit *test,
>                                     struct kunit_suite *suite,
>                                     struct kunit_case *test_case)
>  {
> +       struct timespec64 start, end;
> +       struct timespec64 duration;
> +
>         if (suite->init) {
>                 int ret;
>
> @@ -390,7 +393,20 @@ static void kunit_run_case_internal(struct kunit *test,
>                 }
>         }
>
> +       ktime_get_ts64(&start);
> +
>         test_case->run_case(test);
> +
> +       ktime_get_ts64(&end);
> +
> +       duration = timespec64_sub(end, start);
> +
> +       if (duration.tv_sec >= 1 &&
> +           (test_case->attr.speed == KUNIT_SPEED_UNSET ||
> +            test_case->attr.speed >= KUNIT_SPEED_NORMAL))
> +               kunit_warn(test,
> +                          "Test should be marked slow (runtime: %lld.%09lds)",
> +                          duration.tv_sec, duration.tv_nsec);

I would consider moving this if statement into a separate function.

>  }
>
>  static void kunit_case_internal_cleanup(struct kunit *test)
>
> --
> 2.41.0
>
> --
> You received this message because you are subscribed to the Google Groups "KUnit Development" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to kunit-dev+unsubscribe@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/kunit-dev/20230911-kms-slow-tests-v1-1-d3800a69a1a1%40kernel.org.
Maxime Ripard Sept. 20, 2023, 7:06 a.m. UTC | #4
Hi,

On Tue, Sep 19, 2023 at 03:48:55PM -0400, Rae Moar wrote:
> On Mon, Sep 11, 2023 at 5:51 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>
>
> I like this idea especially if it was helpful in identifying slow
> tests already! I have a few thoughts on this. I share Jani's concern
> for warning all tests on slow machines. I can think of a few options.
> 
> First, we could increase the threshold to about 2s even though that
> would eliminate warnings on potentially slow tests. However, this
> would point out the slowest tests.

I don't have a strong opinion there, so whatever works for you :)

> Second, we could change this to warn users only when they choose by
> making this a configurable option or making this a script to output a
> list of all unmarked slow tests.

I'm not really sure. Adding an option would hide it away from users and
only a fraction of the users (including devs working on tests) would see
that their test should actually be marked as slow.

That will prevent the wider use of it imo, and instead of catching it
early (when we're working on it), will lead to more patches.

Plus, a runtime of more than a second, no matter the platform, is
usually a good indication that what your test is doing probably
shouldn't be done that way.

> Third, we could leave this as is. As the KUnit warnings do not show up
> in the kunit.py output and do not cause the test to fail in any way
> they are relatively harmless if they are unwanted by the user.

I was looking at it the other day, and I think we can modify the TAP
output to expose the warning through the kunit.py command to the user.

It looks like it allows to provide any keyword after the comment mark
and allows to extend it, so we could have something like

ok $TEST # KUNIT_WARN $MESSAGE

and then parse that in kunit.py, pretty much like we handle SKIP. But
that's a separate discussion really.

But yeah, whether or not this is reported to the user, it must not fail
the test.

> Not quite sure which I prefer? The second option might be the cleanest
> for the user and the time threshold could even be customizable. Let me
> know what you think.

I'm in favour of the second one as well.

> > ---
> >  lib/kunit/test.c | 16 ++++++++++++++++
> >  1 file changed, 16 insertions(+)
> >
> > diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> > index 49698a168437..a3b924501f3d 100644
> > --- a/lib/kunit/test.c
> > +++ b/lib/kunit/test.c
> > @@ -379,6 +379,9 @@ static void kunit_run_case_internal(struct kunit *test,
> >                                     struct kunit_suite *suite,
> >                                     struct kunit_case *test_case)
> >  {
> > +       struct timespec64 start, end;
> > +       struct timespec64 duration;
> > +
> >         if (suite->init) {
> >                 int ret;
> >
> > @@ -390,7 +393,20 @@ static void kunit_run_case_internal(struct kunit *test,
> >                 }
> >         }
> >
> > +       ktime_get_ts64(&start);
> > +
> >         test_case->run_case(test);
> > +
> > +       ktime_get_ts64(&end);
> > +
> > +       duration = timespec64_sub(end, start);
> > +
> > +       if (duration.tv_sec >= 1 &&
> > +           (test_case->attr.speed == KUNIT_SPEED_UNSET ||
> > +            test_case->attr.speed >= KUNIT_SPEED_NORMAL))
> > +               kunit_warn(test,
> > +                          "Test should be marked slow (runtime: %lld.%09lds)",
> > +                          duration.tv_sec, duration.tv_nsec);
> 
> I would consider moving this if statement into a separate function.

Ack.

I'll send a v2 with your suggestions

Thanks!
Maxime
diff mbox series

Patch

diff --git a/lib/kunit/test.c b/lib/kunit/test.c
index 49698a168437..a3b924501f3d 100644
--- a/lib/kunit/test.c
+++ b/lib/kunit/test.c
@@ -379,6 +379,9 @@  static void kunit_run_case_internal(struct kunit *test,
 				    struct kunit_suite *suite,
 				    struct kunit_case *test_case)
 {
+	struct timespec64 start, end;
+	struct timespec64 duration;
+
 	if (suite->init) {
 		int ret;
 
@@ -390,7 +393,20 @@  static void kunit_run_case_internal(struct kunit *test,
 		}
 	}
 
+	ktime_get_ts64(&start);
+
 	test_case->run_case(test);
+
+	ktime_get_ts64(&end);
+
+	duration = timespec64_sub(end, start);
+
+	if (duration.tv_sec >= 1 &&
+	    (test_case->attr.speed == KUNIT_SPEED_UNSET ||
+	     test_case->attr.speed >= KUNIT_SPEED_NORMAL))
+		kunit_warn(test,
+			   "Test should be marked slow (runtime: %lld.%09lds)",
+			   duration.tv_sec, duration.tv_nsec);
 }
 
 static void kunit_case_internal_cleanup(struct kunit *test)