[PATCH v2 00/12] tests: enable meson test timeouts to improve debuggability

[PATCH v2 00/12] tests: enable meson test timeouts to improve debuggability

[Daniel P. Berrangé]

Perhaps the most painful of all the GitLab CI failures we see are
the enforced job timeouts:

   "ERROR: Job failed: execution took longer than 1h15m0s seconds"

   https://gitlab.com/qemu-project/qemu/-/jobs/4387047648

when that hits the CI log shows what has *already* run, but figuring
out what was currently running (or rather stuck) is an horrendously
difficult.

The initial meson port disabled the meson test timeouts, in order to
limit the scope for introducing side effects from the port that would
complicate adoption.

Now that the meson port is basically finished we can take advantage of
more of its improved features. It has the ability to set timeouts for
test programs, defaulting to 30 seconds, but overridable per test. This
is further helped by fact that we changed the iotests integration so
that each iotests was a distinct meson test, instead of having one
single giant (slow) test.

We already set overrides for a bunch of tests, but they've not been
kept up2date since we had timeouts disabled. So this series first
updates the timeout overrides such that all tests pass when run in
my test gitlab CI pipeline. Then it enables use of meson timeouts.

We might still hit timeouts due to non-deterministic performance of
gitlab CI runners. So we'll probably have to increase a few more
timeouts in the short term. Fortunately this is going to be massively
easier to diagnose. For example this job during my testing:

   https://gitlab.com/berrange/qemu/-/jobs/4392029495

we can immediately see  the problem tests

Summary of Failures:
  6/252 qemu:qtest+qtest-i386 / qtest-i386/bios-tables-test                TIMEOUT        120.02s   killed by signal 15 SIGTERM
  7/252 qemu:qtest+qtest-aarch64 / qtest-aarch64/bios-tables-test          TIMEOUT        120.03s   killed by signal 15 SIGTERM
 64/252 qemu:qtest+qtest-aarch64 / qtest-aarch64/qom-test                  TIMEOUT        300.03s   killed by signal 15 SIGTERM

The full meson testlog.txt will show each individual TAP log output,
so we can then see exactly which test case we got stuck on.

NB, the artifacts are missing on the job links above, until this
patch merges:

   https://lists.gnu.org/archive/html/qemu-devel/2023-05/msg04668.html

Changed in v2:

 * Increase timeouts for many more tests, such that
   an --enable-debug build stands a better chance of
   passing tests too, without the user manually setting
   a timeout multiplier for meson.

Daniel P. Berrangé (12):
  qtest: bump min meson timeout to 60 seconds
  qtest: bump migration-test timeout to 5 minutes
  qtest: bump qom-test timeout to 15 minutes
  qtest: bump npcm7xx_pwn-test timeout to 5 minutes
  qtest: bump test-hmp timeout to 4 minutes
  qtest: bump pxe-test timeout to 3 minutes
  qtest: bump prom-env-test timeout to 3 minutes
  qtest: bump boot-serial-test timeout to 3 minutes
  qtest: bump qos-test timeout to 2 minutes
  qtest: bump aspeed_smc-test timeout to 4 minutes
  qtest: bump bios-table-test timeout to 9 minutes
  mtest2make: stop disabling meson test timeouts

 scripts/mtest2make.py   |  3 ++-
 tests/qtest/meson.build | 24 ++++++++++++------------
 2 files changed, 14 insertions(+), 13 deletions(-)

-- 
2.41.0

[PATCH v2 01/12] qtest: bump min meson timeout to 60 seconds

[Daniel P. Berrangé]

Even some of the relatively fast qtests can sometimes hit the 30 second
timeout in GitLab CI under high parallelism/load conditions. Bump the
min to 60 seconds to give a higher margin for reliability.

Reviewed-by: Thomas Huth <thuth@redhat.com>
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/qtest/meson.build | 9 ++-------
 1 file changed, 2 insertions(+), 7 deletions(-)

diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
index b071d400b3..b29d7abc39 100644
--- a/tests/qtest/meson.build
+++ b/tests/qtest/meson.build
@@ -1,12 +1,7 @@
 slow_qtests = {
-  'ahci-test' : 60,
   'bios-tables-test' : 120,
-  'boot-serial-test' : 60,
   'migration-test' : 150,
   'npcm7xx_pwm-test': 150,
-  'prom-env-test' : 60,
-  'pxe-test' : 60,
-  'qos-test' : 60,
   'qom-test' : 300,
   'test-hmp' : 120,
 }
@@ -378,8 +373,8 @@ foreach dir : target_dirs
          env: qtest_env,
          args: ['--tap', '-k'],
          protocol: 'tap',
