[Qemu-devel] qom-test on netbsd can be very slow

[Qemu-devel] qom-test on netbsd can be very slow

[Peter Maydell]

My NetBSD build system recently seems to have taken a nosedive
in how long it takes to finish "make check". This seems to be
because qom-test (and probably other things where the test interacts
with the QEMU process) can run very slowly.

netbsdvm# for i in 1 2 3 4 5 6 7 8 9 10; do
(QTEST_QEMU_BINARY=x86_64-softmmu/qemu-system-x86_64 time
tests/qom-test -p /x86_64/qom/pc-i440fx-2.0); done
/x86_64/qom/pc-i440fx-2.0: OK
        8.49 real         1.18 user         7.34 sys
/x86_64/qom/pc-i440fx-2.0: OK
       10.41 real         1.32 user         9.09 sys
/x86_64/qom/pc-i440fx-2.0: OK
        8.45 real         1.24 user         7.24 sys
/x86_64/qom/pc-i440fx-2.0: OK
        9.88 real         1.10 user         8.31 sys
/x86_64/qom/pc-i440fx-2.0: OK
       11.60 real         1.47 user         9.90 sys
/x86_64/qom/pc-i440fx-2.0: OK
       10.94 real         1.28 user         9.68 sys
/x86_64/qom/pc-i440fx-2.0: OK
       10.06 real         1.32 user         8.76 sys
/x86_64/qom/pc-i440fx-2.0: OK
       13.38 real         1.37 user        12.04 sys
/x86_64/qom/pc-i440fx-2.0: OK
       16.19 real         1.46 user        14.29 sys
/x86_64/qom/pc-i440fx-2.0: OK
        9.70 real         1.17 user         8.51 sys

Admittedly this is running in a (KVM) VM, but still, there seems
something wrong with how long each of these is taking. On Linux
each run is less than a second, so there's an order-of-magnitude
slowdown here. Further, I've occasionally seen a run take 100 seconds!

Does anybody else see this, and any ideas why it might be running slow?
I'm not very familiar with debugging on netbsd; I had a look at
ktrace output, and the QEMU process seems to sometimes spend
quite a lot of time in a poll() loop not actually doing anything.
I couldn't figure out how to get the ktrace logs to annotate
which thread was making which syscall though, so they weren't
easy to interpret. If anybody's more experienced at debugging
things in the BSDs that would also be helpful.

On OpenBSD, for comparison, each test run seems to fairly reliably
take 5 seconds give-or-take, there's much less run-to-run
variation, though it's still much slower than Linux is.
The OpenBSD and FreeBSD build VMs seem to complete more
reasonably quickly than the NetBSD one.

One thing I noticed looking at ktrace output is that we do
all our reading of QMP input and output with a read syscall
per character. I don't think that's the cause of this slowness,
though.

thanks
-- PMM

Re: [Qemu-devel] qom-test on netbsd can be very slow

[Kamil Rytarowski]

