Re: biosbits test failing on origin/master

[Ani Sinha]

On Fri, Nov 11, 2022 at 4:39 PM Ani Sinha <ani@anisinha.ca> wrote:
>
> On Fri, Nov 11, 2022 at 9:52 AM Ani Sinha <ani@anisinha.ca> wrote:
> >
> > On Thu, Nov 10, 2022 at 11:37 PM John Snow <jsnow@redhat.com> wrote:
> > >
> > > Hiya, on today's origin/master
> > > (2ccad61746ca7de5dd3e25146062264387e43bd4) I'm finding that "make
> > > check-avocado" is failing on the new biosbits test on my local
> > > development machine:
> > >
> > >  (001/193) tests/avocado/acpi-bits.py:AcpiBitsTest.test_acpi_smbios_bits:
> > > FAIL: True is not false : The VM seems to have failed to shutdown in
> > > time (83.65 s)
> > >
> > > Is this a known issue, or should I begin to investigate it?
> >
> > In my test environment it does pass.
> >
> > $ ./tests/venv/bin/avocado run -t acpi tests/avocado
> > Fetching asset from
> > tests/avocado/acpi-bits.py:AcpiBitsTest.test_acpi_smbios_bits
> > JOB ID     : 35726df7d3c2e0f41847822620c78195ba45b9b9
> > JOB LOG    : 
> > /home/anisinha/avocado/job-results/job-2022-11-11T09.42-35726df/job.log
> >  (1/1) tests/avocado/acpi-bits.py:AcpiBitsTest.test_acpi_smbios_bits:
> > PASS (57.57 s)
> > RESULTS    : PASS 1 | ERROR 0 | FAIL 0 | SKIP 0 | WARN 0 | INTERRUPT 0
> > | CANCEL 0
> > JOB TIME   : 63.82 s
> >
> > However, I have seen that on certain slower test machines or when run
> > within a virtual machine, the test can take longer to complete and 60
> > secs may not always be enough.
>
> Here is an interesting data point. I re-ran on a Centos 8 VM running
> on Ubuntu bare metal. Just like the Ubuntu bare metal, it passed fine.
> Next, I tried to run it on a Centos 7.9.2009 VM running on the same
> Ubuntu bare metal. I was able to reproduce this consistently. So I did
> some digging, gdb into qemu and it looked like the VM was just slow
> but not stuck. So I timed the QEMU command line that was being used in
> the test using the same iso that was being generated by the test. Here
> it is:
>
> # time ./qemu-system-x86_64 -display none -vga none -chardev
> file,path=/var/tmp/debugcon-log.txt,id=debugcon -device
> isa-debugcon,iobase=0x403,chardev=debugcon -cdrom
> /var/tmp/acpi-bits-oogd8wp9.tmp/bits-2020.iso
>
> real 2m34.052s
> user 2m33.858s
> sys 0m0.467s
>
> On bare metal Ubuntu, I see this:
>
> $ time ./qemu-system-x86_64 -display none -vga none -chardev
> file,path=/var/tmp/debugcon-log.txt,id=debugcon -device
> isa-debugcon,iobase=0x403,chardev=debugcon -cdrom ~/temp/bits-2020.iso
>
> real 1m15.318s
> user 1m15.136s
> sys 0m0.345s
>
> With "-icount auto" added in the command line,  both bare metal and VM
> environments were slower. However, we need this command line for some
> latency tests.
>
> avocado framework has a 2 min timeout for any test.

Just realized that this value is coming from
https://gitlab.com/anisinha/qemu/-/blob/master/tests/avocado/avocado_qemu/__init__.py#L232
and can be overiden.
So I will override this to 200 seconds. If we still see timeouts, we
can raise this further by a bit more.

Thanks for bringing this to my attention.

This would
> definitely time out even without my internal timeout check. I verified
> that the test indeed passed by looking into the debug con logs pushed
> out by the test framework. If the system is just slow/overloaded I am
> not sure what we can do.
>
> In those cases raising the maximum
> > completion time to 90 secs helps. Perhaps you can try this and let me
> > know if it helps:
>
> Maybe I will make the timeout 90 secs and hope that this will be enough.
>
> >
> > diff --git a/tests/avocado/acpi-bits.py b/tests/avocado/acpi-bits.py
> > index 8745a58a76..b11fe39350 100644
> > --- a/tests/avocado/acpi-bits.py
> > +++ b/tests/avocado/acpi-bits.py
> > @@ -385,8 +385,9 @@ def test_acpi_smbios_bits(self):
> >          self._vm.launch()
> >          # biosbits has been configured to run all the specified test suites
> >          # in batch mode and then automatically initiate a vm shutdown.
> > -        # sleep for maximum of one minute
> > -        max_sleep_time = time.monotonic() + 60
> > +        # sleep for a maximum of one and half minutes to accommodate
> > running this
> > +        # even on slower machines.
> > +        max_sleep_time = time.monotonic() + 90
> >          while self._vm.is_running() and time.monotonic() < max_sleep_time:
> >              time.sleep(1)