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

1. 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