[-- Attachment #1: Type: text/plain, Size: 3611 bytes --]

On 09.04.2018 19:10, Peter Maydell wrote:
> My NetBSD build system recently seems to have taken a nosedive
> in how long it takes to finish "make check". This seems to be
> because qom-test (and probably other things where the test interacts
> with the QEMU process) can run very slowly.
> 
> netbsdvm# for i in 1 2 3 4 5 6 7 8 9 10; do
> (QTEST_QEMU_BINARY=x86_64-softmmu/qemu-system-x86_64 time
> tests/qom-test -p /x86_64/qom/pc-i440fx-2.0); done
> /x86_64/qom/pc-i440fx-2.0: OK
>         8.49 real         1.18 user         7.34 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>        10.41 real         1.32 user         9.09 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         8.45 real         1.24 user         7.24 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         9.88 real         1.10 user         8.31 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>        11.60 real         1.47 user         9.90 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>        10.94 real         1.28 user         9.68 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>        10.06 real         1.32 user         8.76 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>        13.38 real         1.37 user        12.04 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>        16.19 real         1.46 user        14.29 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         9.70 real         1.17 user         8.51 sys
> 
> Admittedly this is running in a (KVM) VM, but still, there seems
> something wrong with how long each of these is taking. On Linux
> each run is less than a second, so there's an order-of-magnitude
> slowdown here. Further, I've occasionally seen a run take 100 seconds!
> 
> Does anybody else see this, and any ideas why it might be running slow?
> I'm not very familiar with debugging on netbsd; I had a look at
> ktrace output, and the QEMU process seems to sometimes spend
> quite a lot of time in a poll() loop not actually doing anything.
> I couldn't figure out how to get the ktrace logs to annotate
> which thread was making which syscall though, so they weren't
> easy to interpret. If anybody's more experienced at debugging
> things in the BSDs that would also be helpful.
> 
> On OpenBSD, for comparison, each test run seems to fairly reliably
> take 5 seconds give-or-take, there's much less run-to-run
> variation, though it's still much slower than Linux is.
> The OpenBSD and FreeBSD build VMs seem to complete more
> reasonably quickly than the NetBSD one.
> 
> One thing I noticed looking at ktrace output is that we do
> all our reading of QMP input and output with a read syscall
> per character. I don't think that's the cause of this slowness,
> though.
> 
> thanks
> -- PMM
> 

I'm running these tests natively and get apparently expected results:

/x86_64/qom/pc-i440fx-2.0: OK
        2,05 real         1,36 user         0,71 sys
/x86_64/qom/pc-i440fx-2.0: OK
        1,92 real         1,17 user         0,79 sys
/x86_64/qom/pc-i440fx-2.0: OK
        1,84 real         1,14 user         0,77 sys
/x86_64/qom/pc-i440fx-2.0: OK
        1,85 real         1,16 user         0,76 sys
/x86_64/qom/pc-i440fx-2.0: OK
        1,79 real         1,04 user         0,82 sys
/x86_64/qom/pc-i440fx-2.0: OK
        1,84 real         1,00 user         0,91 sys
/x86_64/qom/pc-i440fx-2.0: OK
        1,86 real         1,18 user         0,75 sys
/x86_64/qom/pc-i440fx-2.0: OK
        1,85 real         1,27 user         0,64 sys
/x86_64/qom/pc-i440fx-2.0: OK
        1,84 real         1,27 user         0,64 sys
/x86_64/qom/pc-i440fx-2.0: OK
        1,82 real         1,18 user         0,71 sys


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 850 bytes --]

Re: [Qemu-devel] qom-test on netbsd can be very slow

[Kamil Rytarowski]