-         timeout: slow_qtests.get(test, 30),
-         priority: slow_qtests.get(test, 30),
+         timeout: slow_qtests.get(test, 60),
+         priority: slow_qtests.get(test, 60),
          suite: ['qtest', 'qtest-' + target_base])
   endforeach
 endforeach
-- 
2.41.0

[PATCH v2 02/12] qtest: bump migration-test timeout to 5 minutes

[Daniel P. Berrangé]

The migration test should take between 1 min 30 and 2 mins on reasonably
modern hardware. The test is not especially compute bound, rather its
running time is dominated by the guest RAM size relative to the
bandwidth cap, which forces each iteration to take at least 30 seconds.
None the less under high load conditions with multiple QEMU processes
spawned and competing with other parallel tests, the worst case running
time might be somewhat extended. Bumping the timeout to 5 minutes gives
us good headroom, while still catching stuck tests relatively quickly.

Reviewed-by: Thomas Huth <thuth@redhat.com>
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/qtest/meson.build | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
index b29d7abc39..c3f8bf45e4 100644
--- a/tests/qtest/meson.build
+++ b/tests/qtest/meson.build
@@ -1,6 +1,6 @@
 slow_qtests = {
   'bios-tables-test' : 120,
-  'migration-test' : 150,
+  'migration-test' : 300,
   'npcm7xx_pwm-test': 150,
   'qom-test' : 300,
   'test-hmp' : 120,
-- 
2.41.0

[PATCH v2 03/12] qtest: bump qom-test timeout to 15 minutes

[Daniel P. Berrangé]

The qom-test is periodically hitting the 5 minute timeout when running
on the aarch64 emulator under GitLab CI. With an --enable-debug build
it can take over 10 minutes for arm/aarch64 targets. Setting timeout
to 15 minutes gives enough headroom to hopefully make it reliable.

Reviewed-by: Thomas Huth <thuth@redhat.com>
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/qtest/meson.build | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
index c3f8bf45e4..ecbf515d50 100644
--- a/tests/qtest/meson.build
+++ b/tests/qtest/meson.build
@@ -2,7 +2,7 @@ slow_qtests = {
   'bios-tables-test' : 120,
   'migration-test' : 300,
   'npcm7xx_pwm-test': 150,
-  'qom-test' : 300,
+  'qom-test' : 900,
   'test-hmp' : 120,
 }
 
-- 
2.41.0

[PATCH v2 04/12] qtest: bump npcm7xx_pwn-test timeout to 5 minutes

[Daniel P. Berrangé]

The npcm7xx_pwn-test takes 3 & 1/2 minutes in a --enable-debug build.
Bumping to 5 minutes will give more headroom.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/qtest/meson.build | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
index ecbf515d50..e28f0925e1 100644
--- a/tests/qtest/meson.build
+++ b/tests/qtest/meson.build
@@ -1,7 +1,7 @@
 slow_qtests = {
   'bios-tables-test' : 120,
   'migration-test' : 300,
-  'npcm7xx_pwm-test': 150,
+  'npcm7xx_pwm-test': 300,
   'qom-test' : 900,
   'test-hmp' : 120,
 }
-- 
2.41.0

Re: [PATCH v2 04/12] qtest: bump npcm7xx_pwn-test timeout to 5 minutes

[Thomas Huth]

On 17/07/2023 20.28, Daniel P. Berrangé wrote:
> The npcm7xx_pwn-test takes 3 & 1/2 minutes in a --enable-debug build.
> Bumping to 5 minutes will give more headroom.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   tests/qtest/meson.build | 2 +-
>   1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
> index ecbf515d50..e28f0925e1 100644
> --- a/tests/qtest/meson.build
> +++ b/tests/qtest/meson.build
> @@ -1,7 +1,7 @@
>   slow_qtests = {
>     'bios-tables-test' : 120,
>     'migration-test' : 300,
> -  'npcm7xx_pwm-test': 150,
> +  'npcm7xx_pwm-test': 300,
>     'qom-test' : 900,
>     'test-hmp' : 120,
>   }

Reviewed-by: Thomas Huth <thuth@redhat.com>

(we should maybe still have a look at this test later to see why it is so 
slow, though)

Re: [PATCH v2 04/12] qtest: bump npcm7xx_pwn-test timeout to 5 minutes

[Peter Maydell]

On Wed, 19 Jul 2023 at 14:06, Thomas Huth <thuth@redhat.com> wrote:
>
> On 17/07/2023 20.28, Daniel P. Berrangé wrote:
> > The npcm7xx_pwn-test takes 3 & 1/2 minutes in a --enable-debug build.
> > Bumping to 5 minutes will give more headroom.
> >
> > Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> > ---
> >   tests/qtest/meson.build | 2 +-
> >   1 file changed, 1 insertion(+), 1 deletion(-)
> >
> > diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
> > index ecbf515d50..e28f0925e1 100644
> > --- a/tests/qtest/meson.build
> > +++ b/tests/qtest/meson.build
> > @@ -1,7 +1,7 @@
> >   slow_qtests = {
> >     'bios-tables-test' : 120,
> >     'migration-test' : 300,
> > -  'npcm7xx_pwm-test': 150,
> > +  'npcm7xx_pwm-test': 300,
> >     'qom-test' : 900,
> >     'test-hmp' : 120,
> >   }
>
> Reviewed-by: Thomas Huth <thuth@redhat.com>
>
> (we should maybe still have a look at this test later to see why it is so
> slow, though)

It seems to be doing a massively OTT amount of work to test
a single device. Nuvoton maintainers, can you have a look at
cutting it down, please?

thanks
-- PMM

[PATCH v2 05/12] qtest: bump test-hmp timeout to 4 minutes

[Daniel P. Berrangé]

The npcm7xx_pwn-test takes just under 3 minutes in a --enable-debug
build. Bumping to 4 minutes will give more headroom.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/qtest/meson.build | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
index e28f0925e1..1070c6dc64 100644
--- a/tests/qtest/meson.build
+++ b/tests/qtest/meson.build
@@ -3,7 +3,7 @@ slow_qtests = {
   'migration-test' : 300,
   'npcm7xx_pwm-test': 300,
   'qom-test' : 900,
-  'test-hmp' : 120,
+  'test-hmp' : 240,
 }
 
 qtests_generic = [
-- 
2.41.0

Re: [PATCH v2 05/12] qtest: bump test-hmp timeout to 4 minutes

[Thomas Huth]

On 17/07/2023 20.28, Daniel P. Berrangé wrote:
> The npcm7xx_pwn-test takes just under 3 minutes in a --enable-debug

s/npcm7xx_pwn-test/test-hmp/

With that copy-n-paste error fixed:

Reviewed-by: Thomas Huth <thuth@redhat.com>


> build. Bumping to 4 minutes will give more headroom.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   tests/qtest/meson.build | 2 +-
>   1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
> index e28f0925e1..1070c6dc64 100644
> --- a/tests/qtest/meson.build
> +++ b/tests/qtest/meson.build
> @@ -3,7 +3,7 @@ slow_qtests = {
>     'migration-test' : 300,
>     'npcm7xx_pwm-test': 300,
>     'qom-test' : 900,
> -  'test-hmp' : 120,
> +  'test-hmp' : 240,
>   }
>   
>   qtests_generic = [

[PATCH v2 06/12] qtest: bump pxe-test timeout to 3 minutes

[Daniel P. Berrangé]

The pxe-test takes about 1 + 1/2 minutes in a --enable-debug
build. Bumping to 3 minutes will give more headroom.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/qtest/meson.build | 1 +
 1 file changed, 1 insertion(+)

diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
index 1070c6dc64..c6da428dc5 100644
--- a/tests/qtest/meson.build
+++ b/tests/qtest/meson.build
@@ -4,6 +4,7 @@ slow_qtests = {
   'npcm7xx_pwm-test': 300,
   'qom-test' : 900,
   'test-hmp' : 240,
+  'pxe-test': 180,
 }
 
 qtests_generic = [
-- 
2.41.0

Re: [PATCH v2 06/12] qtest: bump pxe-test timeout to 3 minutes

[Thomas Huth]

On 17/07/2023 20.28, Daniel P. Berrangé wrote:
> The pxe-test takes about 1 + 1/2 minutes in a --enable-debug
> build. Bumping to 3 minutes will give more headroom.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   tests/qtest/meson.build | 1 +
>   1 file changed, 1 insertion(+)
> 
> diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
> index 1070c6dc64..c6da428dc5 100644
> --- a/tests/qtest/meson.build
> +++ b/tests/qtest/meson.build
> @@ -4,6 +4,7 @@ slow_qtests = {
>     'npcm7xx_pwm-test': 300,
>     'qom-test' : 900,
>     'test-hmp' : 240,
> +  'pxe-test': 180,
>   }
>   
>   qtests_generic = [

Reviewed-by: Thomas Huth <thuth@redhat.com>

Re: [PATCH v2 06/12] qtest: bump pxe-test timeout to 3 minutes

[Thomas Huth]

On 17/07/2023 20.28, Daniel P. Berrangé wrote:
> The pxe-test takes about 1 + 1/2 minutes in a --enable-debug
> build. Bumping to 3 minutes will give more headroom.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   tests/qtest/meson.build | 1 +
>   1 file changed, 1 insertion(+)
> 
> diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
> index 1070c6dc64..c6da428dc5 100644
> --- a/tests/qtest/meson.build
> +++ b/tests/qtest/meson.build
> @@ -4,6 +4,7 @@ slow_qtests = {
>     'npcm7xx_pwm-test': 300,
>     'qom-test' : 900,
>     'test-hmp' : 240,
> +  'pxe-test': 180,
>   }

By the way, pxe-test uses the boot_sector_test() function, and that already 
uses a timeout of 600 seconds ... so we maybe should use the same (or even 
slightly higher) timeout value here?

  Thomas

Re: [PATCH v2 06/12] qtest: bump pxe-test timeout to 3 minutes

[Daniel P. Berrangé]

On Wed, Jul 19, 2023 at 03:26:11PM +0200, Thomas Huth wrote:
> On 17/07/2023 20.28, Daniel P. Berrangé wrote:
> > The pxe-test takes about 1 + 1/2 minutes in a --enable-debug
> > build. Bumping to 3 minutes will give more headroom.
> > 
> > Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> > ---
> >   tests/qtest/meson.build | 1 +
> >   1 file changed, 1 insertion(+)
> > 
> > diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
> > index 1070c6dc64..c6da428dc5 100644
> > --- a/tests/qtest/meson.build
> > +++ b/tests/qtest/meson.build
> > @@ -4,6 +4,7 @@ slow_qtests = {
> >     'npcm7xx_pwm-test': 300,
> >     'qom-test' : 900,
> >     'test-hmp' : 240,
> > +  'pxe-test': 180,
> >   }
> 
> By the way, pxe-test uses the boot_sector_test() function, and that already
> uses a timeout of 600 seconds ... so we maybe should use the same (or even
> slightly higher) timeout value here?

Your original change setting that 600 limit says:

    If QEMU has been compiled with the flags --enable-tcg-interpreter and
    --enable-debug, the guest is running incredibly slow. The pxe boot test
    can take up to 400 seconds when testing the pseries ppc64 machine.

so yeah, we need to set the timeout for pxe-test to 600 seconds
too. I guess likewise for other tests using boot_sector_test()
function too.

With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

[PATCH v2 07/12] qtest: bump prom-env-test timeout to 3 minutes

[Daniel P. Berrangé]

The prom-env-test takes about 1 + 1/2 minutes in a --enable-debug
build. Bumping to 3 minutes will give more headroom.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/qtest/meson.build | 1 +
 1 file changed, 1 insertion(+)

diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
index c6da428dc5..095c98820e 100644
--- a/tests/qtest/meson.build
+++ b/tests/qtest/meson.build
@@ -5,6 +5,7 @@ slow_qtests = {
   'qom-test' : 900,
   'test-hmp' : 240,
   'pxe-test': 180,
+  'prom-env-test': 180,
 }
 
 qtests_generic = [
-- 
2.41.0

Re: [PATCH v2 07/12] qtest: bump prom-env-test timeout to 3 minutes

[Thomas Huth]

On 17/07/2023 20.28, Daniel P. Berrangé wrote:
> The prom-env-test takes about 1 + 1/2 minutes in a --enable-debug
> build. Bumping to 3 minutes will give more headroom.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   tests/qtest/meson.build | 1 +
>   1 file changed, 1 insertion(+)
> 
> diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
> index c6da428dc5..095c98820e 100644
> --- a/tests/qtest/meson.build
> +++ b/tests/qtest/meson.build
> @@ -5,6 +5,7 @@ slow_qtests = {
>     'qom-test' : 900,
>     'test-hmp' : 240,
>     'pxe-test': 180,
> +  'prom-env-test': 180,
>   }
>   
>   qtests_generic = [

I tested your patches, and initially, everything looked good now. But this 
prom-env-test them reminded me that we run some additional tests in the 
"SPEED=slow" mode ... I guess we have to take these into consideration, too?

I now did a "configure --enable-debug" build and then ran:

  make -j$(nproc) check-qtest-ppc64 SPEED=slow

and indeed, this prom-env-test is now timing out there. Also the 
device-introspect-test was timing out in SPEED=slow mode. Should we bump the 
timeout for those, or could this maybe be handled via the TIMEOUT_MULTIPLIER 
in the final patch?

  Thomas

Re: [PATCH v2 07/12] qtest: bump prom-env-test timeout to 3 minutes

[Thomas Huth]

On 19/07/2023 15.22, Thomas Huth wrote:
> On 17/07/2023 20.28, Daniel P. Berrangé wrote:
>> The prom-env-test takes about 1 + 1/2 minutes in a --enable-debug
>> build. Bumping to 3 minutes will give more headroom.
>>
>> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
>> ---
>>   tests/qtest/meson.build | 1 +
>>   1 file changed, 1 insertion(+)
>>
>> diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
>> index c6da428dc5..095c98820e 100644
>> --- a/tests/qtest/meson.build
>> +++ b/tests/qtest/meson.build
>> @@ -5,6 +5,7 @@ slow_qtests = {
>>     'qom-test' : 900,
>>     'test-hmp' : 240,
>>     'pxe-test': 180,
>> +  'prom-env-test': 180,
>>   }
>>   qtests_generic = [
> 
> I tested your patches, and initially, everything looked good now. But this 
> prom-env-test them reminded me that we run some additional tests in the 
> "SPEED=slow" mode ... I guess we have to take these into consideration, too?
> 
> I now did a "configure --enable-debug" build and then ran:
> 
>   make -j$(nproc) check-qtest-ppc64 SPEED=slow
> 
> and indeed, this prom-env-test is now timing out there. Also the 
> device-introspect-test was timing out in SPEED=slow mode. Should we bump the 
> timeout for those, or could this maybe be handled via the TIMEOUT_MULTIPLIER 
> in the final patch?

I've now done a full check-qtest run with SPEED=slow and --enable-debug,
and these tests are timing out:

  14/131 qemu:qtest+qtest-aarch64 / qtest-aarch64/migration-test            TIMEOUT        300.02s   killed by signal 15 SIGTERM
  89/131 qemu:qtest+qtest-s390x / qtest-s390x/device-introspect-test        TIMEOUT         60.01s   killed by signal 15 SIGTERM
103/131 qemu:qtest+qtest-ppc64 / qtest-ppc64/device-introspect-test        TIMEOUT         60.02s   killed by signal 15 SIGTERM
108/131 qemu:qtest+qtest-ppc64 / qtest-ppc64/pxe-test                      TIMEOUT        180.02s   killed by signal 15 SIGTERM
129/131 qemu:qtest+qtest-x86_64 / qtest-x86_64/device-introspect-test      TIMEOUT         60.05s   killed by signal 15 SIGTERM
130/131 qemu:qtest+qtest-aarch64 / qtest-aarch64/device-introspect-test    TIMEOUT         60.01s   killed by signal 15 SIGTERM

  Thomas

Re: [PATCH v2 07/12] qtest: bump prom-env-test timeout to 3 minutes

[Daniel P. Berrangé]

On Wed, Jul 19, 2023 at 03:22:30PM +0200, Thomas Huth wrote:
> On 17/07/2023 20.28, Daniel P. Berrangé wrote:
> > The prom-env-test takes about 1 + 1/2 minutes in a --enable-debug
> > build. Bumping to 3 minutes will give more headroom.
> > 
> > Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> > ---
> >   tests/qtest/meson.build | 1 +
> >   1 file changed, 1 insertion(+)
> > 
> > diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
> > index c6da428dc5..095c98820e 100644
> > --- a/tests/qtest/meson.build
> > +++ b/tests/qtest/meson.build
> > @@ -5,6 +5,7 @@ slow_qtests = {
> >     'qom-test' : 900,
> >     'test-hmp' : 240,
> >     'pxe-test': 180,
> > +  'prom-env-test': 180,
> >   }
> >   qtests_generic = [
> 
> I tested your patches, and initially, everything looked good now. But this
> prom-env-test them reminded me that we run some additional tests in the
> "SPEED=slow" mode ... I guess we have to take these into consideration, too?
> 
> I now did a "configure --enable-debug" build and then ran:
> 
>  make -j$(nproc) check-qtest-ppc64 SPEED=slow
> 
> and indeed, this prom-env-test is now timing out there. Also the
> device-introspect-test was timing out in SPEED=slow mode. Should we bump the
> timeout for those, or could this maybe be handled via the TIMEOUT_MULTIPLIER
> in the final patch?

My goal was "no regressions" wrt current status for people working on
common development hardware. If people are using old, or modern low
performance hardware than a timeout multiplier would be expected.

IOW, for SPEED=slow, I think we need to "do the right thing" with
the default timeouts.


With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

[PATCH v2 08/12] qtest: bump boot-serial-test timeout to 3 minutes

[Daniel P. Berrangé]

The boot-serial-test takes about 1 + 1/2 minutes in a --enable-debug
build. Bumping to 3 minutes will give more headroom.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/qtest/meson.build | 1 +
 1 file changed, 1 insertion(+)

diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
index 095c98820e..9e4f5e0ecc 100644
--- a/tests/qtest/meson.build
+++ b/tests/qtest/meson.build
@@ -6,6 +6,7 @@ slow_qtests = {
   'test-hmp' : 240,
   'pxe-test': 180,
   'prom-env-test': 180,
+  'boot-serial-test': 180,
 }
 
 qtests_generic = [
-- 
2.41.0

Re: [PATCH v2 08/12] qtest: bump boot-serial-test timeout to 3 minutes

[Thomas Huth]

On 17/07/2023 20.28, Daniel P. Berrangé wrote:
> The boot-serial-test takes about 1 + 1/2 minutes in a --enable-debug
> build. Bumping to 3 minutes will give more headroom.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   tests/qtest/meson.build | 1 +
>   1 file changed, 1 insertion(+)
> 
> diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
> index 095c98820e..9e4f5e0ecc 100644
> --- a/tests/qtest/meson.build
> +++ b/tests/qtest/meson.build
> @@ -6,6 +6,7 @@ slow_qtests = {
>     'test-hmp' : 240,
>     'pxe-test': 180,
>     'prom-env-test': 180,
> +  'boot-serial-test': 180,
>   }
>   
>   qtests_generic = [

Reviewed-by: Thomas Huth <thuth@redhat.com>

[PATCH v2 09/12] qtest: bump qos-test timeout to 2 minutes

[Daniel P. Berrangé]

The qos-test takes just under 1 minute in a --enable-debug
build. Bumping to 2 minutes will give more headroom.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/qtest/meson.build | 1 +
 1 file changed, 1 insertion(+)

diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
index 9e4f5e0ecc..3df9a51b03 100644
--- a/tests/qtest/meson.build
+++ b/tests/qtest/meson.build
@@ -7,6 +7,7 @@ slow_qtests = {
   'pxe-test': 180,
   'prom-env-test': 180,
   'boot-serial-test': 180,
+  'qos-test': 120,
 }
 
 qtests_generic = [
-- 
2.41.0

Re: [PATCH v2 09/12] qtest: bump qos-test timeout to 2 minutes

[Thomas Huth]

On 17/07/2023 20.28, Daniel P. Berrangé wrote:
> The qos-test takes just under 1 minute in a --enable-debug
> build. Bumping to 2 minutes will give more headroom.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   tests/qtest/meson.build | 1 +
>   1 file changed, 1 insertion(+)
> 
> diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
> index 9e4f5e0ecc..3df9a51b03 100644
> --- a/tests/qtest/meson.build
> +++ b/tests/qtest/meson.build
> @@ -7,6 +7,7 @@ slow_qtests = {
>     'pxe-test': 180,
>     'prom-env-test': 180,
>     'boot-serial-test': 180,
> +  'qos-test': 120,
>   }
>   
>   qtests_generic = [

Reviewed-by: Thomas Huth <thuth@redhat.com>

[PATCH v2 10/12] qtest: bump aspeed_smc-test timeout to 4 minutes

[Daniel P. Berrangé]

On a reasonably old laptop this test takes 2 minutes 20 seconds with the
arm emulator. Raising the timeout to 4 minutes gives greater headroom for
slowdown.

Reviewed-by: Thomas Huth <thuth@redhat.com>
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/qtest/meson.build | 1 +
 1 file changed, 1 insertion(+)

diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
index 3df9a51b03..25732a1cdb 100644
--- a/tests/qtest/meson.build
+++ b/tests/qtest/meson.build
@@ -1,4 +1,5 @@
 slow_qtests = {
+  'aspeed_smc-test': 240,
   'bios-tables-test' : 120,
   'migration-test' : 300,
   'npcm7xx_pwm-test': 300,
-- 
2.41.0

Re: [PATCH v2 10/12] qtest: bump aspeed_smc-test timeout to 4 minutes

[Thomas Huth]

On 17/07/2023 20.28, Daniel P. Berrangé wrote:
> On a reasonably old laptop this test takes 2 minutes 20 seconds with the
> arm emulator. Raising the timeout to 4 minutes gives greater headroom for
> slowdown.
> 
> Reviewed-by: Thomas Huth <thuth@redhat.com>
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   tests/qtest/meson.build | 1 +
>   1 file changed, 1 insertion(+)
> 
> diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
> index 3df9a51b03..25732a1cdb 100644
> --- a/tests/qtest/meson.build
> +++ b/tests/qtest/meson.build
> @@ -1,4 +1,5 @@
>   slow_qtests = {
> +  'aspeed_smc-test': 240,
>     'bios-tables-test' : 120,
>     'migration-test' : 300,
>     'npcm7xx_pwm-test': 300,

Reviewed-by: Thomas Huth <thuth@redhat.com>

[PATCH v2 11/12] qtest: bump bios-table-test timeout to 9 minutes

[Daniel P. Berrangé]

This is reliably hitting the current 2 minute timeout in GitLab CI,
and for the TCI job, it even hits a 6 minute timeout.

Reviewed-by: Thomas Huth <thuth@redhat.com>
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 tests/qtest/meson.build | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
index 25732a1cdb..1a5e7f0a15 100644
--- a/tests/qtest/meson.build
+++ b/tests/qtest/meson.build
@@ -1,6 +1,6 @@
 slow_qtests = {
   'aspeed_smc-test': 240,
-  'bios-tables-test' : 120,
+  'bios-tables-test' : 540,
   'migration-test' : 300,
   'npcm7xx_pwm-test': 300,
   'qom-test' : 900,
-- 
2.41.0

[PATCH v2 12/12] mtest2make: stop disabling meson test timeouts

[Daniel P. Berrangé]

The mtest2make.py script passes the arg '-t 0' to 'meson test' which
disables all test timeouts. This is a major source of pain when running
in GitLab CI and a test gets stuck. It will stall until GitLab kills the
CI job. This leaves us with little easily consumable information about
the stalled test. The TAP format doesn't show the test name until it is
completed, and TAP output from multiple tests it interleaved. So we
have to analyse the log to figure out what tests had un-finished TAP
output present and thus infer which test case caused the hang. This is
very time consuming and error prone.

By allowing meson to kill stalled tests, we get a direct display of what
test program got stuck, which lets us more directly focus in on what
specific test case within the test program hung.

The other issue with disabling meson test timeouts by default is that it
makes it more likely that maintainers inadvertantly introduce slowdowns.
For example the recent-ish change that accidentally made migrate-test
take 15-20 minutes instead of around 1 minute.

The main risk of this change is that the individual test timeouts might
be too short to allow completion in high load scenarios. Thus, there is
likely to be some short term pain where we have to bump the timeouts for
certain tests to make them reliable enough. The preceeding few patches
raised the timeouts for all failures that were immediately apparent
in GitLab CI.

Even with the possible short term instability, this should still be a
net win for debuggability of failed CI pipelines over the long term.

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 scripts/mtest2make.py | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/scripts/mtest2make.py b/scripts/mtest2make.py
index 179dd54871..eb01a05ddb 100644
--- a/scripts/mtest2make.py
+++ b/scripts/mtest2make.py
@@ -27,7 +27,8 @@ def names(self, base):
 .speed.slow = $(foreach s,$(sort $(filter-out %-thorough, $1)), --suite $s)
 .speed.thorough = $(foreach s,$(sort $1), --suite $s)
 
-.mtestargs = --no-rebuild -t 0
+TIMEOUT_MULTIPLIER = 1
+.mtestargs = --no-rebuild -t $(TIMEOUT_MULTIPLIER)
 ifneq ($(SPEED), quick)
 .mtestargs += --setup $(SPEED)
 endif
-- 
2.41.0

Re: [PATCH v2 12/12] mtest2make: stop disabling meson test timeouts

[Philippe Mathieu-Daudé]

On 17/7/23 20:28, Daniel P. Berrangé wrote:
> The mtest2make.py script passes the arg '-t 0' to 'meson test' which
> disables all test timeouts. This is a major source of pain when running
> in GitLab CI and a test gets stuck. It will stall until GitLab kills the
> CI job. This leaves us with little easily consumable information about
> the stalled test. The TAP format doesn't show the test name until it is
> completed, and TAP output from multiple tests it interleaved. So we
> have to analyse the log to figure out what tests had un-finished TAP
> output present and thus infer which test case caused the hang. This is
> very time consuming and error prone.
> 
> By allowing meson to kill stalled tests, we get a direct display of what
> test program got stuck, which lets us more directly focus in on what
> specific test case within the test program hung.
> 
> The other issue with disabling meson test timeouts by default is that it
> makes it more likely that maintainers inadvertantly introduce slowdowns.

"inadvertently"

> For example the recent-ish change that accidentally made migrate-test
> take 15-20 minutes instead of around 1 minute.
> 
> The main risk of this change is that the individual test timeouts might
> be too short to allow completion in high load scenarios. Thus, there is
> likely to be some short term pain where we have to bump the timeouts for
> certain tests to make them reliable enough.

[*] (see below)

> The preceeding few patches

"preceding"

> raised the timeouts for all failures that were immediately apparent
> in GitLab CI.
> 
> Even with the possible short term instability, this should still be a
> net win for debuggability of failed CI pipelines over the long term.
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>   scripts/mtest2make.py | 3 ++-
>   1 file changed, 2 insertions(+), 1 deletion(-)
> 
> diff --git a/scripts/mtest2make.py b/scripts/mtest2make.py
> index 179dd54871..eb01a05ddb 100644
> --- a/scripts/mtest2make.py
> +++ b/scripts/mtest2make.py
> @@ -27,7 +27,8 @@ def names(self, base):
>   .speed.slow = $(foreach s,$(sort $(filter-out %-thorough, $1)), --suite $s)
>   .speed.thorough = $(foreach s,$(sort $1), --suite $s)
>   
> -.mtestargs = --no-rebuild -t 0
> +TIMEOUT_MULTIPLIER = 1

Maybe:

    MESON_TIMEOUT_MULTIPLIER ?= 1

So one can run:

   $ make check MESON_TIMEOUT_MULTIPLIER=0

to tune a modified test timeout limit in [*]?

Regardless,

Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>

> +.mtestargs = --no-rebuild -t $(TIMEOUT_MULTIPLIER)
>   ifneq ($(SPEED), quick)
>   .mtestargs += --setup $(SPEED)
>   endif

Re: [PATCH v2 00/12] tests: enable meson test timeouts to improve debuggability

[Alex Bennée]

Daniel P. Berrangé <berrange@redhat.com> writes:

> Perhaps the most painful of all the GitLab CI failures we see are
> the enforced job timeouts:
>
>    "ERROR: Job failed: execution took longer than 1h15m0s seconds"
>
>    https://gitlab.com/qemu-project/qemu/-/jobs/4387047648
>
> when that hits the CI log shows what has *already* run, but figuring
> out what was currently running (or rather stuck) is an horrendously
> difficult.

I had this in my tree but I see there are a number of review comments to
take into account. Will there be a v3 and do we want it this late in the
cycle?

-- 
Alex Bennée
Virtualisation Tech Lead @ Linaro

Re: [PATCH v2 00/12] tests: enable meson test timeouts to improve debuggability

[Thomas Huth]

On 08/08/2023 10.57, Alex Bennée wrote:
> 
> Daniel P. Berrangé <berrange@redhat.com> writes:
> 
>> Perhaps the most painful of all the GitLab CI failures we see are
>> the enforced job timeouts:
>>
>>     "ERROR: Job failed: execution took longer than 1h15m0s seconds"
>>
>>     https://gitlab.com/qemu-project/qemu/-/jobs/4387047648
>>
>> when that hits the CI log shows what has *already* run, but figuring
>> out what was currently running (or rather stuck) is an horrendously
>> difficult.
> 
> I had this in my tree but I see there are a number of review comments to
> take into account. Will there be a v3 and do we want it this late in the
> cycle?

I think this could maybe cause some false positives in the CI until we 
fine-tuned all related timeouts, so no, we don't want to have this in the 
last release candidates of 8.1. We should commit it early in the 8.2 cycle 
(hoping that Daniel has some spare minutes to release a v3), so we can iron 
out the remaining issues there.

  Thomas

Re: [PATCH v2 00/12] tests: enable meson test timeouts to improve debuggability

[Daniel P. Berrangé]

On Sun, Aug 13, 2023 at 09:02:03AM +0200, Thomas Huth wrote:
> On 08/08/2023 10.57, Alex Bennée wrote:
> > 
> > Daniel P. Berrangé <berrange@redhat.com> writes:
> > 
> > > Perhaps the most painful of all the GitLab CI failures we see are
> > > the enforced job timeouts:
> > > 
> > >     "ERROR: Job failed: execution took longer than 1h15m0s seconds"
> > > 
> > >     https://gitlab.com/qemu-project/qemu/-/jobs/4387047648
> > > 
> > > when that hits the CI log shows what has *already* run, but figuring
> > > out what was currently running (or rather stuck) is an horrendously
> > > difficult.
> > 
> > I had this in my tree but I see there are a number of review comments to
> > take into account. Will there be a v3 and do we want it this late in the
> > cycle?
> 
> I think this could maybe cause some false positives in the CI until we
> fine-tuned all related timeouts, so no, we don't want to have this in the
> last release candidates of 8.1. We should commit it early in the 8.2 cycle
> (hoping that Daniel has some spare minutes to release a v3), so we can iron
> out the remaining issues there.

Agreed, it is safer to wait until 8.2

I've been away on holiday, but will post a v3 after I catchup


With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|