Re: [PATCH 0/2] tests/migration: Fix migration-test slowdown

[Juan Quintela <quintela@redhat.com>]

Thomas Huth <thuth@redhat.com> wrote:
> On 18/04/2023 13.42, Juan Quintela wrote:
>> Thomas Huth <thuth@redhat.com> wrote:
>>> On 12/04/2023 16.19, Juan Quintela wrote:
>>>> Since commit:
>>>> commit 1bfc8dde505f1e6a92697c52aa9b09e81b54c78f
>>>> Author: Dr. David Alan Gilbert <dgilbert@redhat.com>
>>>> Date:   Mon Mar 6 15:26:12 2023 +0000
>>>>       tests/migration: Tweek auto converge limits check
>>>>       Thomas found an autoconverge test failure where the
>>>>       migration completed before the autoconverge had kicked in.
>>>>       [...]
>>>> migration-test has become very slow.
>>>> On my laptop, before that commit migration-test takes 2min10seconds
>>>> After that commit, it takes around 11minutes
>>>> We can't revert it because it fixes a real problem when the host
>>>> machine is overloaded.  See the comment on test_migrate_auto_converge().
>>>
>>> Thanks, your patches decrease the time to run the migration-test from
>>> 16 minutes down to 5 minutes on my system, that's a great improvement,
>>> indeed!
>>>
>>> Tested-by: Thomas Huth <thuth@redhat.com>
>> Thanks
>> 
>>> (though 5 minutes are still quite a lot for qtests ... maybe some
>>> other parts could be moved to only run with g_test_slow() ?)
>> Hi
>> Could you gime the output of:
>> time for i in $(./tests/qtest/migration-test -l | grep "^/"); do
>> echo $i; time ./tests/qtest/migration-test -p $i; done
>> To see what tests are taking so long on your system?
>> On my system (i9900K processor, i.e. not the latest) and
>> auto_converge
>> moved to slow the total of the tests take a bit more than 1 minute.
>
> This is with both of your patches applied:


> /x86_64/migration/postcopy/plain
> /x86_64/migration/postcopy/plain: OK
>
> real	0m35,446s
> user	0m47,208s
> sys	0m11,828s

This is quite slower than on mine, basically almost all the code that
does migration.

$ time ./tests/qtest/migration-test -p /x86_64/migration/postcopy/plain
# random seed: R02S42809b71f513e8524bd24df5facd5768
# Start of x86_64 tests
# Start of migration tests
# Start of postcopy tests
# starting QEMU: exec ./qemu-system-x86_64 -qtest unix:/tmp/qtest-246853.sock -qtest-log /dev/null -chardev socket,path=/tmp/qtest-246853.qmp,id=char0 -mon chardev=char0,mode=control -display none -accel kvm -accel tcg -name source,debug-threads=on -m 150M -serial file:/tmp/migration-test-1MGL31/src_serial -drive file=/tmp/migration-test-1MGL31/bootsect,format=raw    -accel qtest
# starting QEMU: exec ./qemu-system-x86_64 -qtest unix:/tmp/qtest-246853.sock -qtest-log /dev/null -chardev socket,path=/tmp/qtest-246853.qmp,id=char0 -mon chardev=char0,mode=control -display none -accel kvm -accel tcg -name target,debug-threads=on -m 150M -serial file:/tmp/migration-test-1MGL31/dest_serial -incoming unix:/tmp/migration-test-1MGL31/migsocket -drive file=/tmp/migration-test-1MGL31/bootsect,format=raw    -accel qtest
ok 1 /x86_64/migration/postcopy/plain
# End of postcopy tests
# End of migration tests
# End of x86_64 tests
1..1

real	0m1.104s
user	0m0.697s
sys	0m0.414s





> /x86_64/migration/postcopy/recovery/plain
> /x86_64/migration/postcopy/recovery/plain: OK
>
> real	0m34,707s
> user	0m46,357s
> sys	0m11,366s
> /x86_64/migration/postcopy/recovery/tls/psk
> /x86_64/migration/postcopy/recovery/tls/psk: OK
>
> real	0m33,052s
> user	0m46,539s
> sys	0m11,537s
> /x86_64/migration/postcopy/preempt/plain
> /x86_64/migration/postcopy/preempt/plain: OK
>
> real	0m35,107s
> user	0m46,556s
> sys	0m11,755s
> /x86_64/migration/postcopy/preempt/recovery/plain
> /x86_64/migration/postcopy/preempt/recovery/plain: OK
>
> real	0m35,329s
> user	0m46,951s
> sys	0m11,529s
> /x86_64/migration/postcopy/preempt/recovery/tls/psk
> /x86_64/migration/postcopy/preempt/recovery/tls/psk: OK
>
> real	0m36,237s
> user	0m51,450s
> sys	0m12,419s
> /x86_64/migration/postcopy/preempt/tls/psk
> /x86_64/migration/postcopy/preempt/tls/psk: OK
>
> real	0m35,033s
> user	0m49,244s
> sys	0m12,123s
> /x86_64/migration/postcopy/tls/psk
> /x86_64/migration/postcopy/tls/psk: OK
>
> real	0m36,097s
> user	0m50,873s
> sys	0m12,569s


> real	5m32,733s
> user	7m24,380s
> sys	1m50,801s

Ouch.

Can I ask:
- what is your machine?  It is specially slow?
  Otherwise I want to know why it is happening.

- as what is going slow to you is postcopy, can you told me what is this
  setting?

# we want postcopy to work for normal users
vm.unprivileged_userfaultfd = 1

And if it is not set, just change it and retest.

Thanks, Juan.