[-- Attachment #1: Type: text/plain, Size: 5100 bytes --]

On 09.04.2018 22:51, Kamil Rytarowski wrote:
> On 09.04.2018 19:10, Peter Maydell wrote:
>> My NetBSD build system recently seems to have taken a nosedive
>> in how long it takes to finish "make check". This seems to be
>> because qom-test (and probably other things where the test interacts
>> with the QEMU process) can run very slowly.
>>
>> netbsdvm# for i in 1 2 3 4 5 6 7 8 9 10; do
>> (QTEST_QEMU_BINARY=x86_64-softmmu/qemu-system-x86_64 time
>> tests/qom-test -p /x86_64/qom/pc-i440fx-2.0); done
>> /x86_64/qom/pc-i440fx-2.0: OK
>>         8.49 real         1.18 user         7.34 sys
>> /x86_64/qom/pc-i440fx-2.0: OK
>>        10.41 real         1.32 user         9.09 sys
>> /x86_64/qom/pc-i440fx-2.0: OK
>>         8.45 real         1.24 user         7.24 sys
>> /x86_64/qom/pc-i440fx-2.0: OK
>>         9.88 real         1.10 user         8.31 sys
>> /x86_64/qom/pc-i440fx-2.0: OK
>>        11.60 real         1.47 user         9.90 sys
>> /x86_64/qom/pc-i440fx-2.0: OK
>>        10.94 real         1.28 user         9.68 sys
>> /x86_64/qom/pc-i440fx-2.0: OK
>>        10.06 real         1.32 user         8.76 sys
>> /x86_64/qom/pc-i440fx-2.0: OK
>>        13.38 real         1.37 user        12.04 sys
>> /x86_64/qom/pc-i440fx-2.0: OK
>>        16.19 real         1.46 user        14.29 sys
>> /x86_64/qom/pc-i440fx-2.0: OK
>>         9.70 real         1.17 user         8.51 sys
>>
>> Admittedly this is running in a (KVM) VM, but still, there seems
>> something wrong with how long each of these is taking. On Linux
>> each run is less than a second, so there's an order-of-magnitude
>> slowdown here. Further, I've occasionally seen a run take 100 seconds!
>>
>> Does anybody else see this, and any ideas why it might be running slow?
>> I'm not very familiar with debugging on netbsd; I had a look at
>> ktrace output, and the QEMU process seems to sometimes spend
>> quite a lot of time in a poll() loop not actually doing anything.
>> I couldn't figure out how to get the ktrace logs to annotate
>> which thread was making which syscall though, so they weren't
>> easy to interpret. If anybody's more experienced at debugging
>> things in the BSDs that would also be helpful.
>>
>> On OpenBSD, for comparison, each test run seems to fairly reliably
>> take 5 seconds give-or-take, there's much less run-to-run
>> variation, though it's still much slower than Linux is.
>> The OpenBSD and FreeBSD build VMs seem to complete more
>> reasonably quickly than the NetBSD one.
>>
>> One thing I noticed looking at ktrace output is that we do
>> all our reading of QMP input and output with a read syscall
>> per character. I don't think that's the cause of this slowness,
>> though.
>>
>> thanks
>> -- PMM
>>
> 
> I'm running these tests natively and get apparently expected results:
> 
> /x86_64/qom/pc-i440fx-2.0: OK
>         2,05 real         1,36 user         0,71 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         1,92 real         1,17 user         0,79 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         1,84 real         1,14 user         0,77 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         1,85 real         1,16 user         0,76 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         1,79 real         1,04 user         0,82 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         1,84 real         1,00 user         0,91 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         1,86 real         1,18 user         0,75 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         1,85 real         1,27 user         0,64 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         1,84 real         1,27 user         0,64 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         1,82 real         1,18 user         0,71 sys
> 

There is a registered bug in the NetBSD database:

https://gnats.netbsd.org/52184
"Recent qemu performs badly on NetBSD hosts under load"

Could you please try to check if the following commit is culprit using
the reproducer in gnats or running qom-test?


commit 05e514b1d4d5bd4209e2c8bbc76ff05c85a235f3
Author: Paolo Bonzini <pbonzini@redhat.com>
Date:   Tue Jul 21 16:07:53 2015 +0200

    AioContext: optimize clearing the EventNotifier

    It is pretty rare for aio_notify to actually set the EventNotifier.  It
    can happen with worker threads such as thread-pool.c's, but otherwise it
    should never be set thanks to the ctx->notify_me optimization.  The
    previous patch, unfortunately, added an unconditional call to
    event_notifier_test_and_clear; now add a userspace fast path that
    avoids the call.

    Note that it is not possible to do the same with event_notifier_set;
    it would break, as proved (again) by the included formal model.

    This patch survived over 3000 reboots on aarch64 KVM.

    Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
    Reviewed-by: Fam Zheng <famz@redhat.com>
    Tested-by: Richard W.M. Jones <rjones@redhat.com>
    Message-id: 1437487673-23740-7-git-send-email-pbonzini@redhat.com
    Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 850 bytes --]

Re: [Qemu-devel] qom-test on netbsd can be very slow

[Daniel P. Berrangé]

On Mon, Apr 09, 2018 at 06:10:43PM +0100, Peter Maydell wrote:
> My NetBSD build system recently seems to have taken a nosedive
> in how long it takes to finish "make check". This seems to be
> because qom-test (and probably other things where the test interacts
> with the QEMU process) can run very slowly.
> 
> netbsdvm# for i in 1 2 3 4 5 6 7 8 9 10; do
> (QTEST_QEMU_BINARY=x86_64-softmmu/qemu-system-x86_64 time
> tests/qom-test -p /x86_64/qom/pc-i440fx-2.0); done
> /x86_64/qom/pc-i440fx-2.0: OK
>         8.49 real         1.18 user         7.34 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>        10.41 real         1.32 user         9.09 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         8.45 real         1.24 user         7.24 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         9.88 real         1.10 user         8.31 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>        11.60 real         1.47 user         9.90 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>        10.94 real         1.28 user         9.68 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>        10.06 real         1.32 user         8.76 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>        13.38 real         1.37 user        12.04 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>        16.19 real         1.46 user        14.29 sys
> /x86_64/qom/pc-i440fx-2.0: OK
>         9.70 real         1.17 user         8.51 sys
> 
> Admittedly this is running in a (KVM) VM, but still, there seems
> something wrong with how long each of these is taking. On Linux
> each run is less than a second, so there's an order-of-magnitude
> slowdown here. Further, I've occasionally seen a run take 100 seconds!
> 
> Does anybody else see this, and any ideas why it might be running slow?

My only real suggestion is to try "git bisect" as presumably this is
a regression caused by something we've merged in this dev cycle ?

> One thing I noticed looking at ktrace output is that we do
> all our reading of QMP input and output with a read syscall
> per character. I don't think that's the cause of this slowness,
> though.

IIRC, that has been long standing behaviour so would be unlikely to
explain a recent slowdown, nor the huge variation in time for some
runs.

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