snapshot-save very slow in 8.1-rc2
Host environment
- Operating system: Proxmox VE 8.0
- OS/kernel version: Linux pve8a1 6.2.16-8-pve #1 SMP PREEMPT_DYNAMIC PMX 6.2.16-8 (2023-08-02T12:17Z) x86_64 GNU/Linux
- Architecture: x86
- QEMU flavor: qemu-system-x86_64
- QEMU version: QEMU emulator version 8.0.92 (v8.1.0-rc2-102-ga8fc5165)
- QEMU command line:
root@pve8a1 /home/febner/repos/qemu/build # cat ~/save-snap.sh ./qemu-img create -f qcow2 /tmp/test.qcow2 1G ./qemu-system-x86_64 \ -qmp stdio \ -m 8192 \ -blockdev qcow2,node-name=node0,file.driver=file,file.filename=/tmp/test.qcow2 \ <<EOF {"execute": "qmp_capabilities"} {"execute": "snapshot-save", "arguments": { "job-id": "save0", "tag": "snap0", "vmstate": "node0", "devices": ["node0"] } } {"execute": "quit"} EOF
Description of problem
Before commit 813cd616 ("migration: Use migration_transferred_bytes() to calculate rate_limit") the above script will take about 1.5 seconds to execute, after the commit, 1 minute 30 seconds. More RAM makes it take longer still.
Steps to reproduce
- Execute the script given as the command line above.
Additional information
Creating the issue here, so it doesn't get lost and is documented.
The following series by @juan.quintela would've avoided the regression, but seems like it never landed: https://lists.nongnu.org/archive/html/qemu-devel/2023-05/msg07971.html
Logs:
Before commit 813cd616
root@pve8a1 /home/febner/repos/qemu/build # time ~/save-snap.sh
Formatting '/tmp/test.qcow2', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=1073741824 lazy_refcounts=off refcount_bits=16
{"QMP": {"version": {"qemu": {"micro": 50, "minor": 0, "major": 8}, "package": "v8.0.0-967-g3db9c05a90-dirty"}, "capabilities": ["oob"]}}
VNC server running on ::1:5900
{"return": {}}
{"timestamp": {"seconds": 1691572701, "microseconds": 708660}, "event": "JOB_STATUS_CHANGE", "data": {"status": "created", "id": "save0"}}
{"timestamp": {"seconds": 1691572701, "microseconds": 708731}, "event": "JOB_STATUS_CHANGE", "data": {"status": "running", "id": "save0"}}
{"return": {}}
{"timestamp": {"seconds": 1691572701, "microseconds": 709239}, "event": "STOP"}
{"timestamp": {"seconds": 1691572702, "microseconds": 939059}, "event": "RESUME"}
{"timestamp": {"seconds": 1691572702, "microseconds": 939565}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "save0"}}
{"timestamp": {"seconds": 1691572702, "microseconds": 939605}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "save0"}}
{"timestamp": {"seconds": 1691572702, "microseconds": 939638}, "event": "JOB_STATUS_CHANGE", "data": {"status": "concluded", "id": "save0"}}
{"return": {}}
{"timestamp": {"seconds": 1691572702, "microseconds": 939730}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
{"timestamp": {"seconds": 1691572702, "microseconds": 941746}, "event": "JOB_STATUS_CHANGE", "data": {"status": "null", "id": "save0"}}
~/save-snap.sh 1.18s user 0.09s system 85% cpu 1.476 total
After commit 813cd616
root@pve8a1 /home/febner/repos/qemu/build # time ~/save-snap.sh
Formatting '/tmp/test.qcow2', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=1073741824 lazy_refcounts=off refcount_bits=16
{"QMP": {"version": {"qemu": {"micro": 92, "minor": 0, "major": 8}, "package": "v8.1.0-rc2-102-ga8fc5165aa"}, "capabilities": ["oob"]}}
VNC server running on ::1:5900
{"return": {}}
{"timestamp": {"seconds": 1691572864, "microseconds": 944026}, "event": "JOB_STATUS_CHANGE", "data": {"status": "created", "id": "save0"}}
{"timestamp": {"seconds": 1691572864, "microseconds": 944115}, "event": "JOB_STATUS_CHANGE", "data": {"status": "running", "id": "save0"}}
{"return": {}}
{"timestamp": {"seconds": 1691572864, "microseconds": 944631}, "event": "STOP"}
{"timestamp": {"seconds": 1691572954, "microseconds": 697523}, "event": "RESUME"}
{"timestamp": {"seconds": 1691572954, "microseconds": 697962}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "save0"}}
{"timestamp": {"seconds": 1691572954, "microseconds": 697996}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "save0"}}
{"timestamp": {"seconds": 1691572954, "microseconds": 698020}, "event": "JOB_STATUS_CHANGE", "data": {"status": "concluded", "id": "save0"}}
{"return": {}}
{"timestamp": {"seconds": 1691572954, "microseconds": 698089}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
{"timestamp": {"seconds": 1691572954, "microseconds": 701263}, "event": "JOB_STATUS_CHANGE", "data": {"status": "null", "id": "save0"}}
~/save-snap.sh 31.81s user 41.69s system 81% cpu 1:30.03 total