Big TCG slowdown when using zstd with aarch64

[Juan Quintela]

Hi

Before I continue investigating this further, do you have any clue what
is going on here.  I am running qemu-system-aarch64 on x86_64.

$ time ./tests/qtest/migration-test -p /aarch64/migration/multifd/tcp/plain/none
TAP version 13
# random seed: R02S3d50a0e874b28727af4b862a3cc4214e
# Start of aarch64 tests
# Start of migration tests
# Start of multifd tests
# Start of tcp tests
# Start of plain tests
# starting QEMU: exec ./qemu-system-aarch64 -qtest unix:/tmp/qtest-2888203.sock 
-qtest-log /dev/null -chardev socket,path=/tmp/qtest-2888203.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -net none -accel kvm -accel tcg 
-machine virt,gic-version=max -name source,debug-threads=on -m 150M -serial 
file:/tmp/migration-test-WT9151/src_serial -cpu max -kernel 
/tmp/migration-test-WT9151/bootsect     -accel qtest
# starting QEMU: exec ./qemu-system-aarch64 -qtest unix:/tmp/qtest-2888203.sock 
-qtest-log /dev/null -chardev socket,path=/tmp/qtest-2888203.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -net none -accel kvm -accel tcg 
-machine virt,gic-version=max -name target,debug-threads=on -m 150M -serial 
file:/tmp/migration-test-WT9151/dest_serial -incoming defer -cpu max -kernel 
/tmp/migration-test-WT9151/bootsect    -accel qtest
ok 1 /aarch64/migration/multifd/tcp/plain/none
# End of plain tests
# End of tcp tests
# End of multifd tests
# End of migration tests
# End of aarch64 tests
1..1

real    0m4.559s
user    0m4.898s
sys     0m1.156s
$ time ./tests/qtest/migration-test -p /aarch64/migration/multifd/tcp/plain/zlib
TAP version 13
# random seed: R02S014dd197350726bdd95aea37b81d3898
# Start of aarch64 tests
# Start of migration tests
# Start of multifd tests
# Start of tcp tests
# Start of plain tests
# starting QEMU: exec ./qemu-system-aarch64 -qtest unix:/tmp/qtest-2888278.sock 
-qtest-log /dev/null -chardev socket,path=/tmp/qtest-2888278.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -net none -accel kvm -accel tcg 
-machine virt,gic-version=max -name source,debug-threads=on -m 150M -serial 
file:/tmp/migration-test-25U151/src_serial -cpu max -kernel 
/tmp/migration-test-25U151/bootsect     -accel qtest
# starting QEMU: exec ./qemu-system-aarch64 -qtest unix:/tmp/qtest-2888278.sock 
-qtest-log /dev/null -chardev socket,path=/tmp/qtest-2888278.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -net none -accel kvm -accel tcg 
-machine virt,gic-version=max -name target,debug-threads=on -m 150M -serial 
file:/tmp/migration-test-25U151/dest_serial -incoming defer -cpu max -kernel 
/tmp/migration-test-25U151/bootsect    -accel qtest
ok 1 /aarch64/migration/multifd/tcp/plain/zlib
# End of plain tests
# End of tcp tests
# End of multifd tests
# End of migration tests
# End of aarch64 tests
1..1

real    0m1.645s
user    0m3.484s
sys     0m0.512s
$ time ./tests/qtest/migration-test -p /aarch64/migration/multifd/tcp/plain/zstd
TAP version 13
# random seed: R02Se49afe2ea9d2b76a1eda1fa2bc8d812c
# Start of aarch64 tests
# Start of migration tests
# Start of multifd tests
# Start of tcp tests
# Start of plain tests
# starting QEMU: exec ./qemu-system-aarch64 -qtest unix:/tmp/qtest-2888353.sock 
-qtest-log /dev/null -chardev socket,path=/tmp/qtest-2888353.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -net none -accel kvm -accel tcg 
-machine virt,gic-version=max -name source,debug-threads=on -m 150M -serial 
file:/tmp/migration-test-UILY51/src_serial -cpu max -kernel 
/tmp/migration-test-UILY51/bootsect     -accel qtest
# starting QEMU: exec ./qemu-system-aarch64 -qtest unix:/tmp/qtest-2888353.sock 
-qtest-log /dev/null -chardev socket,path=/tmp/qtest-2888353.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -net none -accel kvm -accel tcg 
-machine virt,gic-version=max -name target,debug-threads=on -m 150M -serial 
file:/tmp/migration-test-UILY51/dest_serial -incoming defer -cpu max -kernel 
/tmp/migration-test-UILY51/bootsect    -accel qtest



ok 1 /aarch64/migration/multifd/tcp/plain/zstd
# End of plain tests
# End of tcp tests
# End of multifd tests
# End of migration tests
# End of aarch64 tests
1..1

real    0m48.022s
user    8m17.306s
sys     0m35.217s


This test is very amenable to compression, basically we only modify one
byte for each page, and basically all the pages are the same.

no compression: 4.5 seconds
zlib compression: 1.6 seconds (inside what I would expect)
zstd compression: 48 seconds, what is going on here?

As a comparison, this are the times for x86_64 running natively, values
much more reasonable.

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

real    0m3.889s
user    0m4.264s
sys     0m1.295s
$ time ./tests/qtest/migration-test -p /x86_64/migration/multifd/tcp/plain/zlib
TAP version 13
# random seed: R02S968738d716d2c0dc8c8279716ff3dd9a
# Start of x86_64 tests
# Start of migration tests
# Start of multifd tests
# Start of tcp tests
# Start of plain tests
# starting QEMU: exec ./qemu-system-x86_64 -qtest unix:/tmp/qtest-3002385.sock 
-qtest-log /dev/null -chardev socket,path=/tmp/qtest-3002385.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -net none -accel kvm -accel tcg -name 
source,debug-threads=on -m 150M -serial 
file:/tmp/migration-test-9JTZ51/src_serial -drive 
file=/tmp/migration-test-9JTZ51/bootsect,format=raw     -accel qtest
# starting QEMU: exec ./qemu-system-x86_64 -qtest unix:/tmp/qtest-3002385.sock 
-qtest-log /dev/null -chardev socket,path=/tmp/qtest-3002385.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -net none -accel kvm -accel tcg -name 
target,debug-threads=on -m 150M -serial 
file:/tmp/migration-test-9JTZ51/dest_serial -incoming defer -drive 
file=/tmp/migration-test-9JTZ51/bootsect,format=raw    -accel qtest
ok 1 /x86_64/migration/multifd/tcp/plain/zlib
# End of plain tests
# End of tcp tests
# End of multifd tests
# End of migration tests
# End of x86_64 tests
1..1

real    0m1.464s
user    0m2.868s
sys     0m0.534s
$ time ./tests/qtest/migration-test -p /x86_64/migration/multifd/tcp/plain/zstd
TAP version 13
# random seed: R02Sba4a923c284ad824bc82fd488044a5df
# Start of x86_64 tests
# Start of migration tests
# Start of multifd tests
# Start of tcp tests
# Start of plain tests
# starting QEMU: exec ./qemu-system-x86_64 -qtest unix:/tmp/qtest-3006857.sock 
-qtest-log /dev/null -chardev socket,path=/tmp/qtest-3006857.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -net none -accel kvm -accel tcg -name 
source,debug-threads=on -m 150M -serial 
file:/tmp/migration-test-ALK251/src_serial -drive 
file=/tmp/migration-test-ALK251/bootsect,format=raw     -accel qtest
# starting QEMU: exec ./qemu-system-x86_64 -qtest unix:/tmp/qtest-3006857.sock 
-qtest-log /dev/null -chardev socket,path=/tmp/qtest-3006857.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -net none -accel kvm -accel tcg -name 
target,debug-threads=on -m 150M -serial 
file:/tmp/migration-test-ALK251/dest_serial -incoming defer -drive 
file=/tmp/migration-test-ALK251/bootsect,format=raw    -accel qtest
ok 1 /x86_64/migration/multifd/tcp/plain/zstd
# End of plain tests
# End of tcp tests
# End of multifd tests
# End of migration tests
# End of x86_64 tests
1..1

real    0m1.298s
user    0m2.540s
sys     0m0.662s

3.88, 1.46 and 1.29 seconds, what I would have expected.

And if you ask why is this so important: with 48 seconds, we are very
near the limit.  If I am running 2 or more migration tests at the same
time:

# random seed: R02Sfb0b65ab5484a997057ef94daed7072f
# Start of aarch64 tests
# Start of migration tests
# Start of multifd tests
# Start of tcp tests
# Start of plain tests
# starting QEMU: exec ./qemu-system-aarch64 -qtest unix:/tmp/qtest-2754383.sock 
-qtest-log /dev/null -chardev socket,path=/tmp/qtest-2754383.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -net none -accel kvm -accel tcg 
-machine virt,gic-version=max -name source,debug-threads=on -m 150M -serial 
file:/tmp/migration-test-L93051/src_serial -cpu max -kernel 
/tmp/migration-test-L93051/bootsect     -accel qtest
# starting QEMU: exec ./qemu-system-aarch64 -qtest unix:/tmp/qtest-2754383.sock 
-qtest-log /dev/null -chardev socket,path=/tmp/qtest-2754383.qmp,id=char0 -mon 
chardev=char0,mode=control -display none -net none -accel kvm -accel tcg 
-machine virt,gic-version=max -name target,debug-threads=on -m 150M -serial 
file:/tmp/migration-test-L93051/dest_serial -incoming defer -cpu max -kernel 
/tmp/migration-test-L93051/bootsect    -accel qtest
**
ERROR:../../../../mnt/code/qemu/multifd/tests/qtest/migration-helpers.c:143:wait_for_migration_status:
 assertion failed: (g_test_timer_elapsed() < MIGRATION_STATUS_WAIT_TIMEOUT)
not ok /aarch64/migration/multifd/tcp/plain/zstd - 
ERROR:../../../../mnt/code/qemu/multifd/tests/qtest/migration-helpers.c:143:wait_for_migration_status:
 assertion failed: (g_test_timer_elapsed() < MIGRATION_STATUS_WAIT_TIMEOUT)
Bail out!
qemu-system-aarch64: multifd_send_pages: channel 0 has already quit!
qemu-system-aarch64: Unable to write to socket: Connection reset by peer
Aborted (core dumped)

real    2m0.928s
user    16m15.671s
sys     1m11.431s


Later, Juan.